backport Bug #47707 print some progress messages during shutdown of innodb

to mysql-5.5

rb://979 approved by Marko

5 files changed, 207 insertions, 39 deletions

diff --git a/storage/innobase/buf/buf0buf.c b/storage/innobase/buf/buf0buf.c
index 62837920753..1672057d552 100644
--- a/storage/innobase/buf/buf0buf.c
+++ b/storage/innobase/buf/buf0buf.c
@@ -4750,34 +4750,32 @@ buf_all_freed(void)
 /*********************************************************************//**
 Checks that there currently are no pending i/o-operations for the buffer
 pool.
-@return	TRUE if there is no pending i/o */
+@return	number of pending i/o */
 UNIV_INTERN
-ibool
-buf_pool_check_no_pending_io(void)
-/*==============================*/
+ulint
+buf_pool_check_num_pending_io(void)
+/*===============================*/
 {
 	ulint		i;
-	ibool		ret = TRUE;
+	ulint		pending_io = 0;
 
 	buf_pool_mutex_enter_all();
 
-	for (i = 0; i < srv_buf_pool_instances && ret; i++) {
+	for (i = 0; i < srv_buf_pool_instances; i++) {
 		const buf_pool_t*	buf_pool;
 
 		buf_pool = buf_pool_from_array(i);
 
-		if (buf_pool->n_pend_reads
-		    + buf_pool->n_flush[BUF_FLUSH_LRU]
-		    + buf_pool->n_flush[BUF_FLUSH_LIST]
-		    + buf_pool->n_flush[BUF_FLUSH_SINGLE_PAGE]) {
+		pending_io += buf_pool->n_pend_reads
+			      + buf_pool->n_flush[BUF_FLUSH_LRU]
+			      + buf_pool->n_flush[BUF_FLUSH_LIST]
+			      + buf_pool->n_flush[BUF_FLUSH_SINGLE_PAGE];
 
-			ret = FALSE;
-		}
 	}
 
 	buf_pool_mutex_exit_all();
 
-	return(ret);
+	return(pending_io);
 }
 
 #if 0
diff --git a/storage/innobase/include/buf0buf.h b/storage/innobase/include/buf0buf.h
index 5054429156a..d9e6801eb86 100644
--- a/storage/innobase/include/buf0buf.h
+++ b/storage/innobase/include/buf0buf.h
@@ -789,11 +789,11 @@ buf_all_freed(void);
 /*********************************************************************//**
 Checks that there currently are no pending i/o-operations for the buffer
 pool.
-@return	TRUE if there is no pending i/o */
+@return	number of pending i/o operations */
 UNIV_INTERN
-ibool
-buf_pool_check_no_pending_io(void);
-/*==============================*/
+ulint
+buf_pool_check_num_pending_io(void);
+/*===============================*/
 /*********************************************************************//**
 Invalidates the file pages in the buffer pool when an archive recovery is
 completed. All the file pages buffered must be in a replaceable state when
diff --git a/storage/innobase/include/srv0srv.h b/storage/innobase/include/srv0srv.h
index dfe7397d189..2c901d2cf96 100644
--- a/storage/innobase/include/srv0srv.h
+++ b/storage/innobase/include/srv0srv.h
@@ -678,12 +678,14 @@ srv_que_task_enqueue_low(
 	que_thr_t*	thr);	/*!< in: query thread */
 
 /**********************************************************************//**
-Check whether any background thread is active.
-@return FALSE if all are are suspended or have exited. */
+Check whether any background thread is active. If so, return the thread
+type.
+@return ULINT_UNDEFINED if all are are suspended or have exited, thread
+type if any are still active. */
 UNIV_INTERN
-ibool
-srv_is_any_background_thread_active(void);
-/*======================================*/
+ulint
+srv_get_active_thread_type(void);
+/*============================*/
 
 /** Status variables to be passed to MySQL */
 struct export_var_struct{
diff --git a/storage/innobase/log/log0log.c b/storage/innobase/log/log0log.c
index c40292bcf1e..8bae95f0a5d 100644
--- a/storage/innobase/log/log0log.c
+++ b/storage/innobase/log/log0log.c
@@ -3076,9 +3076,12 @@ void
 logs_empty_and_mark_files_at_shutdown(void)
 /*=======================================*/
 {
-	ib_uint64_t	lsn;
-	ulint		arch_log_no;
-	ibool		server_busy;
+	ib_uint64_t		lsn;
+	ulint			arch_log_no;
+	ibool			server_busy;
+	ulint			count = 0;
+	ulint			pending_io;
+	ulint			active_thd;
 
 	if (srv_print_verbose_log) {
 		ut_print_timestamp(stderr);
@@ -3091,6 +3094,8 @@ logs_empty_and_mark_files_at_shutdown(void)
 loop:
 	os_thread_sleep(100000);
 
+	count++;
+
 	mutex_enter(&kernel_mutex);
 
 	/* We need the monitor threads to stop before we proceed with
@@ -3099,6 +3104,21 @@ loop:
 	if (srv_error_monitor_active
 	    || srv_lock_timeout_active
 	    || srv_monitor_active) {
+		const char*	thread_active = NULL;
+
+		/* Print a message every 60 seconds if we are waiting
+		for the monitor thread to exit. Master and worker threads
+		check will be done later. */
+		if (srv_print_verbose_log && count > 600) {
+
+		       if (srv_error_monitor_active) {
+			       thread_active = "srv_error_monitor_thread";
+		       } else if (srv_lock_timeout_active) {
+			       thread_active = "srv_lock_timeout thread";
+		       } else if (srv_monitor_active) {
+			       thread_active = "srv_monitor_thread";
+		       }
+		}
 
 		mutex_exit(&kernel_mutex);
 
@@ -3106,6 +3126,13 @@ loop:
 		os_event_set(srv_monitor_event);
 		os_event_set(srv_timeout_event);
 
+		if (thread_active) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr, "  InnoDB: Waiting for %s to exit\n",
+				thread_active);
+			count = 0;
+		}
+
 		goto loop;
 	}
 
@@ -3116,9 +3143,54 @@ loop:
 
 	server_busy = trx_n_mysql_transactions > 0
 		|| UT_LIST_GET_LEN(trx_sys->trx_list) > trx_n_prepared;
+
+	if (server_busy) {
+		ulint	total_trx = UT_LIST_GET_LEN(trx_sys->trx_list)
+				    + trx_n_mysql_transactions;
+
+		mutex_exit(&kernel_mutex);
+
+		if (srv_print_verbose_log && count > 600) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr, "  InnoDB: Waiting for %lu "
+				"active transactions to finish\n",
+				(ulong) total_trx);
+			count = 0;
+		}
+
+		goto loop;
+	}
+
 	mutex_exit(&kernel_mutex);
 
