MDEV-14705: slow innodb startup/shutdown can exceed systemd timeout

Use systemd EXTEND_TIMEOUT_USEC to advise systemd of progress

Move towards progress measures rather than pure time based measures.

Progress reporting at numberious shutdown/startup locations incuding:
* For innodb_fast_shutdown=0 trx_roll_must_shutdown() for rolling back incomplete transactions.
* For merging the change buffer (in srv_shutdown(bool ibuf_merge))
* For purging history, srv_do_purge

Thanks Marko for feedback and suggestions.

Author: grooverdan

include/my_systemd.h renamed to include/my_service_manager.h

@@ -16,8 +16,8 @@
 */
 
 
-#ifndef MY_SYSTEMD_INCLUDED
-#define MY_SYSTEMD_INCLUDED
+#ifndef MY_SERVICE_MANAGER_INCLUDED
+#define MY_SERVICE_MANAGER_INCLUDED
 
 #if defined(HAVE_SYSTEMD) && !defined(EMBEDDED_LIBRARY)
 /*
@@ -26,9 +26,14 @@
 */
 #define __STDC_FORMAT_MACROS
 #include <systemd/sd-daemon.h>
+/** INTERVAL in seconds followed by printf style status */
+#define service_manager_extend_timeout(INTERVAL, FMTSTR, ...) \
+  sd_notifyf(0, "STATUS=" FMTSTR "\nEXTEND_TIMEOUT_USEC=%u\n", ##__VA_ARGS__, INTERVAL * 1000000)
+
 #else
 #define sd_notify(X, Y)
 #define sd_notifyf(E, F, ...)
+#define service_manager_extend_timeout(I, FMTSTR, ...)
 #endif
 
-#endif /* MY_SYSTEMD_INCLUDED */
+#endif /* MY_SERVICE_MANAGER_INCLUDED */

sql/mysqld.cc

@@ -111,7 +111,7 @@
 #include <poll.h>
 #endif
 
-#include <my_systemd.h>
+#include <my_service_manager.h>
 
 #define mysqld_charset &my_charset_latin1
 
@@ -6482,7 +6482,7 @@ void handle_connections_sockets()
 #endif
 
   sd_notify(0, "READY=1\n"
-            "STATUS=Taking your SQL requests now...");
+            "STATUS=Taking your SQL requests now...\n");
 
   DBUG_PRINT("general",("Waiting for connections."));
   MAYBE_BROKEN_SYSCALL;
@@ -6700,7 +6700,7 @@ void handle_connections_sockets()
     set_current_thd(0);
   }
   sd_notify(0, "STOPPING=1\n"
-            "STATUS=Shutdown in progress");
+            "STATUS=Shutdown in progress\n");
   DBUG_VOID_RETURN;
 }
 

storage/innobase/buf/buf0dump.cc

@@ -42,6 +42,7 @@ Created April 08, 2011 Vasil Dimov
 #include "ut0byte.h" /* ut_ull_create() */
 #include "ut0sort.h" /* UT_SORT_FUNCTION_BODY */
 #include "mysql/service_wsrep.h" /* wsrep_recovery */
+#include <my_service_manager.h>
 
 enum status_severity {
 	STATUS_INFO,
@@ -333,6 +334,14 @@ buf_dump(
 					i + 1, srv_buf_pool_instances,
 					j + 1, n_pages);
 			}
+			if ( (j % 1024) == 0) {
+				service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+					"Dumping buffer pool "
+					ULINTPF "/" ULINTPF ", "
+					"page " ULINTPF "/" ULINTPF,
+					i + 1, srv_buf_pool_instances,
+					j + 1, n_pages);
+			}
 		}
 
 		ut_free(dump);

storage/innobase/buf/buf0flu.cc

@@ -54,6 +54,8 @@ Created 11/11/1995 Heikki Tuuri
 #include "mysql/service_thd_wait.h"
 #include "fil0pagecompress.h"
 
