[Commits] 1fc09ca52b1: MDEV-11027 InnoDB log recovery is too noisy

marko.makela at mariadb.com marko.makela at mariadb.com
Tue Mar 7 19:00:14 EET 2017


revision-id: 1fc09ca52b1798435bdc282b9707d0870b870af5 (mariadb-10.1.21-52-g1fc09ca52b1)
parent(s): aeff61ee5857f2351030c604f62dc7628543209a
author: Marko Mäkelä
committer: Marko Mäkelä
timestamp: 2017-03-07 18:59:37 +0200
message:

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_sys_t::report(ib_time_t): Determine whether progress should
be reported.

recv_scan_print_counter: Remove.

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

recv_apply_hashed_log_recs(): Change the return type back to void
(DB_SUCCESS was always returned), and rename the parameter to last_batch.
At the start of each batch, if there are pages to be recovered,
issue a message.

---
 mysql-test/suite/innodb/r/log_file_size.result |  12 +-
 mysql-test/suite/innodb/t/log_file_size.test   |  16 +-
 storage/innobase/include/log0recv.h            |  36 +++--
 storage/innobase/log/log0log.cc                |  15 +-
 storage/innobase/log/log0recv.cc               | 195 +++++++------------------
 storage/innobase/srv/srv0start.cc              |   8 +-
 storage/xtradb/include/log0recv.h              |  36 +++--
 storage/xtradb/log/log0log.cc                  |  15 +-
 storage/xtradb/log/log0recv.cc                 | 193 +++++++-----------------
 storage/xtradb/srv/srv0start.cc                |   8 +-
 10 files changed, 195 insertions(+), 339 deletions(-)

diff --git a/mysql-test/suite/innodb/r/log_file_size.result b/mysql-test/suite/innodb/r/log_file_size.result
index d0b389379e7..67794f293aa 100644
--- a/mysql-test/suite/innodb/r/log_file_size.result
+++ b/mysql-test/suite/innodb/r/log_file_size.result
@@ -20,28 +20,24 @@ ERROR 42000: Unknown storage engine 'InnoDB'
 FOUND /syntax error in innodb_log_group_home_dir/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND /InnoDB: Starting an apply batch of log records/ in mysqld.1.err
+FOUND /InnoDB: Starting crash recovery from checkpoint LSN=/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND /InnoDB: Starting an apply batch of log records/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
 FOUND /InnoDB: innodb_read_only prevents crash recovery/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND /InnoDB: Starting an apply batch of log records/ in mysqld.1.err
-FOUND /InnoDB: Resizing redo log from 3\*[0-9]+ to 2\*[0-9]+ pages/ in mysqld.1.err
+FOUND /redo log from 3\*[0-9]+ to 2\*[0-9]+ pages/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND /InnoDB: Starting an apply batch of log records/ in mysqld.1.err
-FOUND /InnoDB: Resizing redo log from 3\*[0-9]+ to 2\*[0-9]+ pages/ in mysqld.1.err
+FOUND /redo log from 3\*[0-9]+ to 2\*[0-9]+ pages/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
 FOUND /InnoDB: innodb_read_only prevents crash recovery/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND /InnoDB: Starting an apply batch of log records/ in mysqld.1.err
-FOUND /InnoDB: Resizing redo log from 3\*[0-9]+ to 2\*[0-9]+ pages/ in mysqld.1.err
+FOUND /redo log from 3\*[0-9]+ to 2\*[0-9]+ pages/ in mysqld.1.err
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
 SELECT * FROM t1;
diff --git a/mysql-test/suite/innodb/t/log_file_size.test b/mysql-test/suite/innodb/t/log_file_size.test
index ae63ee6e133..bf307123734 100644
--- a/mysql-test/suite/innodb/t/log_file_size.test
+++ b/mysql-test/suite/innodb/t/log_file_size.test
@@ -76,15 +76,13 @@ let SEARCH_PATTERN= syntax error in innodb_log_group_home_dir;
 --source include/restart_mysqld.inc
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
-let SEARCH_PATTERN= InnoDB: Starting an apply batch of log records;
+let SEARCH_PATTERN= InnoDB: Starting crash recovery from checkpoint LSN=;
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --debug=d,innodb_log_abort_3
 --source include/restart_mysqld.inc
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
-let SEARCH_PATTERN= InnoDB: Starting an apply batch of log records;
---source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --innodb-read-only
 --source include/restart_mysqld.inc
