MDEV-11027 InnoDB log recovery is too noisy

Provide more useful progress reporting of crash recovery.

recv_sys_t::progress_time: The time of the last report.

recv_scan_print_counter: Remove.

log_group_read_log_seg(): After after each I/O request,
report progress if needed.

recv_apply_hashed_log_recs(): At the start of each batch,
if there are pages to be recovered, issue a message.

6 files changed, 90 insertions, 156 deletions

diff --git a/storage/innobase/include/log0recv.h b/storage/innobase/include/log0recv.h
index ec70e4b7d56..aa5f79aa198 100644
--- a/storage/innobase/include/log0recv.h
+++ b/storage/innobase/include/log0recv.h
@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1997, 2010, Innobase Oy. All Rights Reserved.
+Copyright (c) 2017, MariaDB Corporation.
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -428,6 +429,8 @@ struct recv_sys_struct{
 				scan find a corrupt log block, or a corrupt
 				log record, or there is a log parsing
 				buffer overflow */
+	/** the time when progress was last reported */
+	ib_time_t	progress_time;
 #ifdef UNIV_LOG_ARCHIVE
 	log_group_t*	archive_group;
 				/*!< in archive recovery: the log group whose
diff --git a/storage/innobase/log/log0log.c b/storage/innobase/log/log0log.c
index eacee12a2d4..4a307c80598 100644
--- a/storage/innobase/log/log0log.c
+++ b/storage/innobase/log/log0log.c
@@ -2,6 +2,7 @@
 
 Copyright (c) 1995, 2010, Oracle and/or its affiliates. All Rights Reserved.
 Copyright (c) 2009, Google Inc.
+Copyright (c) 2017, MariaDB Corporation.
 
 Portions of this file contain modifications contributed and copyrighted by
 Google, Inc. Those modifications are gratefully acknowledged and are described
@@ -2303,6 +2304,7 @@ log_group_read_log_seg(
 	ulint	len;
 	ulint	source_offset;
 	ibool	sync;
+	ib_time_t	time;
 
 	ut_ad(mutex_own(&(log_sys->mutex)));
 
@@ -2335,6 +2337,15 @@ loop:
 	start_lsn += len;
 	buf += len;
 
+	time = ut_time();
+
+	if (recv_sys->progress_time - time >= 15) {
+		recv_sys->progress_time = time;
+		ut_print_timestamp(stderr);
+		fprintf(stderr, "  InnoDB: Read redo log up to LSN=%llu\n",
+			start_lsn);
+	}
+
 	if (start_lsn != end_lsn) {
 
 		goto loop;
diff --git a/storage/innobase/log/log0recv.c b/storage/innobase/log/log0recv.c
index eee3b9ff6c3..a458e47d45d 100644
--- a/storage/innobase/log/log0recv.c
+++ b/storage/innobase/log/log0recv.c
@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1997, 2016, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2017, MariaDB Corporation.
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -65,7 +66,7 @@ this must be less than UNIV_PAGE_SIZE as it is stored in the buffer pool */
 #define RECV_READ_AHEAD_AREA	32
 
 /** The recovery system */
-UNIV_INTERN recv_sys_t*	recv_sys = NULL;
+UNIV_INTERN recv_sys_t*	recv_sys;
 /** TRUE when applying redo log records during crash recovery; FALSE
 otherwise.  Note that this is FALSE while a background thread is
 rolling back incomplete transactions. */
@@ -121,9 +122,6 @@ UNIV_INTERN ibool	recv_is_making_a_backup	= FALSE;
 UNIV_INTERN ibool	recv_is_from_backup	= FALSE;
 # define buf_pool_get_curr_size() (5 * 1024 * 1024)
 #endif /* !UNIV_HOTBACKUP */
-/** The following counter is used to decide when to print info on
-log scan */
-static ulint	recv_scan_print_counter;
 
 /** The type of the previous parsed redo log record */
 static ulint	recv_previous_parsed_rec_type;
@@ -275,8 +273,6 @@ recv_sys_var_init(void)
 
 	recv_no_ibuf_operations = FALSE;
 
-	recv_scan_print_counter	= 0;
-
 	recv_previous_parsed_rec_type	= 999999;
 
 	recv_previous_parsed_rec_offset	= 0;
@@ -342,6 +338,7 @@ recv_sys_init(
 	recv_sys->last_block = ut_align(recv_sys->last_block_buf_start,
 					OS_FILE_LOG_BLOCK_SIZE);
 	recv_sys->found_corrupt_log = FALSE;
+	recv_sys->progress_time = ut_time();
 
 	recv_max_page_lsn = 0;
 
@@ -1490,6 +1487,7 @@ recv_recover_page_func(
 	ibool		success;
 #endif /* !UNIV_HOTBACKUP */
 	mtr_t		mtr;
+	ib_time_t	time;
 
 	mutex_enter(&(recv_sys->mutex));
 
@@ -1669,6 +1667,8 @@ recv_recover_page_func(
 
 	mtr_commit(&mtr);
 
+	time = ut_time();
+
 	mutex_enter(&(recv_sys->mutex));
 
 	if (recv_max_page_lsn < page_lsn) {
@@ -1677,11 +1677,16 @@ recv_recover_page_func(
 
 	recv_addr->state = RECV_PROCESSED;
 
-	ut_a(recv_sys->n_addrs);
-	recv_sys->n_addrs--;
-
-	mutex_exit(&(recv_sys->mutex));
+	ut_a(recv_sys->n_addrs > 0);
+	if (--recv_sys->n_addrs && recv_sys->progress_time - time >= 15) {
+		recv_sys->progress_time = time;
+		ut_print_timestamp(stderr);
+		fprintf(stderr,
+			"  InnoDB: To recover: " ULINTPF " pages from log\n",
+			recv_sys->n_addrs);
+	}
 
+	mutex_exit(&recv_sys->mutex);
 }
 
 #ifndef UNIV_HOTBACKUP
@@ -1727,9 +1732,6 @@ recv_read_in_area(
 	}
 
 	buf_read_recv_pages(FALSE, space, zip_size, page_nos, n);
-	/*
-	fprintf(stderr, "Recv pages at %lu n %lu\n", page_nos[0], n);
-	*/
 	return(n);
 }
 
@@ -1753,7 +1755,6 @@ recv_apply_hashed_log_recs(
 	recv_addr_t* recv_addr;
 	ulint	i;
 	ulint	n_pages;
-	ibool	has_printed	= FALSE;
 	mtr_t	mtr;
 loop:
 	mutex_enter(&(recv_sys->mutex));
@@ -1773,6 +1774,16 @@ loop:
 		recv_no_ibuf_operations = TRUE;
 	}
 
+	if (recv_sys->n_addrs) {
+		ut_print_timestamp(stderr);
+		fprintf(stderr,
+			"  InnoDB: %s" ULINTPF " pages from redo log\n",
+			allow_ibuf
+			? "Starting final batch to recover "
+			: "Starting a batch to recover ",
+			recv_sys->n_addrs);
+	}
+
 	recv_sys->apply_log_recs = TRUE;
 	recv_sys->apply_batch_on = TRUE;
 
@@ -1786,16 +1797,6 @@ loop:
 			ulint	page_no = recv_addr->page_no;
 
 			if (recv_addr->state == RECV_NOT_PROCESSED) {
-				if (!has_printed) {
-					ut_print_timestamp(stderr);
-					fputs("  InnoDB: Starting an"
-					      " apply batch of log records"
-					      " to the database...\n"
-					      "InnoDB: Progress in percents: ",
-					      stderr);
-					has_printed = TRUE;
-				}
-
 				mutex_exit(&(recv_sys->mutex));
 
 				if (buf_page_peek(space, page_no)) {
@@ -1821,16 +1822,6 @@ loop:
 
 			recv_addr = HASH_GET_NEXT(addr_hash, recv_addr);
 		}
-
-		if (has_printed
-		    && (i * 100) / hash_get_n_cells(recv_sys->addr_hash)
-		    != ((i + 1) * 100)
-		    / hash_get_n_cells(recv_sys->addr_hash)) {
-
-			fprintf(stderr, "%lu ", (ulong)
-				((i * 100)
-				 / hash_get_n_cells(recv_sys->addr_hash)));
-		}
 	}
 
 	/* Wait until all the pages have been processed */
@@ -1844,11 +1835,6 @@ loop:
 		mutex_enter(&(recv_sys->mutex));
 	}
 
-	if (has_printed) {
-
-		fprintf(stderr, "\n");
-	}
-
 	if (!allow_ibuf) {
 		/* Flush all the file pages to disk and invalidate them in
 		the buffer pool */
@@ -1876,10 +1862,6 @@ loop:
 
 	recv_sys_empty_hash();
 
-	if (has_printed) {
-		fprintf(stderr, "InnoDB: Apply batch completed\n");
-	}
-
 	mutex_exit(&(recv_sys->mutex));
 }
 #else /* !UNIV_HOTBACKUP */
@@ -1903,10 +1885,6 @@ recv_apply_log_recs_for_backup(void)
 
 	block = back_block1;
 
-	fputs("InnoDB: Starting an apply batch of log records"
-	      " to the database...\n"
-	      "InnoDB: Progress in percents: ", stderr);
-
 	n_hash_cells = hash_get_n_cells(recv_sys->addr_hash);
 
 	for (i = 0; i < n_hash_cells; i++) {
@@ -2697,10 +2675,10 @@ recv_scan_log_recs(
 #ifndef UNIV_HOTBACKUP
 			if (recv_log_scan_is_startup_type
 			    && !recv_needed_recovery) {
-
+				ut_print_timestamp(stderr);
 				fprintf(stderr,
-					"InnoDB: Log scan progressed"
-					" past the checkpoint lsn %llu\n",
+					"  InnoDB: Starting crash recovery"
+					" from checkpoint LSN=%llu\n",
 					recv_sys->scanned_lsn);
 				recv_init_crash_recovery();
 			}
@@ -2751,19 +2729,6 @@ recv_scan_log_recs(
 
 	*group_scanned_lsn = scanned_lsn;
 
-	if (recv_needed_recovery
-	    || (recv_is_from_backup && !recv_is_making_a_backup)) {
-		recv_scan_print_counter++;
-
-		if (finished || (recv_scan_print_counter % 80 == 0)) {
-
-			fprintf(stderr,
-				"InnoDB: Doing recovery: scanned up to"
-				" log sequence number %llu\n",
-				*group_scanned_lsn);
-		}
-	}
-
 	if (more_data && !recv_sys->found_corrupt_log) {
 		/* Try to parse more log records */
 
@@ -2854,17 +2819,6 @@ recv_init_crash_recovery(void)
 
 	recv_needed_recovery = TRUE;
 
-	ut_print_timestamp(stderr);
-
-	fprintf(stderr,
-		"  InnoDB: Database was not"
-		" shut down normally!\n"
-		"InnoDB: Starting crash recovery.\n");
-
-	fprintf(stderr,
-		"InnoDB: Reading tablespace information"
-		" from the .ibd files...\n");
-
 	fil_load_single_table_tablespaces();
 
 	/* If we are using the doublewrite method, we will
@@ -2877,8 +2831,7 @@ recv_init_crash_recovery(void)
 		fprintf(stderr,
 			"InnoDB: Restoring possible"
 			" half-written data pages from"
-			" the doublewrite\n"
-			"InnoDB: buffer...\n");
+			" the doublewrite buffer...\n");
 		trx_sys_doublewrite_init_or_restore_pages(TRUE);
 	}
 }
diff --git a/storage/xtradb/include/log0recv.h b/storage/xtradb/include/log0recv.h
index ad30f6862c2..afac0d4f4ab 100644
--- a/storage/xtradb/include/log0recv.h
+++ b/storage/xtradb/include/log0recv.h
@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1997, 2010, Innobase Oy. All Rights Reserved.
+Copyright (c) 2017, MariaDB Corporation.
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -465,6 +466,8 @@ struct recv_sys_struct{
 				scan find a corrupt log block, or a corrupt
 				log record, or there is a log parsing
 				buffer overflow */
+	/** the time when progress was last reported */
+	ib_time_t	progress_time;
 #ifdef UNIV_LOG_ARCHIVE
 	log_group_t*	archive_group;
 				/*!< in archive recovery: the log group whose
diff --git a/storage/xtradb/log/log0log.c b/storage/xtradb/log/log0log.c
index e5063e9c8a1..e327fa7ea9a 100644
--- a/storage/xtradb/log/log0log.c
+++ b/storage/xtradb/log/log0log.c
@@ -2,6 +2,7 @@
 
 Copyright (c) 1995, 2010, Oracle and/or its affiliates. All Rights Reserved.
 Copyright (c) 2009, Google Inc.
+Copyright (c) 2017, MariaDB Corporation.
 
 Portions of this file contain modifications contributed and copyrighted by
 Google, Inc. Those modifications are gratefully acknowledged and are described
@@ -2502,6 +2503,7 @@ log_group_read_log_seg(
 	ulint	len;
 	ulint	source_offset;
 	ibool	sync;
+	ib_time_t	time;
 
 	ut_ad(mutex_own(&(log_sys->mutex)));
 
@@ -2538,6 +2540,15 @@ loop:
 	start_lsn += len;
 	buf += len;
 
+	time = ut_time();
+
+	if (recv_sys->progress_time - time >= 15) {
+		recv_sys->progress_time = time;
+		ut_print_timestamp(stderr);
+		fprintf(stderr, "  InnoDB: Read redo log up to LSN=%llu\n",
+			start_lsn);
+	}
+
 	if (start_lsn != end_lsn) {
 
 		if (release_mutex) {
diff --git a/storage/xtradb/log/log0recv.c b/storage/xtradb/log/log0recv.c
index aea83c90870..6fdc3aff7cc 100644
--- a/storage/xtradb/log/log0recv.c
+++ b/storage/xtradb/log/log0recv.c
@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1997, 2016, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2017, MariaDB Corporation.
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -72,7 +73,7 @@ this must be less than UNIV_PAGE_SIZE as it is stored in the buffer pool */
 #define RECV_READ_AHEAD_AREA	32
 
 /** The recovery system */
-UNIV_INTERN recv_sys_t*	recv_sys = NULL;
+UNIV_INTERN recv_sys_t*	recv_sys;
 /** TRUE when applying redo log records during crash recovery; FALSE
 otherwise.  Note that this is FALSE while a background thread is
 rolling back incomplete transactions. */
@@ -128,9 +129,6 @@ UNIV_INTERN ibool	recv_is_making_a_backup	= FALSE;
 UNIV_INTERN ibool	recv_is_from_backup	= FALSE;
 # define buf_pool_get_curr_size() (5 * 1024 * 1024)
 #endif /* !UNIV_HOTBACKUP */
-/** The following counter is used to decide when to print info on
-log scan */
-static ulint	recv_scan_print_counter;
 
 /** The type of the previous parsed redo log record */
 static ulint	recv_previous_parsed_rec_type;
@@ -285,8 +283,6 @@ recv_sys_var_init(void)
 
 	recv_no_ibuf_operations = FALSE;
 
-	recv_scan_print_counter	= 0;
-
 	recv_previous_parsed_rec_type	= 999999;
 
 	recv_previous_parsed_rec_offset	= 0;
@@ -357,6 +353,7 @@ recv_sys_init(
 	recv_sys->last_block = ut_align(recv_sys->last_block_buf_start,
 					OS_FILE_LOG_BLOCK_SIZE);
 	recv_sys->found_corrupt_log = FALSE;
+	recv_sys->progress_time = ut_time();
 
 	recv_max_page_lsn = 0;
 
@@ -1557,6 +1554,7 @@ recv_recover_page_func(
 	ibool		success;
 #endif /* !UNIV_HOTBACKUP */
 	mtr_t		mtr;
+	ib_time_t	time;
 
 	mutex_enter(&(recv_sys->mutex));
 
@@ -1769,6 +1767,8 @@ recv_recover_page_func(
 
 	mtr_commit(&mtr);
 
+	time = ut_time();
+
 	mutex_enter(&(recv_sys->mutex));
 
 	if (recv_max_page_lsn < page_lsn) {
@@ -1777,11 +1777,16 @@ recv_recover_page_func(
 
 	recv_addr->state = RECV_PROCESSED;
 
-	ut_a(recv_sys->n_addrs);
-	recv_sys->n_addrs--;
-
-	mutex_exit(&(recv_sys->mutex));
+	ut_a(recv_sys->n_addrs > 0);
+	if (--recv_sys->n_addrs && recv_sys->progress_time - time >= 15) {
+		recv_sys->progress_time = time;
+		ut_print_timestamp(stderr);
+		fprintf(stderr,
+			"  InnoDB: To recover: " ULINTPF " pages from log\n",
+			recv_sys->n_addrs);
+	}
 
+	mutex_exit(&recv_sys->mutex);
 }
 
 #ifndef UNIV_HOTBACKUP
@@ -1834,9 +1839,6 @@ recv_read_in_area(
 	}
 
 	buf_read_recv_pages(FALSE, space, zip_size, page_nos, n);
-	/*
-	fprintf(stderr, "Recv pages at %lu n %lu\n", page_nos[0], n);
-	*/
 	return(n);
 }
 
@@ -1860,7 +1862,6 @@ recv_apply_hashed_log_recs(
 	recv_addr_t* recv_addr;
 	ulint	i;
 	ulint	n_pages;
-	ibool	has_printed	= FALSE;
 	mtr_t	mtr;
 loop:
 	mutex_enter(&(recv_sys->mutex));
@@ -1880,6 +1881,20 @@ loop:
 		recv_no_ibuf_operations = TRUE;
 	}
 
+	if (recv_sys->n_addrs) {
+		ut_print_timestamp(stderr);
+		fprintf(stderr,
+			"  InnoDB: %s" ULINTPF " pages from redo log\n",
+			allow_ibuf
+			? "Starting final batch to recover "
+			: "Starting a batch to recover ",
+			recv_sys->n_addrs);
+
+		if (srv_recovery_stats) {
+			recv_sys->stats_recv_turns++;
+		}
+	}
+
 	recv_sys->apply_log_recs = TRUE;
 	recv_sys->apply_batch_on = TRUE;
 
@@ -1893,16 +1908,6 @@ loop:
 			ulint	page_no = recv_addr->page_no;
 
 			if (recv_addr->state == RECV_NOT_PROCESSED) {
-				if (!has_printed) {
-					ut_print_timestamp(stderr);
-					fputs("  InnoDB: Starting an"
-					      " apply batch of log records"
-					      " to the database...\n"
-					      "InnoDB: Progress in percents: ",
-					      stderr);
-					has_printed = TRUE;
-				}
-
 				mutex_exit(&(recv_sys->mutex));
 
 				if (buf_page_peek(space, page_no)) {
@@ -1928,16 +1933,6 @@ loop:
 
 			recv_addr = HASH_GET_NEXT(addr_hash, recv_addr);
 		}
-
-		if (has_printed
-		    && (i * 100) / hash_get_n_cells(recv_sys->addr_hash)
-		    != ((i + 1) * 100)
-		    / hash_get_n_cells(recv_sys->addr_hash)) {
-
-			fprintf(stderr, "%lu ", (ulong)
-				((i * 100)
-				 / hash_get_n_cells(recv_sys->addr_hash)));
-		}
 	}
 
 	/* Wait until all the pages have been processed */
@@ -1951,11 +1946,6 @@ loop:
 		mutex_enter(&(recv_sys->mutex));
 	}
 
-	if (has_printed) {
-
-		fprintf(stderr, "\n");
-	}
-
 	if (!allow_ibuf) {
 		/* Flush all the file pages to disk and invalidate them in
 		the buffer pool */
@@ -1983,14 +1973,6 @@ loop:
 
 	recv_sys_empty_hash();
 
-	if (has_printed) {
-		fprintf(stderr, "InnoDB: Apply batch completed\n");
-
-		if (srv_recovery_stats) {
-			recv_sys->stats_recv_turns++;
-		}
-	}
-
 	mutex_exit(&(recv_sys->mutex));
 }
 #else /* !UNIV_HOTBACKUP */
@@ -2014,10 +1996,6 @@ recv_apply_log_recs_for_backup(void)
 
 	block = back_block1;
 
-	fputs("InnoDB: Starting an apply batch of log records"
-	      " to the database...\n"
-	      "InnoDB: Progress in percents: ", stderr);
-
 	n_hash_cells = hash_get_n_cells(recv_sys->addr_hash);
 
 	for (i = 0; i < n_hash_cells; i++) {
@@ -2808,10 +2786,10 @@ recv_scan_log_recs(
 #ifndef UNIV_HOTBACKUP
 			if (recv_log_scan_is_startup_type
 			    && !recv_needed_recovery) {
-
+				ut_print_timestamp(stderr);
 				fprintf(stderr,
-					"InnoDB: Log scan progressed"
-					" past the checkpoint lsn %llu\n",
+					"  InnoDB: Starting crash recovery"
+					" from checkpoint LSN=%llu\n",
 					recv_sys->scanned_lsn);
 				recv_init_crash_recovery();
 			}
@@ -2862,19 +2840,6 @@ recv_scan_log_recs(
 
 	*group_scanned_lsn = scanned_lsn;
 
-	if (recv_needed_recovery
-	    || (recv_is_from_backup && !recv_is_making_a_backup)) {
-		recv_scan_print_counter++;
-
-		if (finished || (recv_scan_print_counter % 80 == 0)) {
-
-			fprintf(stderr,
-				"InnoDB: Doing recovery: scanned up to"
-				" log sequence number %llu\n",
-				*group_scanned_lsn);
-		}
-	}
-
 	if (more_data && !recv_sys->found_corrupt_log) {
 		/* Try to parse more log records */
 
@@ -2965,17 +2930,6 @@ recv_init_crash_recovery(void)
 
 	recv_needed_recovery = TRUE;
 
-	ut_print_timestamp(stderr);
-
-	fprintf(stderr,
-		"  InnoDB: Database was not"
-		" shut down normally!\n"
-		"InnoDB: Starting crash recovery.\n");
-
-	fprintf(stderr,
-		"InnoDB: Reading tablespace information"
-		" from the .ibd files...\n");
-
 	fil_load_single_table_tablespaces();
 
 	/* If we are using the doublewrite method, we will
@@ -2988,8 +2942,7 @@ recv_init_crash_recovery(void)
 		fprintf(stderr,
 			"InnoDB: Restoring possible"
 			" half-written data pages from"
-			" the doublewrite\n"
-			"InnoDB: buffer...\n");
+			" the doublewrite buffer...\n");
 		trx_sys_doublewrite_init_or_restore_pages(TRUE);
 	}
 }