+#include <my_service_manager.h>
+
 /** Number of pages flushed through non flush_list flushes. */
 static ulint buf_lru_flush_page_count = 0;
 
@@ -528,6 +530,14 @@ buf_flush_remove(
 	buf_pool_t*	buf_pool = buf_pool_from_bpage(bpage);
 	ulint		zip_size;
 
+	/* TODO Marko: "I think that it might be useful to have a global time base for the shutdown progress reporting and extending the timeout intervals." */
+	if (UNIV_UNLIKELY(srv_shutdown_state == SRV_SHUTDOWN_FLUSH_PHASE)) {
+		service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+			"Flush and remove page with tablespace id %d"
+			", Poolid %d, flush list length %d",
+			bpage->space, buf_pool->instance_no, UT_LIST_GET_LEN(buf_pool->flush_list));
+	}
+
 	ut_ad(buf_pool_mutex_own(buf_pool));
 	ut_ad(mutex_own(buf_page_get_mutex(bpage)));
 	ut_ad(bpage->in_flush_list);

storage/innobase/handler/ha_innodb.cc

@@ -55,7 +55,7 @@ MYSQL_PLUGIN_IMPORT extern char mysql_unpacked_real_data_home[];
 #include <io.h>
 #endif
 
-#include <my_systemd.h>
+#include <my_service_manager.h>
 
 /** @file ha_innodb.cc */
 

storage/innobase/include/univ.i

@@ -65,6 +65,10 @@ component, i.e. we show M.N.P as M.N */
 	IB_TO_STR(INNODB_VERSION_MAJOR) "."		\
 	IB_TO_STR(INNODB_VERSION_MINOR) "/en/"
 
+/** How far ahead should we tell the service manager the timeout
+(time in seconds) */
+#define INNODB_EXTEND_TIMEOUT_INTERVAL 30
+
 #ifdef MYSQL_DYNAMIC_PLUGIN
 /* In the dynamic plugin, redefine some externally visible symbols
 in order not to conflict with the symbols of a builtin InnoDB. */

storage/innobase/log/log0log.cc

@@ -39,7 +39,7 @@ Created 12/9/1995 Heikki Tuuri
 
 #ifndef UNIV_HOTBACKUP
 #if MYSQL_VERSION_ID < 100200
-# include <my_systemd.h> /* sd_notifyf() */
+# include <my_service_manager.h>
 #endif
 
 #include "mem0mem.h"
@@ -1443,6 +1443,11 @@ log_write_up_to(
 		return;
 	}
 
+	if (srv_shutdown_state != SRV_SHUTDOWN_NONE) {
+		service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+			"log write up to: %llu", lsn);
+	}
+
 loop:
 	ut_ad(++loop_count < 100);
 