@@ -98,18 +96,14 @@ let SEARCH_PATTERN= InnoDB: innodb_read_only prevents crash recovery;
 --source include/restart_mysqld.inc
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
-let SEARCH_PATTERN= InnoDB: Starting an apply batch of log records;
---source include/search_pattern_in_file.inc
-let SEARCH_PATTERN= InnoDB: Resizing redo log from 3\*[0-9]+ to 2\*[0-9]+ pages;
+let SEARCH_PATTERN= redo log from 3\*[0-9]+ to 2\*[0-9]+ pages;
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --debug=d,innodb_log_abort_5
 --source include/restart_mysqld.inc
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
-let SEARCH_PATTERN= InnoDB: Starting an apply batch of log records;
---source include/search_pattern_in_file.inc
-let SEARCH_PATTERN= InnoDB: Resizing redo log from 3\*[0-9]+ to 2\*[0-9]+ pages;
+let SEARCH_PATTERN= redo log from 3\*[0-9]+ to 2\*[0-9]+ pages;
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --innodb-read-only
@@ -124,9 +118,7 @@ let SEARCH_PATTERN= InnoDB: innodb_read_only prevents crash recovery;
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
 
-let SEARCH_PATTERN= InnoDB: Starting an apply batch of log records;
---source include/search_pattern_in_file.inc
-let SEARCH_PATTERN= InnoDB: Resizing redo log from 3\*[0-9]+ to 2\*[0-9]+ pages;
+let SEARCH_PATTERN= redo log from 3\*[0-9]+ to 2\*[0-9]+ pages;
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --debug=d,innodb_log_abort_7
diff --git a/storage/innobase/include/log0recv.h b/storage/innobase/include/log0recv.h
index b6c977bdc74..4459dda3120 100644
--- a/storage/innobase/include/log0recv.h
+++ b/storage/innobase/include/log0recv.h
@@ -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
@@ -271,20 +272,11 @@ void
 recv_sys_var_init(void);
 /*===================*/
 #endif /* !UNIV_HOTBACKUP */
-/*******************************************************************//**
-Empties the hash table of stored log records, applying them to appropriate
-pages. */
-UNIV_INTERN
-dberr_t
-recv_apply_hashed_log_recs(
-/*=======================*/
-	ibool	allow_ibuf);	/*!< in: if TRUE, also ibuf operations are
-				allowed during the application; if FALSE,
-				no ibuf operations are allowed, and after
-				the application all file pages are flushed to
-				disk and invalidated in buffer pool: this
-				alternative means that no new log records
-				can be generated during the application */
+/** Empty the hash table of stored log records, applying them to the pages.
+ at param[in]	last_batch	whether the change buffer merge will be
+				performed as part of the operation */
+void
+recv_apply_hashed_log_recs(bool last_batch);
 #ifdef UNIV_HOTBACKUP
 /*******************************************************************//**
 Applies log records in the hash table to a backup. */
