Description:
MySQL 5.5.23 or later, can log the details for InnoDB: Shutdown process.
https://bugs.mysql.com/bug.php?id=47707
* InnoDB: When shutting down the MySQL server, the cleanup
operations of the InnoDB shutdown could take a long time
with no output, making the server appear to be hung.
[Note] mysqld: Normal shutdown
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number ...
Now additional progress messages are displayed between
the "starting" and "completed" messages:
InnoDB: Waiting for srv_monitor_thread (srv_lock_timeout_thread/ srv_e
rror_monitor_thread) to exit
InnoDB: Waiting for %lu active transactions to exit
InnoDB: Waiting for master thread (worker threads) to be suspended
InnoDB: Pending checkpoint_writes: %lu
InnoDB: Pending log flush writes: %lu
InnoDB: Waiting for %lu buffer page I/Os to complete
InnoDB: Waiting for dirty buffer pages to be flushed
For both fast shutdown
(http://dev.mysql.com/doc/refman/5.5/en/glossary.html#glo
s_fast_shutdown) and slow shutdown
(http://dev.mysql.com/doc/refman/5.5/en/glossary.html#glo
s_slow_shutdown), a progress messages is printed every 60
seconds:
InnoDB: Waiting for %lu tables to be dropped
During a slow shutdown, two additional messages are
printed if certain phases take longer than normal:
InnoDB: Waiting for %lu undo logs to be purged
InnoDB: number of pages just purged: %lu
InnoDB: Waiting for change buffer merge to complete\n
InnoDB: number of bytes of change buffer just merged: %lu
But in some case, still take a long time without any message like this.
180930 0:29:10 InnoDB: Starting shutdown...
180930 0:38:06 InnoDB: Shutdown completed; log sequence number 25xxxxxxxxxx
180930 0:38:06 [Note] /usr/sbin/mysqld: Shutdown complete
So please add more information about InnoDB's shutdown.
How to repeat:
There is no testcase for reproducing this case.
Suggested fix:
InnoDB's shutdown process is executed in innobase_shutdown_for_mysql(void).
MySQL 5.5.23 add messages in /* 1. Flush the buffer pool to disk, write the current lsn... */ by calling logs_empty_and_mark_files_at_shutdown();
We can add more messages for each /* 2 , /*3, /*4, /*5 steps.
It will be great help to investigate which process do harm for fast shutting down.
2103 /****************************************************************//**
2104 Shuts down the InnoDB database.
2105 @return DB_SUCCESS or error code */
2106 UNIV_INTERN
2107 int
2108 innobase_shutdown_for_mysql(void)
2109 /*=============================*/
2110 {
2111 ulint i;
2112 if (!srv_was_started) {
2113 if (srv_is_being_started) {
2114 ut_print_timestamp(stderr);
2115 fprintf(stderr,
2116 " InnoDB: Warning: shutting down"
2117 " a not properly started\n"
2118 "InnoDB: or created database!\n");
2119 }
2120
2121 return(DB_SUCCESS);
2122 }
2123
2124 /* 1. Flush the buffer pool to disk, write the current lsn to
2125 the tablespace header(s), and copy all log data to archive.
2126 The step 1 is the real InnoDB shutdown. The remaining steps 2 - ...
2127 just free data structures after the shutdown. */
2128
2129 logs_empty_and_mark_files_at_shutdown();
2130
2131 if (srv_conc_n_threads != 0) {
2132 fprintf(stderr,
2133 "InnoDB: Warning: query counter shows %ld queries"
2134 " still\n"
2135 "InnoDB: inside InnoDB at shutdown\n",
2136 srv_conc_n_threads);
2137 }
2138
2139 /* 2. Make all threads created by InnoDB to exit */
2140
2141 srv_shutdown_state = SRV_SHUTDOWN_EXIT_THREADS;
2142
2143 /* All threads end up waiting for certain events. Put those events
2144 to the signaled state. Then the threads will exit themselves after
2145 os_event_wait(). */
2146
2147 for (i = 0; i < 1000; i++) {
2148 /* NOTE: IF YOU CREATE THREADS IN INNODB, YOU MUST EXIT THEM
2149 HERE OR EARLIER */
2150
2151 /* a. Let the lock timeout thread exit */
2152 os_event_set(srv_lock_timeout_thread_event);
2153
2154 /* b. srv error monitor thread exits automatically, no need
2155 to do anything here */
2156
2157 /* c. We wake the master thread so that it exits */
2158 srv_wake_master_thread();
2159
2160 /* d. We wake the purge thread so that it exits */
2161 srv_wake_purge_thread();
2162
2163 /* e. Exit the i/o threads */
2164
2165 os_aio_wake_all_threads_at_shutdown();
2166
2167 os_mutex_enter(os_sync_mutex);
2168
2169 if (os_thread_count == 0) {
2170 /* All the threads have exited or are just exiting;
2171 NOTE that the threads may not have completed their
2172 exit yet. Should we use pthread_join() to make sure
2173 they have exited? If we did, we would have to
2174 remove the pthread_detach() from
2175 os_thread_exit(). Now we just sleep 0.1
2176 seconds and hope that is enough! */
2177
2178 os_mutex_exit(os_sync_mutex);
2179
2180 os_thread_sleep(100000);
2181
2182 break;
2183 }
2184
2185 os_mutex_exit(os_sync_mutex);
2186
2187 os_thread_sleep(100000);
2188 }
2189
2190 if (i == 1000) {
2191 fprintf(stderr,
2192 "InnoDB: Warning: %lu threads created by InnoDB"
2193 " had not exited at shutdown!\n",
2194 (ulong) os_thread_count);
2195 }
2196
2197 if (srv_monitor_file) {
2198 fclose(srv_monitor_file);
2199 srv_monitor_file = 0;
2200 if (srv_monitor_file_name) {
2201 unlink(srv_monitor_file_name);
2202 mem_free(srv_monitor_file_name);
2203 }
2204 }
2205 if (srv_dict_tmpfile) {
2206 fclose(srv_dict_tmpfile);
2207 srv_dict_tmpfile = 0;
2208 }
2209
2210 if (srv_misc_tmpfile) {
2211 fclose(srv_misc_tmpfile);
2212 srv_misc_tmpfile = 0;
2213 }
2214
2215 /* This must be disabled before closing the buffer pool
2216 and closing the data dictionary. */
2217 btr_search_disable();
2218
2219 ibuf_close();
2220 log_shutdown();
2221 lock_sys_close();
2222 trx_sys_file_format_close();
2223 trx_sys_close();
2224
2225 mutex_free(&srv_monitor_file_mutex);
2226 mutex_free(&srv_dict_tmpfile_mutex);
2227 mutex_free(&srv_misc_tmpfile_mutex);
2228 dict_close();
2229 btr_search_sys_free();
2230
2231 /* 3. Free all InnoDB's own mutexes and the os_fast_mutexes inside
2232 them */
2233 os_aio_free();
2234 sync_close();
2235 srv_free();
2236 fil_close();
2237
2238 /* 4. Free the os_conc_mutex and all os_events and os_mutexes */
2239
2240 os_sync_free();
2241
2242 /* 5. Free all allocated memory */
2243
2244 pars_lexer_close();
2245 log_mem_free();
2246 buf_pool_free(srv_buf_pool_instances);
2247 mem_close();
2248
2249 /* ut_free_all_mem() frees all allocated memory not freed yet
2250 in shutdown, and it will also free the ut_list_mutex, so it
2251 should be the last one for all operation */
2252 ut_free_all_mem();
2253
2254 if (os_thread_count != 0
2255 || os_event_count != 0
2256 || os_mutex_count != 0
2257 || os_fast_mutex_count != 0) {
2258 fprintf(stderr,
2259 "InnoDB: Warning: some resources were not"
2260 " cleaned up in shutdown:\n"
2261 "InnoDB: threads %lu, events %lu,"
2262 " os_mutexes %lu, os_fast_mutexes %lu\n",
2263 (ulong) os_thread_count, (ulong) os_event_count,
2264 (ulong) os_mutex_count, (ulong) os_fast_mutex_count);
2265 }
2266
2267 if (dict_foreign_err_file) {
2268 fclose(dict_foreign_err_file);
2269 }
2270 if (lock_latest_err_file) {
2271 fclose(lock_latest_err_file);
2272 }
2273
2274 if (srv_print_verbose_log) {
2275 ut_print_timestamp(stderr);
2276 fprintf(stderr,
2277 " InnoDB: Shutdown completed;"
2278 " log sequence number %llu\n",
2279 srv_shutdown_lsn);
2280 }
2281
2282 srv_was_started = FALSE;
2283 srv_start_has_been_called = FALSE;
2284
2285 return((int) DB_SUCCESS);
2286 }