-	if (server_busy || srv_is_any_background_thread_active()) {
+	/* Check that the background threads are suspended */
+	active_thd = srv_get_active_thread_type();
+
+	if (active_thd != ULINT_UNDEFINED) {
+
+		/* The srv_lock_timeout_thread, srv_error_monitor_thread
+		and srv_monitor_thread should already exit by now. The
+		only threads to be suspended are the master threads
+		and worker threads (purge threads). Print the thread
+		type if any of such threads not in suspended mode */
+		if (srv_print_verbose_log && count > 600) {
+			const char*     thread_type = "<null>";
+
+			switch (active_thd) {
+			case SRV_WORKER:
+				thread_type = "worker threads";
+				break;
+			case SRV_MASTER:
+				thread_type = "master thread";
+				break;
+			}
+
+			ut_print_timestamp(stderr);
+			fprintf(stderr, "  InnoDB: Waiting for %s "
+				"to be suspended\n", thread_type);
+			count = 0;
+		}
+
 		goto loop;
 	}
 
@@ -3130,10 +3202,35 @@ loop:
 		|| log_sys->n_pending_writes;
 	mutex_exit(&log_sys->mutex);
 
-	if (server_busy || !buf_pool_check_no_pending_io()) {
+	if (server_busy) {
+		if (srv_print_verbose_log && count > 600) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr,
+				"  InnoDB: Pending checkpoint_writes: %lu\n"
+				"  InnoDB: Pending log flush writes: %lu\n",
+				(ulong) log_sys->n_pending_checkpoint_writes,
+				(ulong) log_sys->n_pending_writes);
+			count = 0;
+		}
+
 		goto loop;
 	}
 