@@ -2351,8 +2356,9 @@ log_group_read_log_seg(
 	if (recv_sys->report(ut_time())) {
 		ib_logf(IB_LOG_LEVEL_INFO, "Read redo log up to LSN=" LSN_PF,
 			start_lsn);
-		sd_notifyf(0, "STATUS=Read redo log up to LSN=" LSN_PF,
-			   start_lsn);
+		service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+			"Read redo log up to LSN=" LSN_PF,
+			start_lsn);
 	}
 
 	if (start_lsn != end_lsn) {
@@ -3320,10 +3326,16 @@ logs_empty_and_mark_files_at_shutdown(void)
 	before proceeding further. */
 
 	count = 0;
+#define COUNT_INTERVAL 600
+#define CHECK_INTERVAL 100000
+	service_manager_extend_timeout(COUNT_INTERVAL * CHECK_INTERVAL/1000000 * 2,
+		"Waiting for page cleaner");
 	while (buf_page_cleaner_is_active) {
 		++count;
-		os_thread_sleep(100000);
-		if (srv_print_verbose_log && count > 600) {
+		os_thread_sleep(CHECK_INTERVAL);
+		if (srv_print_verbose_log && count > COUNT_INTERVAL) {
+			service_manager_extend_timeout(COUNT_INTERVAL * CHECK_INTERVAL/1000000 * 2,
+				"Waiting for page cleaner");
 			ib_logf(IB_LOG_LEVEL_INFO,
 				"Waiting for page_cleaner to "
 				"finish flushing of buffer pool");
@@ -3408,6 +3420,8 @@ logs_empty_and_mark_files_at_shutdown(void)
 	}
 
 	if (!srv_read_only_mode) {
+		service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+			"ensuring dirty buffer pool are written to log");
 		log_make_checkpoint_at(LSN_MAX, TRUE);
 
 		mutex_enter(&log_sys->mutex);
@@ -3451,6 +3465,8 @@ logs_empty_and_mark_files_at_shutdown(void)
 	srv_thread_type	type = srv_get_active_thread_type();
 	ut_a(type == SRV_NONE);
 
+	service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+				       "Free innodb buffer pool");
 	buf_all_freed();
 
 	ut_a(lsn == log_sys->lsn);

storage/innobase/log/log0recv.cc

@@ -30,7 +30,7 @@ Created 9/20/1997 Heikki Tuuri
 #include <stdio.h>                              // Solaris/x86 header file bug
 
 #include <vector>
-#include <my_systemd.h>
+#include <my_service_manager.h>
 
 #include "log0recv.h"
 
@@ -1717,8 +1717,8 @@ recv_recover_page_func(
 		if (recv_sys->report(time)) {
 			ib_logf(IB_LOG_LEVEL_INFO,
 				"To recover: " ULINTPF " pages from log", n);
-			sd_notifyf(0, "STATUS=To recover: " ULINTPF
-				   " pages from log", n);
+			service_manager_extend_timeout(
+				INNODB_EXTEND_TIMEOUT_INTERVAL, "To recover: " ULINTPF " pages from log", n);
 		}
 	}
 
@@ -2911,6 +2911,9 @@ recv_init_crash_recovery(void)
 	and restore them from the doublewrite buffer if
 	possible */
 
+	service_manager_extend_timeout(
+		INNODB_EXTEND_TIMEOUT_INTERVAL, "Starting Innodb crash recovery");
+
 	if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
 		buf_dblwr_process();
 

storage/innobase/srv/srv0srv.cc

@@ -77,6 +77,12 @@ Created 10/8/1995 Heikki Tuuri
 #include "fil0pagecompress.h"
 #include "btr0scrub.h"
 
+#include <my_service_manager.h>
+
+#ifdef WITH_WSREP
+extern int wsrep_debug;
+extern int wsrep_trx_is_aborting(void *thd_ptr);
+#endif
 /* The following is the maximum allowed duration of a lock wait. */
 UNIV_INTERN ulong	srv_fatal_semaphore_wait_threshold =  DEFAULT_SRV_FATAL_SEMAPHORE_TIMEOUT;
 
@@ -2727,6 +2733,10 @@ srv_do_purge(
 
 		*n_total_purged += n_pages_purged;
 
+		if (n_pages_purged > 0) {
+			service_manager_extend_timeout(
+				INNODB_EXTEND_TIMEOUT_INTERVAL, "Innodb %d pages purged", n_pages_purged);
+		}
 	} while (!srv_purge_should_exit(n_pages_purged)
 		 && n_pages_purged > 0
 		 && purge_sys->state == PURGE_STATE_RUN);

storage/innobase/trx/trx0roll.cc

@@ -25,7 +25,7 @@ Created 3/26/1996 Heikki Tuuri
 *******************************************************/
 
 #include "my_config.h"
-#include <my_systemd.h>
+#include <my_service_manager.h>
 
 #include "trx0roll.h"
 
@@ -740,11 +740,17 @@ UNIV_INTERN void trx_roll_report_progress()
 				n_rows += t->undo_no;
 			}
 		}
