1 files changed, 126 insertions, 49 deletions

diff --git a/storage/xtradb/log/log0log.c b/storage/xtradb/log/log0log.c
index af0c801a4ec..dcaf951a0ed 100644
--- a/storage/xtradb/log/log0log.c
+++ b/storage/xtradb/log/log0log.c
@@ -1,6 +1,6 @@
 /*****************************************************************************
 
-Copyright (c) 1995, 2010, Innobase Oy. All Rights Reserved.
+Copyright (c) 1995, 2010, Oracle and/or its affiliates. All Rights Reserved.
 Copyright (c) 2009, Google Inc.
 
 Portions of this file contain modifications contributed and copyrighted by
@@ -18,8 +18,8 @@ ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
 FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details.
 
 You should have received a copy of the GNU General Public License along with
-this program; if not, write to the Free Software Foundation, Inc., 59 Temple
-Place, Suite 330, Boston, MA 02111-1307 USA
+this program; if not, write to the Free Software Foundation, Inc.,
+51 Franklin Street, Suite 500, Boston, MA 02110-1335 USA
 
 *****************************************************************************/
 
@@ -1693,13 +1693,10 @@ log_preflush_pool_modified_pages(
 		recv_apply_hashed_log_recs(TRUE);
 	}
 
- retry:
 	n_pages = buf_flush_list(ULINT_MAX, new_oldest);
 
-	if (sync && n_pages != 0) {
-		//buf_flush_wait_batch_end(NULL, BUF_FLUSH_LIST);
-		os_thread_sleep(100000);
-		goto retry;
+	if (sync) {
+		buf_flush_wait_batch_end(NULL, BUF_FLUSH_LIST);
 	}
 
 	if (n_pages == ULINT_UNDEFINED) {
@@ -2023,13 +2020,6 @@ log_checkpoint(
 {
 	ib_uint64_t	oldest_lsn;
 
-#ifdef UNIV_DEBUG
-	if (srv_flush_checkpoint_debug == 1) {
-
-		return TRUE;
-	}
-#endif
-
 	if (recv_recovery_is_on()) {
 		recv_apply_hashed_log_recs(TRUE);
 	}
@@ -2134,11 +2124,7 @@ log_make_checkpoint_at(
 					physical write will always be made to
 					log files */
 {
-#ifdef UNIV_DEBUG
-	if (srv_flush_checkpoint_debug == 1)
-		return;
-#endif
-/* Preflush pages synchronously */
+	/* Preflush pages synchronously */
 
 	while (!log_preflush_pool_modified_pages(lsn, TRUE));
 
@@ -2230,13 +2216,7 @@ log_checkpoint_margin(void)
 	ibool		checkpoint_sync;
 	ibool		do_checkpoint;
 	ibool		success;
-
-#ifdef UNIV_DEBUG
-	if (srv_flush_checkpoint_debug == 1)
-		return;
-#endif
-
- loop:
+loop:
 	sync = FALSE;
 	checkpoint_sync = FALSE;
 	do_checkpoint = FALSE;
@@ -2259,15 +2239,13 @@ log_checkpoint_margin(void)
 		/* A flush is urgent: we have to do a synchronous preflush */
 
 		sync = TRUE;
-		advance = age - log->max_modified_age_sync;
+		advance = 2 * (age - log->max_modified_age_sync);
 	} else if (age > log_max_modified_age_async()) {
 
 		/* A flush is not urgent: we do an asynchronous preflush */
 		advance = age - log_max_modified_age_async();
-		log->check_flush_or_checkpoint = FALSE;
 	} else {
 		advance = 0;
-		log->check_flush_or_checkpoint = FALSE;
 	}
 
 	checkpoint_age = log->lsn - log->last_checkpoint_lsn;
@@ -2284,9 +2262,9 @@ log_checkpoint_margin(void)
 
 		do_checkpoint = TRUE;
 
-		//log->check_flush_or_checkpoint = FALSE;
+		log->check_flush_or_checkpoint = FALSE;
 	} else {
-		//log->check_flush_or_checkpoint = FALSE;
+		log->check_flush_or_checkpoint = FALSE;
 	}
 
 	mutex_exit(&(log->mutex));
@@ -2294,7 +2272,6 @@ log_checkpoint_margin(void)
 	if (advance) {
 		ib_uint64_t	new_oldest = oldest_lsn + advance;
 
-retry:
 		success = log_preflush_pool_modified_pages(new_oldest, sync);
 
 		/* If the flush succeeded, this thread has done its part
@@ -2309,7 +2286,7 @@ retry:
 			log->check_flush_or_checkpoint = TRUE;
 
 			mutex_exit(&(log->mutex));
-			goto retry;
+			goto loop;
 		}
 	}
 
@@ -3187,11 +3164,7 @@ void
 log_check_margins(void)
 /*===================*/
 {
-#ifdef UNIV_DEBUG
-	if (srv_flush_checkpoint_debug == 1)
-		return;
-#endif
- loop:
+loop:
 	log_flush_margin();
 
 	log_checkpoint_margin();
@@ -3223,9 +3196,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);
@@ -3244,6 +3220,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
@@ -3252,6 +3230,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);
 
@@ -3259,6 +3252,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;
 	}
 
@@ -3269,9 +3269,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;
 	}
 
@@ -3283,10 +3328,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 */
@@ -3310,7 +3380,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");
@@ -3319,7 +3389,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;
 	}
 
@@ -3357,7 +3427,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");
@@ -3375,13 +3445,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);
@@ -3403,7 +3480,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);