+	pending_io = buf_pool_check_num_pending_io();
+
+	if (pending_io) {
+		if (srv_print_verbose_log && count > 600) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr, "  InnoDB: Waiting for %lu buffer page "
+				"I/Os to complete\n",
+				(ulong) pending_io);
+			count = 0;
+		}
+
+		goto loop;
+	}
+
+
 #ifdef UNIV_LOG_ARCHIVE
 	log_archive_all();
 #endif /* UNIV_LOG_ARCHIVE */
@@ -3157,7 +3254,7 @@ loop:
 		log_buffer_flush_to_disk();
 
 		/* Check that the background threads stay suspended */
-		if (srv_is_any_background_thread_active()) {
+		if (srv_get_active_thread_type() != ULINT_UNDEFINED) {
 			fprintf(stderr,
 				"InnoDB: Warning: some background thread"
 				" woke up during shutdown\n");
@@ -3166,7 +3263,7 @@ loop:
 
 		srv_shutdown_state = SRV_SHUTDOWN_LAST_PHASE;
 		fil_close_all_files();
-		ut_a(!srv_is_any_background_thread_active());
+		ut_a(srv_get_active_thread_type() == ULINT_UNDEFINED);
 		return;
 	}
 
@@ -3204,7 +3301,7 @@ loop:
 	mutex_exit(&log_sys->mutex);
 
 	/* Check that the background threads stay suspended */
-	if (srv_is_any_background_thread_active()) {
+	if (srv_get_active_thread_type() != ULINT_UNDEFINED) {
 		fprintf(stderr,
 			"InnoDB: Warning: some background thread woke up"
 			" during shutdown\n");
@@ -3222,13 +3319,20 @@ loop:
 
 	if (!buf_all_freed()) {
 
+		if (srv_print_verbose_log && count > 600) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr, " InnoDB: Waiting for dirty buffer "
+				"pages to be flushed\n");
+			count = 0;
+		}
+
 		goto loop;
 	}
 
 	srv_shutdown_state = SRV_SHUTDOWN_LAST_PHASE;
 
 	/* Make some checks that the server really is quiet */
-	ut_a(!srv_is_any_background_thread_active());
+	ut_a(srv_get_active_thread_type() == ULINT_UNDEFINED);
 
 	ut_a(buf_all_freed());
 	ut_a(lsn == log_sys->lsn);
@@ -3250,7 +3354,7 @@ loop:
 	fil_close_all_files();
 
 	/* Make some checks that the server really is quiet */
-	ut_a(!srv_is_any_background_thread_active());
+	ut_a(srv_get_active_thread_type() == ULINT_UNDEFINED);
 
 	ut_a(buf_all_freed());
 	ut_a(lsn == log_sys->lsn);
diff --git a/storage/innobase/srv/srv0srv.c b/storage/innobase/srv/srv0srv.c
index bda086f4778..df89156baae 100644
--- a/storage/innobase/srv/srv0srv.c
+++ b/storage/innobase/srv/srv0srv.c
@@ -2485,21 +2485,23 @@ loop:
 }
 
 /**********************************************************************//**
-Check whether any background thread is active.
-@return FALSE if all are are suspended or have exited. */
+Check whether any background thread is active. If so return the thread
+type
+@return ULINT_UNDEFINED if all are suspended or have exited, thread
+type if any are still active. */
 UNIV_INTERN