+
+		if (n_rows > 0) {
+			service_manager_extend_timeout(
+				INNODB_EXTEND_TIMEOUT_INTERVAL,
+				"To roll back: " ULINTPF " transactions, "
+				"%llu rows", n_trx, n_rows);
+		}
+
 		ib_logf(IB_LOG_LEVEL_INFO,
 			"To roll back: " ULINTPF " transactions, "
 			"%llu rows", n_trx, n_rows);
-		sd_notifyf(0, "STATUS=To roll back: " ULINTPF " transactions, "
-			   "%llu rows", n_trx, n_rows);
 	}
 
 	mutex_exit(&recv_sys->mutex);

storage/xtradb/buf/buf0dump.cc

@@ -42,6 +42,7 @@ Created April 08, 2011 Vasil Dimov
 #include "ut0byte.h" /* ut_ull_create() */
 #include "ut0sort.h" /* UT_SORT_FUNCTION_BODY */
 #include "mysql/service_wsrep.h" /* wsrep_recovery */
+#include <my_service_manager.h>
 
 enum status_severity {
 	STATUS_INFO,
@@ -333,6 +334,14 @@ buf_dump(
 					i + 1, srv_buf_pool_instances,
 					j + 1, n_pages);
 			}
+			if ( (j % 1024) == 0) {
+				service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+					"Dumping buffer pool "
+					ULINTPF "/" ULINTPF ", "
+					"page " ULINTPF "/" ULINTPF,
+					i + 1, srv_buf_pool_instances,
+					j + 1, n_pages);
+			}
 		}
 
 		ut_free(dump);

storage/xtradb/buf/buf0flu.cc

@@ -54,6 +54,8 @@ Created 11/11/1995 Heikki Tuuri
 #include "mysql/service_thd_wait.h"
 #include "fil0pagecompress.h"
 
+#include <my_service_manager.h>
+
 /** Number of pages flushed through non flush_list flushes. */
 // static ulint buf_lru_flush_page_count = 0;
 
@@ -575,6 +577,14 @@ buf_flush_remove(
 	buf_pool_t*	buf_pool = buf_pool_from_bpage(bpage);
 	ulint		zip_size;
 
+	/* TODO Marko: "I think that it might be useful to have a global time base for the shutdown progress reporting and extending the timeout intervals." */
+	if (UNIV_UNLIKELY(srv_shutdown_state == SRV_SHUTDOWN_FLUSH_PHASE)) {
+		service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+			"Flush and remove page with tablespace id %d"
+			", Poolid %d, flush list length %d",
+			bpage->space, buf_pool->instance_no, UT_LIST_GET_LEN(buf_pool->flush_list));
+	}
+
 	ut_ad(mutex_own(buf_page_get_mutex(bpage)));
 #if defined UNIV_DEBUG || defined UNIV_BUF_DEBUG
 	ut_ad(buf_page_get_state(bpage) != BUF_BLOCK_ZIP_DIRTY

storage/xtradb/handler/ha_innodb.cc

@@ -50,7 +50,7 @@ this program; if not, write to the Free Software Foundation, Inc.,
 #include <io.h>
 #endif
 
-#include <my_systemd.h>
+#include <my_service_manager.h>
 
 /** @file ha_innodb.cc */
 

storage/xtradb/include/univ.i

@@ -73,6 +73,10 @@ component, i.e. we show M.N.P as M.N */
 	IB_TO_STR(INNODB_VERSION_MAJOR) "."		\
 	IB_TO_STR(INNODB_VERSION_MINOR) "/en/"
 
+/** How far ahead should we tell the service manager the timeout
+(time in seconds) */
+#define INNODB_EXTEND_TIMEOUT_INTERVAL 30
+
 #ifdef MYSQL_DYNAMIC_PLUGIN
 /* In the dynamic plugin, redefine some externally visible symbols
 in order not to conflict with the symbols of a builtin InnoDB. */