@@ -434,6 +426,8 @@ struct recv_sys_t{
 				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
@@ -446,6 +440,20 @@ struct recv_sys_t{
 				addresses in the hash table */
 
 	recv_dblwr_t	dblwr;
+
+	/** Determine whether redo log recovery progress should be reported.
+	@param[in]	time	the current time
+	@return	whether progress should be reported
+		(the last report was at least 15 seconds ago) */
+	bool report(ib_time_t time)
+	{
+		if (time - progress_time < 15) {
+			return false;
+		}
+
+		progress_time = time;
+		return true;
+	}
 };
 
 /** The recovery system */
diff --git a/storage/innobase/log/log0log.cc b/storage/innobase/log/log0log.cc
index 624ee0bb35d..82549e96bc5 100644
--- a/storage/innobase/log/log0log.cc
+++ b/storage/innobase/log/log0log.cc
@@ -38,6 +38,10 @@ Created 12/9/1995 Heikki Tuuri
 #endif
 
 #ifndef UNIV_HOTBACKUP
+#if MYSQL_VERSION_ID < 100200
+# include <my_systemd.h> /* sd_notifyf() */
+#endif
+
 #include "mem0mem.h"
 #include "buf0buf.h"
 #include "buf0flu.h"
@@ -1756,7 +1760,7 @@ log_preflush_pool_modified_pages(
 		and we could not make a new checkpoint on the basis of the
 		info on the buffer pool only. */
 
-		recv_apply_hashed_log_recs(TRUE);
+		recv_apply_hashed_log_recs(true);
 	}
 
 	success = buf_flush_list(ULINT_MAX, new_oldest, &n_pages);
@@ -2099,7 +2103,7 @@ log_checkpoint(
 	ut_ad(!srv_read_only_mode);
 
 	if (recv_recovery_is_on()) {
-		recv_apply_hashed_log_recs(TRUE);
+		recv_apply_hashed_log_recs(true);
 	}
 
 	if (srv_unix_file_flush_method != SRV_UNIX_NOSYNC) {
@@ -2374,6 +2378,13 @@ log_group_read_log_seg(
 	start_lsn += len;
 	buf += len;
 
+	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);
+	}
+
 	if (start_lsn != end_lsn) {
 
 		goto loop;
diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc
index 104b5b6b421..b3731ec8152 100644
--- a/storage/innobase/log/log0recv.cc
+++ b/storage/innobase/log/log0recv.cc
@@ -78,7 +78,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. */
@@ -134,9 +134,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;
@@ -311,8 +308,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;
@@ -426,6 +421,7 @@ recv_sys_init(
 		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;
 
@@ -435,33 +431,18 @@ recv_sys_init(
 	mutex_exit(&(recv_sys->mutex));
 }
 
-/********************************************************//**
-Empties the hash table when it has been fully processed.
- at return DB_SUCCESS when successfull or DB_ERROR when fails. */
+/** Empty a fully processed hash table. */
 static
-dberr_t
-recv_sys_empty_hash(void)
-/*=====================*/
+void
+recv_sys_empty_hash()
 {
 	ut_ad(mutex_own(&(recv_sys->mutex)));
-
-	if (recv_sys->n_addrs != 0) {
-		fprintf(stderr,
-			"InnoDB: Error: %lu pages with log records"
-			" were left unprocessed!\n"
-			"InnoDB: Maximum page number with"
-			" log records on it %lu\n",
-			(ulong) recv_sys->n_addrs,
-			(ulong) recv_max_parsed_page_no);
-		return DB_ERROR;
-	}
+	ut_a(recv_sys->n_addrs == 0);
 
 	hash_table_free(recv_sys->addr_hash);
 	mem_heap_empty(recv_sys->heap);
 
 	recv_sys->addr_hash = hash_create(buf_pool_get_curr_size() / 512);
-
-	return DB_SUCCESS;
 }
 
 #ifndef UNIV_HOTBACKUP
@@ -1716,6 +1697,8 @@ recv_recover_page_func(
 
 	mtr_commit(&mtr);
 
+	ib_time_t time = ut_time();
+
 	mutex_enter(&(recv_sys->mutex));
 
 	if (recv_max_page_lsn < page_lsn) {
@@ -1724,11 +1707,17 @@ 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 (ulint n = --recv_sys->n_addrs) {
+		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);
+		}
+	}
 
+	mutex_exit(&recv_sys->mutex);
 }
 
 #ifndef UNIV_HOTBACKUP
@@ -1774,62 +1763,49 @@ 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);
 }
 
-/*******************************************************************//**
-Empties the hash table of stored log records, applying them to appropriate
-pages.
- at return DB_SUCCESS when successfull or DB_ERROR when fails. */
-UNIV_INTERN
-dberr_t
-recv_apply_hashed_log_recs(
-/*=======================*/
-	ibool	allow_ibuf)	/*!< in: if TRUE, also ibuf operations are
-				allowed during the application; if FALSE,
-				no ibuf operations are allowed, and after
-				the application all file pages are flushed to
-				disk and invalidated in buffer pool: this
-				alternative means that no new log records
-				can be generated during the application;
-				the caller must in this case own the log
-				mutex */
+/** Empty the hash table of stored log records, applying them to the pages.
+ at param[in]	last_batch	whether the change buffer merge will be
+				performed as part of the operation */
+void
+recv_apply_hashed_log_recs(bool last_batch)
 {
-	recv_addr_t* recv_addr;
-	ulint	i;
-	ibool	has_printed	= FALSE;
-	ulong progress;
-	mtr_t	mtr;
-	dberr_t err = DB_SUCCESS;
-loop:
-	mutex_enter(&(recv_sys->mutex));
-
-	if (recv_sys->apply_batch_on) {
+	for (;;) {
+		mutex_enter(&recv_sys->mutex);
 
-		mutex_exit(&(recv_sys->mutex));
+		if (!recv_sys->apply_batch_on) {
+			break;
+		}
 
+		mutex_exit(&recv_sys->mutex);
 		os_thread_sleep(500000);
-
-		goto loop;
 	}
 
-	ut_ad((!allow_ibuf) == mutex_own(&log_sys->mutex));
+	ut_ad(!last_batch == mutex_own(&log_sys->mutex));
 
-	if (!allow_ibuf) {
+	if (!last_batch) {
 		recv_no_ibuf_operations = TRUE;
 	}
 
+	if (ulint n = recv_sys->n_addrs) {
+		const char* msg = last_batch
+			? "Starting final batch to recover "
+			: "Starting a batch to recover ";
+		ib_logf(IB_LOG_LEVEL_INFO,
+			"%s" ULINTPF " pages from redo log", msg, n);
+		sd_notifyf(0, "STATUS=%s" ULINTPF " pages from redo log",
+			   msg, n);
+	}
 	recv_sys->apply_log_recs = TRUE;
 	recv_sys->apply_batch_on = TRUE;
 
-	for (i = 0; i < hash_get_n_cells(recv_sys->addr_hash); i++) {
+	for (ulint i = 0; i < hash_get_n_cells(recv_sys->addr_hash); i++) {
 
-		for (recv_addr = static_cast<recv_addr_t*>(
+		for (recv_addr_t* recv_addr = static_cast<recv_addr_t*>(
 				HASH_GET_FIRST(recv_sys->addr_hash, i));
-		     recv_addr != 0;
+		     recv_addr;
 		     recv_addr = static_cast<recv_addr_t*>(
 				HASH_GET_NEXT(addr_hash, recv_addr))) {
 
@@ -1838,24 +1814,12 @@ recv_apply_hashed_log_recs(
 			ulint	page_no = recv_addr->page_no;
 
 			if (recv_addr->state == RECV_NOT_PROCESSED) {
-				if (!has_printed) {
-					ib_logf(IB_LOG_LEVEL_INFO,
-						"Starting an apply batch"
-						" of log records"
-						" to the database...");
-					fputs("InnoDB: Progress in percent: ",
-					      stderr);
-					has_printed = TRUE;
-				}
-
-				mutex_exit(&(recv_sys->mutex));
+				mutex_exit(&recv_sys->mutex);
 
 				if (buf_page_peek(space, page_no)) {
-					buf_block_t*	block;
-
+					mtr_t		mtr;
 					mtr_start(&mtr);
-
-					block = buf_page_get(
+					buf_block_t*	block = buf_page_get(
 						space, zip_size, page_no,
 						RW_X_LATCH, &mtr);
 					buf_block_dbg_add_level(
@@ -1868,21 +1832,9 @@ recv_apply_hashed_log_recs(
 							  page_no);
 				}
 
-				mutex_enter(&(recv_sys->mutex));
+				mutex_enter(&recv_sys->mutex);
 			}
 		}
-
-		progress = (ulong) (i * 100)
-                                   / hash_get_n_cells(recv_sys->addr_hash);
-		if (has_printed
-		    && progress
-		    != ((i + 1) * 100)
-		    / hash_get_n_cells(recv_sys->addr_hash)) {
-
-			fprintf(stderr, "%lu ", progress);
-			sd_notifyf(0, "STATUS=Applying batch of log records for"
-				   " InnoDB: Progress %lu", progress);
-		}
 	}
 
 	/* Wait until all the pages have been processed */
@@ -1896,12 +1848,7 @@ recv_apply_hashed_log_recs(
 		mutex_enter(&(recv_sys->mutex));
 	}
 
-	if (has_printed) {
-
-		fprintf(stderr, "\n");
-	}
-
-	if (!allow_ibuf) {
+	if (!last_batch) {
 		bool	success;
 
 		/* Flush all the file pages to disk and invalidate them in
@@ -1939,16 +1886,9 @@ recv_apply_hashed_log_recs(
 	recv_sys->apply_log_recs = FALSE;
 	recv_sys->apply_batch_on = FALSE;
 
-	err = recv_sys_empty_hash();
-
-	if (has_printed) {
-		fprintf(stderr, "InnoDB: Apply batch completed\n");
-		sd_notify(0, "STATUS=InnoDB: Apply batch completed");
-	}
-
-	mutex_exit(&(recv_sys->mutex));
+	recv_sys_empty_hash();
 
-	return err;
+	mutex_exit(&recv_sys->mutex);
 }
 #else /* !UNIV_HOTBACKUP */
 /*******************************************************************//**
@@ -2800,8 +2740,8 @@ recv_scan_log_recs(
 
 				if (!srv_read_only_mode) {
 					ib_logf(IB_LOG_LEVEL_INFO,
-						"Log scan progressed past the "
-						"checkpoint lsn " LSN_PF "",
+						"Starting crash recovery from "
+						"checkpoint LSN=" LSN_PF,
 						recv_sys->scanned_lsn);
 
 					recv_init_crash_recovery();
@@ -2861,19 +2801,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 " LSN_PF "\n",
-				*group_scanned_lsn);
-		}
-	}
-
 	if (more_data && !recv_sys->found_corrupt_log) {
 		/* Try to parse more log records */
 
@@ -2893,12 +2820,7 @@ recv_scan_log_recs(
 			log yet: they would be produced by ibuf
 			operations */
 
-			*err = recv_apply_hashed_log_recs(FALSE);
-
-			if (*err != DB_SUCCESS) {
-				/* Finish processing because of error */
-				return (TRUE);
-			}
+			recv_apply_hashed_log_recs(false);
 		}
 #endif /* !UNIV_HOTBACKUP */
 
@@ -2982,11 +2904,6 @@ recv_init_crash_recovery(void)
 
 	recv_needed_recovery = TRUE;
 
-	ib_logf(IB_LOG_LEVEL_INFO, "Database was not shutdown normally!");
-	ib_logf(IB_LOG_LEVEL_INFO, "Starting crash recovery.");
-	ib_logf(IB_LOG_LEVEL_INFO,
-		"Reading tablespace information from the .ibd files...");
-
 	fil_load_single_table_tablespaces();
 
 	/* If we are using the doublewrite method, we will
@@ -2997,9 +2914,7 @@ recv_init_crash_recovery(void)
 	if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
 
 		ib_logf(IB_LOG_LEVEL_INFO,
-			"Restoring possible half-written data pages ");
-
-		ib_logf(IB_LOG_LEVEL_INFO,
+			"Restoring possible half-written data pages "
 			"from the doublewrite buffer...");
 
 		buf_dblwr_process();
@@ -3984,7 +3899,7 @@ recv_recovery_from_archive_start(
 
 	if (limit_lsn != LSN_MAX) {
 
-		recv_apply_hashed_log_recs(FALSE);
+		recv_apply_hashed_log_recs(false);
 
 		recv_reset_logs(0, FALSE, recv_sys->recovered_lsn);
 	}
diff --git a/storage/innobase/srv/srv0start.cc b/storage/innobase/srv/srv0start.cc
index 79cd3aebdd0..e44530bb8ed 100644
--- a/storage/innobase/srv/srv0start.cc
+++ b/storage/innobase/srv/srv0start.cc
@@ -2483,7 +2483,7 @@ innobase_start_or_create_for_mysql(void)
 			return(err);
 		}
 
-		/* This must precede recv_apply_hashed_log_recs(TRUE). */
+		/* This must precede recv_apply_hashed_log_recs(true). */
 		ib_bh = trx_sys_init_at_db_start();
 
 		if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
@@ -2491,11 +2491,11 @@ innobase_start_or_create_for_mysql(void)
 			respective file pages, for the last batch of
 			recv_group_scan_log_recs(). */
 
-			err = recv_apply_hashed_log_recs(TRUE);
+			recv_apply_hashed_log_recs(true);
 			DBUG_PRINT("ib_log", ("apply completed"));
 
-			if (err != DB_SUCCESS) {
-				return(err);
+			if (recv_needed_recovery) {
+				trx_sys_print_mysql_binlog_offset();
 			}
 		}
 
diff --git a/storage/xtradb/include/log0recv.h b/storage/xtradb/include/log0recv.h
index e93ec2666af..9494b6f5645 100644
--- a/storage/xtradb/include/log0recv.h
+++ b/storage/xtradb/include/log0recv.h
@@ -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
@@ -300,20 +301,11 @@ void
 recv_sys_var_init(void);
 /*===================*/
 #endif /* !UNIV_HOTBACKUP */
-/*******************************************************************//**
-Empties the hash table of stored log records, applying them to appropriate
-pages. */
-UNIV_INTERN
-dberr_t
-recv_apply_hashed_log_recs(
-/*=======================*/
-	ibool	allow_ibuf);	/*!< in: if TRUE, also ibuf operations are
-				allowed during the application; if FALSE,
-				no ibuf operations are allowed, and after
-				the application all file pages are flushed to
-				disk and invalidated in buffer pool: this
-				alternative means that no new log records
-				can be generated during the application */
+/** Empty the hash table of stored log records, applying them to the pages.
+ at param[in]	last_batch	whether the change buffer merge will be
+				performed as part of the operation */
+void
+recv_apply_hashed_log_recs(bool last_batch);
 #ifdef UNIV_HOTBACKUP
 /*******************************************************************//**
 Applies log records in the hash table to a backup. */
@@ -439,6 +431,8 @@ struct recv_sys_t{
 				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
@@ -451,6 +445,20 @@ struct recv_sys_t{
 				addresses in the hash table */
 
 	recv_dblwr_t	dblwr;
+
+	/** Determine whether redo log recovery progress should be reported.
+	@param[in]	time	the current time
+	@return	whether progress should be reported
+		(the last report was at least 15 seconds ago) */
+	bool report(ib_time_t time)
+	{
+		if (time - progress_time < 15) {
+			return false;
+		}
+
+		progress_time = time;
+		return true;
+	}
 };
 
 /** The recovery system */
diff --git a/storage/xtradb/log/log0log.cc b/storage/xtradb/log/log0log.cc
index e0259ef80a6..b1f0886db96 100644
--- a/storage/xtradb/log/log0log.cc
+++ b/storage/xtradb/log/log0log.cc
@@ -48,6 +48,10 @@ Created 12/9/1995 Heikki Tuuri
 #endif
 
 #ifndef UNIV_HOTBACKUP
+#if MYSQL_VERSION_ID < 100200
+# include <my_systemd.h> /* sd_notifyf() */
+#endif
+
 #include "mem0mem.h"
 #include "buf0buf.h"
 #include "buf0flu.h"
@@ -1876,7 +1880,7 @@ log_preflush_pool_modified_pages(
 		and we could not make a new checkpoint on the basis of the
 		info on the buffer pool only. */
 
-		recv_apply_hashed_log_recs(TRUE);
+		recv_apply_hashed_log_recs(true);
 	}
 
 	if (!buf_page_cleaner_is_active
@@ -2251,7 +2255,7 @@ log_checkpoint(
 	ut_ad(!srv_read_only_mode);
 
 	if (recv_recovery_is_on()) {
-		recv_apply_hashed_log_recs(TRUE);
+		recv_apply_hashed_log_recs(true);
 	}
 
 	if (srv_unix_file_flush_method != SRV_UNIX_NOSYNC &&
@@ -2625,6 +2629,13 @@ log_group_read_log_seg(
 	start_lsn += len;
 	buf += len;
 
+	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);
+	}
+
 	if (start_lsn != end_lsn) {
 
 		if (release_mutex) {
diff --git a/storage/xtradb/log/log0recv.cc b/storage/xtradb/log/log0recv.cc
index 6405a87a2bd..d429efbf432 100644
--- a/storage/xtradb/log/log0recv.cc
+++ b/storage/xtradb/log/log0recv.cc
@@ -85,7 +85,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. */
@@ -137,9 +137,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;
@@ -310,8 +307,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;
@@ -422,6 +417,7 @@ recv_sys_init(
 		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;
 
@@ -431,33 +427,18 @@ recv_sys_init(
 	mutex_exit(&(recv_sys->mutex));
 }
 
-/********************************************************//**
-Empties the hash table when it has been fully processed.
- at return DB_SUCCESS when successfull or DB_ERROR when fails. */
+/** Empty a fully processed hash table. */
 static
-dberr_t
-recv_sys_empty_hash(void)
-/*=====================*/
+void
+recv_sys_empty_hash()
 {
 	ut_ad(mutex_own(&(recv_sys->mutex)));
-
-	if (recv_sys->n_addrs != 0) {
-		fprintf(stderr,
-			"InnoDB: Error: %lu pages with log records"
-			" were left unprocessed!\n"
-			"InnoDB: Maximum page number with"
-			" log records on it %lu\n",
-			(ulong) recv_sys->n_addrs,
-			(ulong) recv_max_parsed_page_no);
-		return DB_ERROR;
-	}
+	ut_a(recv_sys->n_addrs == 0);
 
 	hash_table_free(recv_sys->addr_hash);
 	mem_heap_empty(recv_sys->heap);
 
 	recv_sys->addr_hash = hash_create(buf_pool_get_curr_size() / 512);
-
-	return DB_SUCCESS;
 }
 
 #ifndef UNIV_HOTBACKUP
@@ -1804,6 +1785,8 @@ recv_recover_page_func(
 
 	mtr_commit(&mtr);
 
+	ib_time_t time = ut_time();
+
 	mutex_enter(&(recv_sys->mutex));
 
 	if (recv_max_page_lsn < page_lsn) {
@@ -1812,11 +1795,17 @@ 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 (ulint n = --recv_sys->n_addrs) {
+		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);
+		}
+	}
 
+	mutex_exit(&recv_sys->mutex);
 }
 
 #ifndef UNIV_HOTBACKUP
@@ -1862,62 +1851,49 @@ 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);
 }
 
-/*******************************************************************//**
-Empties the hash table of stored log records, applying them to appropriate
-pages.
- at return DB_SUCCESS when successfull or DB_ERROR when fails. */
-UNIV_INTERN
-dberr_t
-recv_apply_hashed_log_recs(
-/*=======================*/
-	ibool	allow_ibuf)	/*!< in: if TRUE, also ibuf operations are
-				allowed during the application; if FALSE,
-				no ibuf operations are allowed, and after
-				the application all file pages are flushed to
-				disk and invalidated in buffer pool: this
-				alternative means that no new log records
-				can be generated during the application;
-				the caller must in this case own the log
-				mutex */
+/** Empty the hash table of stored log records, applying them to the pages.
+ at param[in]	last_batch	whether the change buffer merge will be
+				performed as part of the operation */
+void
+recv_apply_hashed_log_recs(bool last_batch)
 {
-	recv_addr_t* recv_addr;
-	ulint	i;
-	ibool	has_printed	= FALSE;
-	ulong progress;
-	mtr_t	mtr;
-	dberr_t err = DB_SUCCESS;
-loop:
-	mutex_enter(&(recv_sys->mutex));
-
-	if (recv_sys->apply_batch_on) {
+	for (;;) {
+		mutex_enter(&recv_sys->mutex);
 
-		mutex_exit(&(recv_sys->mutex));
+		if (!recv_sys->apply_batch_on) {
+			break;
+		}
 
+		mutex_exit(&recv_sys->mutex);
 		os_thread_sleep(500000);
-
-		goto loop;
 	}
 
-	ut_ad((allow_ibuf == 0) == (mutex_own(&log_sys->mutex) != 0));
+	ut_ad(!last_batch == mutex_own(&log_sys->mutex));
 
-	if (!allow_ibuf) {
+	if (!last_batch) {
 		recv_no_ibuf_operations = TRUE;
 	}
 
+	if (ulint n = recv_sys->n_addrs) {
+		const char* msg = last_batch
+			? "Starting final batch to recover "
+			: "Starting a batch to recover ";
+		ib_logf(IB_LOG_LEVEL_INFO,
+			"%s" ULINTPF " pages from redo log", msg, n);
+		sd_notifyf(0, "STATUS=%s" ULINTPF " pages from redo log",
+			   msg, n);
+	}
 	recv_sys->apply_log_recs = TRUE;
 	recv_sys->apply_batch_on = TRUE;
 
-	for (i = 0; i < hash_get_n_cells(recv_sys->addr_hash); i++) {
+	for (ulint i = 0; i < hash_get_n_cells(recv_sys->addr_hash); i++) {
 
-		for (recv_addr = static_cast<recv_addr_t*>(
+		for (recv_addr_t* recv_addr = static_cast<recv_addr_t*>(
 				HASH_GET_FIRST(recv_sys->addr_hash, i));
-		     recv_addr != 0;
+		     recv_addr;
 		     recv_addr = static_cast<recv_addr_t*>(
 				HASH_GET_NEXT(addr_hash, recv_addr))) {
 
@@ -1926,24 +1902,12 @@ recv_apply_hashed_log_recs(
 			ulint	page_no = recv_addr->page_no;
 
 			if (recv_addr->state == RECV_NOT_PROCESSED) {
-				if (!has_printed) {
-					ib_logf(IB_LOG_LEVEL_INFO,
-						"Starting an apply batch"
-						" of log records"
-						" to the database...");
-					fputs("InnoDB: Progress in percent: ",
-					      stderr);
-					has_printed = TRUE;
-				}
-
-				mutex_exit(&(recv_sys->mutex));
+				mutex_exit(&recv_sys->mutex);
 
 				if (buf_page_peek(space, page_no)) {
-					buf_block_t*	block;
-
+					mtr_t		mtr;
 					mtr_start(&mtr);
-
-					block = buf_page_get(
+					buf_block_t*	block = buf_page_get(
 						space, zip_size, page_no,
 						RW_X_LATCH, &mtr);
 					buf_block_dbg_add_level(
@@ -1956,21 +1920,9 @@ recv_apply_hashed_log_recs(
 							  page_no);
 				}
 
-				mutex_enter(&(recv_sys->mutex));
+				mutex_enter(&recv_sys->mutex);
 			}
 		}
-
-                progress = (ulong) (i * 100)
-                                   / hash_get_n_cells(recv_sys->addr_hash);
-		if (has_printed
-		    && progress
-		    != ((i + 1) * 100)
-		    / hash_get_n_cells(recv_sys->addr_hash)) {
-
-                        fprintf(stderr, "%lu ", progress);
-                        sd_notifyf(0, "STATUS=Applying batch of log records for"
-                                   " InnoDB: Progress %lu", progress);
-		}
 	}
 
 	/* Wait until all the pages have been processed */
@@ -1984,12 +1936,7 @@ recv_apply_hashed_log_recs(
 		mutex_enter(&(recv_sys->mutex));
 	}
 
-	if (has_printed) {
-
-		fprintf(stderr, "\n");
-	}
-
-	if (!allow_ibuf) {
+	if (!last_batch) {
 		bool	success;
 
 		/* Flush all the file pages to disk and invalidate them in
@@ -2027,16 +1974,9 @@ recv_apply_hashed_log_recs(
 	recv_sys->apply_log_recs = FALSE;
 	recv_sys->apply_batch_on = FALSE;
 
-	err = recv_sys_empty_hash();
-
-	if (has_printed) {
-		fprintf(stderr, "InnoDB: Apply batch completed\n");
-		sd_notify(0, "STATUS=InnoDB: Apply batch completed");
-	}
-
-	mutex_exit(&(recv_sys->mutex));
+	recv_sys_empty_hash();
 
-	return err;
+	mutex_exit(&recv_sys->mutex);
 }
 #else /* !UNIV_HOTBACKUP */
 /*******************************************************************//**
@@ -2892,8 +2832,8 @@ recv_scan_log_recs(
 
 				if (!srv_read_only_mode) {
 					ib_logf(IB_LOG_LEVEL_INFO,
-						"Log scan progressed past the "
-						"checkpoint lsn " LSN_PF "",
+						"Starting crash recovery from "
+						"checkpoint LSN=" LSN_PF,
 						recv_sys->scanned_lsn);
 
 					recv_init_crash_recovery();
@@ -2953,19 +2893,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 " LSN_PF "\n",
-				*group_scanned_lsn);
-		}
-	}
-
 	if (more_data && !recv_sys->found_corrupt_log) {
 		/* Try to parse more log records */
 
@@ -2985,12 +2912,7 @@ recv_scan_log_recs(
 			log yet: they would be produced by ibuf
 			operations */
 
-			*err = recv_apply_hashed_log_recs(FALSE);
-
-			if (*err != DB_SUCCESS) {
-				/* Finish processing because of error */
-				return (TRUE);
-			}
+			recv_apply_hashed_log_recs(false);
 		}
 #endif /* !UNIV_HOTBACKUP */
 
@@ -3074,11 +2996,6 @@ recv_init_crash_recovery(void)
 
 	recv_needed_recovery = TRUE;
 
-	ib_logf(IB_LOG_LEVEL_INFO, "Database was not shutdown normally!");
-	ib_logf(IB_LOG_LEVEL_INFO, "Starting crash recovery.");
-	ib_logf(IB_LOG_LEVEL_INFO,
-		"Reading tablespace information from the .ibd files...");
-
 	fil_load_single_table_tablespaces();
 
 	/* If we are using the doublewrite method, we will
@@ -3089,9 +3006,7 @@ recv_init_crash_recovery(void)
 	if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
 
 		ib_logf(IB_LOG_LEVEL_INFO,
-			"Restoring possible half-written data pages ");
-
-		ib_logf(IB_LOG_LEVEL_INFO,
+			"Restoring possible half-written data pages "
 			"from the doublewrite buffer...");
 
 		buf_dblwr_process();
diff --git a/storage/xtradb/srv/srv0start.cc b/storage/xtradb/srv/srv0start.cc
index 679913959c9..46cfda076c9 100644
--- a/storage/xtradb/srv/srv0start.cc
+++ b/storage/xtradb/srv/srv0start.cc
@@ -2533,7 +2533,7 @@ innobase_start_or_create_for_mysql(void)
 			return(err);
 		}
 
-		/* This must precede recv_apply_hashed_log_recs(TRUE). */
+		/* This must precede recv_apply_hashed_log_recs(true). */
 		ib_bh = trx_sys_init_at_db_start();
 
 		if (srv_force_recovery < SRV_FORCE_NO_LOG_REDO) {
@@ -2541,11 +2541,11 @@ innobase_start_or_create_for_mysql(void)
 			respective file pages, for the last batch of
 			recv_group_scan_log_recs(). */
 
-			err = recv_apply_hashed_log_recs(TRUE);
+			recv_apply_hashed_log_recs(true);
 			DBUG_PRINT("ib_log", ("apply completed"));
 
-			if (err != DB_SUCCESS) {
-				return(err);
+			if (recv_needed_recovery) {
+				trx_sys_print_mysql_binlog_offset();
 			}
 		}
 


More information about the commits mailing list