-ibool
-srv_is_any_background_thread_active(void)
-/*=====================================*/
+ulint
+srv_get_active_thread_type(void)
+/*============================*/
 {
 	ulint	i;
-	ibool	ret = FALSE;
+	ibool	ret = ULINT_UNDEFINED;
 
 	mutex_enter(&kernel_mutex);
 
 	for (i = 0; i <= SRV_MASTER; ++i) {
 		if (srv_n_threads_active[i] != 0) {
-			ret = TRUE;
+			ret = i;
 			break;
 		}
 	}
@@ -2509,6 +2511,57 @@ srv_is_any_background_thread_active(void)
 	return(ret);
 }
 
+/*********************************************************************//**
+This function prints progress message every 60 seconds during server
+shutdown, for any activities that master thread is pending on. */
+static
+void
+srv_shutdown_print_master_pending(
+/*==============================*/
+	ib_time_t*	last_print_time,	/*!< last time the function
+						print the message */
+	ulint		n_tables_to_drop,	/*!< number of tables to
+						be dropped */
+	ulint		n_bytes_merged,		/*!< number of change buffer
+						just merged */
+	ulint		n_pages_flushed)	/*!< number of pages flushed */
+{
+	ib_time_t	current_time;
+	double		time_elapsed;
+
+	current_time = ut_time();
+	time_elapsed = ut_difftime(current_time, *last_print_time);
+
+	if (time_elapsed > 60) {
+		*last_print_time = ut_time();
+
+		if (n_tables_to_drop) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr, "  InnoDB: Waiting for "
+				"%lu table(s) to be dropped\n",
+				(ulong) n_tables_to_drop);
+		}
+
+		/* Check change buffer merge, we only wait for change buffer
+		merge if it is a slow shutdown */
+		if (!srv_fast_shutdown && n_bytes_merged) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr, "  InnoDB: Waiting for change "
+				"buffer merge to complete\n"
+				"  InnoDB: number of bytes of change buffer "
+				"just merged:  %lu\n",
+				n_bytes_merged);
+		}
+
+		if (n_pages_flushed) {
+			ut_print_timestamp(stderr);
+			fprintf(stderr, "  InnoDB: Waiting for "
+				"%lu pages to be flushed\n",
+				(ulong) n_pages_flushed);
+		}
+        }
+}
+
 /*******************************************************************//**
 Tells the InnoDB server that there has been activity in the database
 and wakes up the master thread if it is suspended (not sleeping). Used
@@ -2664,6 +2717,7 @@ srv_master_thread(
 	ulint		n_pend_ios;
 	ulint		next_itr_time;
 	ulint		i;
+	ib_time_t	last_print_time;
 
 #ifdef UNIV_DEBUG_THREAD_CREATION
 	fprintf(stderr, "Master thread starts, id %lu\n",
@@ -2685,6 +2739,7 @@ srv_master_thread(
 
 	mutex_exit(&kernel_mutex);
 
+	last_print_time = ut_time();
 loop:
 	/*****************************************************************/
 	/* ---- When there is database activity by users, we cycle in this
@@ -3030,6 +3085,14 @@ flush_loop:
 	*/
 	n_bytes_archived = 0;
 
+	/* Print progress message every 60 seconds during shutdown */
+	if (srv_shutdown_state > 0 && srv_print_verbose_log) {
+		srv_shutdown_print_master_pending(&last_print_time,
+						  n_tables_to_drop,
+						  n_bytes_merged,
+						  n_pages_flushed);
+	}
+
 	/* Keep looping in the background loop if still work to do */
 
 	if (srv_fast_shutdown && srv_shutdown_state > 0) {
@@ -3048,6 +3111,7 @@ flush_loop:
 	} else if (n_tables_to_drop
 		   + n_pages_purged + n_bytes_merged + n_pages_flushed
 		   + n_bytes_archived != 0) {
+
 		/* In a 'slow' shutdown we run purge and the insert buffer
 		merge to completion */