MDEV-14776: InnoDB Monitor output generated by specific error is flooding error logsbb-10.1-MDEV-14776

innodb/buf_LRU_get_free_block
	Add debug instrumentation to produce error message about
	no free pages. Print error message only once and do not
	enable innodb monitor if it is not enabled.

xtradb/buf_LRU_get_free_block
	Add debug instrumentation to produce error message about
	no free pages. Print error message only once and do not
	enable innodb monitor if it is not enabled. Remove code
	that does not seem to be used.

innodb-lru-force-no-free-page.test
	New test case to force produce desired error message.

5 files changed, 159 insertions, 126 deletions

diff --git a/mysql-test/suite/innodb/r/innodb-lru-force-no-free-page.result b/mysql-test/suite/innodb/r/innodb-lru-force-no-free-page.result
new file mode 100644
index 00000000000..2bbb681a8ef
--- /dev/null
+++ b/mysql-test/suite/innodb/r/innodb-lru-force-no-free-page.result
@@ -0,0 +1,17 @@
+call mtr.add_suppression("\\[Warning\\] InnoDB: Difficult to find free blocks in the buffer pool.*");
+SET GLOBAL innodb_compression_level=0;
+SELECT @@innodb_compression_level;
+@@innodb_compression_level
+0
+SET SESSION debug_dbug="+d,ib_lru_force_no_free_page";
+CREATE TABLE t1 (j LONGBLOB) ENGINE = InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=1;
+BEGIN;
+INSERT INTO t1 VALUES (repeat('abcdefghijklmnopqrstuvwxyz',200));
+INSERT INTO t1 SELECT * from t1;
+INSERT INTO t1 SELECT * from t1;
+INSERT INTO t1 SELECT * from t1;
+COMMIT;
+SET SESSION debug_dbug="";
+DROP TABLE t1;
+FOUND /InnoDB: Difficult to find free blocks / in mysqld.1.err
+set GLOBAL innodb_compression_level=6;
diff --git a/mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.opt b/mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.opt
new file mode 100644
index 00000000000..78a5174dbbc
--- /dev/null
+++ b/mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.opt
@@ -0,0 +1,5 @@
+--skip-innodb-doublewrite
+--innodb-file-per-table
+--innodb-file-format=Barracuda
+--innodb-change-buffering=none
+--innodb_buffer_pool_size=8M
diff --git a/mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.test b/mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.test
new file mode 100644
index 00000000000..cc59c8060f4
--- /dev/null
+++ b/mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.test
@@ -0,0 +1,40 @@
+--source include/have_innodb.inc
+--source include/have_debug.inc
+--source include/no_valgrind_without_big.inc
+--source include/not_embedded.inc
+--source include/big_test.inc
+# The test case currently uses grep, which may be unavailable on
+# some windows systems. But see MWL#191 for how to remove the need for grep.
+--source include/not_windows.inc
+
+call mtr.add_suppression("\\[Warning\\] InnoDB: Difficult to find free blocks in the buffer pool.*");
+
+let $comp = `SELECT @@innodb_compression_level`;
+SET GLOBAL innodb_compression_level=0;
+SELECT @@innodb_compression_level;
+
+SET SESSION debug_dbug="+d,ib_lru_force_no_free_page";
+
+CREATE TABLE t1 (j LONGBLOB) ENGINE = InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=1;
+BEGIN;
+INSERT INTO t1 VALUES (repeat('abcdefghijklmnopqrstuvwxyz',200));
+let $i=3;
+while ($i > 0) {
+  INSERT INTO t1 SELECT * from t1;
+  dec $i;
+}
+COMMIT;
+
+SET SESSION debug_dbug="";
+
+DROP TABLE t1;
+
+#
+# There should be only one message
+#
+let SEARCH_RANGE= -50000;
+let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err;
+--let SEARCH_PATTERN=InnoDB: Difficult to find free blocks 
+--source include/search_pattern_in_file.inc
+
+eval set GLOBAL innodb_compression_level=$comp;
diff --git a/storage/innobase/buf/buf0lru.cc b/storage/innobase/buf/buf0lru.cc
index a047b28f4fd..308d8e462c9 100644
--- a/storage/innobase/buf/buf0lru.cc
+++ b/storage/innobase/buf/buf0lru.cc
@@ -1,7 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1995, 2016, Oracle and/or its affiliates. All Rights Reserved.
-Copyright (c) 2017, MariaDB Corporation.
+Copyright (c) 2017, 2018, 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
@@ -90,6 +90,11 @@ during LRU eviction. */
 frames in the buffer pool, we set this to TRUE */
 static ibool	buf_lru_switched_on_innodb_mon	= FALSE;
 
+/** True if diagnostic message about difficult to find free blocks
+in the buffer bool has already printed. */
+static bool	buf_lru_free_blocks_error_printed = false;
+
+
 /******************************************************************//**
 These statistics are not 'of' LRU but 'for' LRU.  We keep count of I/O
 and page_zip_decompress() operations.  Based on the statistics,
@@ -1042,11 +1047,9 @@ buf_LRU_get_free_block(
 	buf_pool_t*	buf_pool)	/*!< in/out: buffer pool instance */
 {
 	buf_block_t*	block		= NULL;
-	ibool		freed		= FALSE;
+	bool		freed		= false;
 	ulint		n_iterations	= 0;
 	ulint		flush_failures	= 0;
-	ibool		mon_value_was	= FALSE;
-	ibool		started_monitor	= FALSE;
 
 	MONITOR_INC(MONITOR_LRU_GET_FREE_SEARCH);
 loop:
@@ -1054,6 +1057,9 @@ loop:
 
 	buf_LRU_check_size_of_non_data_objects(buf_pool);
 
+	DBUG_EXECUTE_IF("ib_lru_force_no_free_page",
+		if (n_iterations < 22) { goto not_found;});
+
 	/* If there is a block in the free list, take it */
 	block = buf_LRU_get_free_only(buf_pool);
 
@@ -1062,12 +1068,6 @@ loop:
 		buf_pool_mutex_exit(buf_pool);
 		ut_ad(buf_pool_from_block(block) == buf_pool);
 		memset(&block->page.zip, 0, sizeof block->page.zip);
-
-		if (started_monitor) {
-			srv_print_innodb_monitor =
-				static_cast<my_bool>(mon_value_was);
-		}
-
 		return(block);
 	}
 
@@ -1094,6 +1094,8 @@ loop:
 		}
 	}
 
+not_found:
+
 	buf_pool_mutex_exit(buf_pool);
 
 	if (freed) {
@@ -1101,40 +1103,41 @@ loop:
 
 	}
 
-	if (n_iterations > 20) {
-		ut_print_timestamp(stderr);
-		fprintf(stderr,
-			"  InnoDB: Warning: difficult to find free blocks in\n"
-			"InnoDB: the buffer pool (%lu search iterations)!\n"
-			"InnoDB: %lu failed attempts to flush a page!"
-			" Consider\n"
-			"InnoDB: increasing the buffer pool size.\n"
-			"InnoDB: It is also possible that"
-			" in your Unix version\n"
-			"InnoDB: fsync is very slow, or"
-			" completely frozen inside\n"
-			"InnoDB: the OS kernel. Then upgrading to"
-			" a newer version\n"
-			"InnoDB: of your operating system may help."
-			" Look at the\n"
-			"InnoDB: number of fsyncs in diagnostic info below.\n"
-			"InnoDB: Pending flushes (fsync) log: %lu;"
-			" buffer pool: %lu\n"
-			"InnoDB: %lu OS file reads, %lu OS file writes,"
-			" %lu OS fsyncs\n"
-			"InnoDB: Starting InnoDB Monitor to print further\n"
-			"InnoDB: diagnostics to the standard output.\n",
-			(ulong) n_iterations,
-			(ulong)	flush_failures,
-			(ulong) fil_n_pending_log_flushes,
-			(ulong) fil_n_pending_tablespace_flushes,
-			(ulong) os_n_file_reads, (ulong) os_n_file_writes,
-			(ulong) os_n_fsyncs);
-
-		mon_value_was = srv_print_innodb_monitor;
-		started_monitor = TRUE;
-		srv_print_innodb_monitor = TRUE;
-		os_event_set(srv_monitor_event);
+	if (n_iterations > 20 && !buf_lru_free_blocks_error_printed) {
+		ib_logf(IB_LOG_LEVEL_WARN,
+			"Difficult to find free blocks in"
+			" the buffer pool (" ULINTPF " search iterations)! "
+			ULINTPF " failed attempts to flush a page!",
+			n_iterations, flush_failures);
+		ib_logf(IB_LOG_LEVEL_INFO,
+			" Consider increasing the buffer pool size.");
+		ib_logf(IB_LOG_LEVEL_INFO,
+			"It is also possible that in your Unix version"
+			" fsync is very slow, or"
+			" completely frozen inside"
+			" the OS kernel. Then upgrading to"
+			" a newer version"
+			" of your operating system may help.");
+		ib_logf(IB_LOG_LEVEL_INFO,
+			" Pending flushes (fsync) log: " ULINTPF
+			" buffer pool: " ULINTPF
+			" OS file reads: " ULINTPF " OS file writes: "
+			ULINTPF " OS fsyncs: " ULINTPF "",
+			fil_n_pending_log_flushes,
+			fil_n_pending_tablespace_flushes,
+			os_n_file_reads,
+			os_n_file_writes,
+			os_n_fsyncs);
+
+		if (srv_print_innodb_monitor) {
+			ib_logf(IB_LOG_LEVEL_INFO,
+				"Starting InnoDB Monitor to print further"
+				" diagnostics to the standard output.");
+
+			os_event_set(srv_monitor_event);
+		}
+
+		buf_lru_free_blocks_error_printed = true;
 	}
 
 	/* If we have scanned the whole LRU and still are unable to
diff --git a/storage/xtradb/buf/buf0lru.cc b/storage/xtradb/buf/buf0lru.cc
index c71d45009e4..90ea5599ce8 100644
--- a/storage/xtradb/buf/buf0lru.cc
+++ b/storage/xtradb/buf/buf0lru.cc
@@ -1,7 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1995, 2016, Oracle and/or its affiliates. All Rights Reserved.
-Copyright (c) 2017, MariaDB Corporation.
+Copyright (c) 2017, 2018, 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
@@ -87,6 +87,11 @@ buffer pools. */
 frames in the buffer pool, we set this to TRUE */
 static ibool	buf_lru_switched_on_innodb_mon	= FALSE;
 
+/** True if diagnostic message about difficult to find free blocks
+in the buffer bool has already printed. */
+static bool	buf_lru_free_blocks_error_printed = false;
+
+
 /******************************************************************//**
 These statistics are not 'of' LRU but 'for' LRU.  We keep count of I/O
 and page_zip_decompress() operations.  Based on the statistics,
@@ -1087,15 +1092,13 @@ the error log if more than two seconds have been spent already.
                                 free page started
 @param[in]	flush_failures	how many times single-page flush, if allowed,
                                 has failed
-@param[out]	mon_value_was	previous srv_print_innodb_monitor value
-@param[out]	started_monitor	whether InnoDB monitor print has been requested
 */
 static
 void
-buf_LRU_handle_lack_of_free_blocks(ulint n_iterations, ulint started_ms,
-				   ulint flush_failures,
-				   ibool *mon_value_was,
-				   ibool *started_monitor)
+buf_LRU_handle_lack_of_free_blocks(
+	ulint n_iterations,
+	ulint started_ms,
+	ulint flush_failures)
 {
 	static ulint last_printout_ms = 0;
 
@@ -1104,42 +1107,37 @@ buf_LRU_handle_lack_of_free_blocks(ulint n_iterations, ulint started_ms,
 	const ulint current_ms = ut_time_ms();
 
 	if ((current_ms > started_ms + 2000)
-	    && (current_ms > last_printout_ms + 2000)) {
-
-		ut_print_timestamp(stderr);
-		fprintf(stderr,
-			"  InnoDB: Warning: difficult to find free blocks in\n"
-			"InnoDB: the buffer pool (%lu search iterations)!\n"
-			"InnoDB: %lu failed attempts to flush a page!"
-			" Consider\n"
-			"InnoDB: increasing the buffer pool size.\n"
-			"InnoDB: It is also possible that"
-			" in your Unix version\n"
-			"InnoDB: fsync is very slow, or"
-			" completely frozen inside\n"
-			"InnoDB: the OS kernel. Then upgrading to"
-			" a newer version\n"
-			"InnoDB: of your operating system may help."
-			" Look at the\n"
-			"InnoDB: number of fsyncs in diagnostic info below.\n"
-			"InnoDB: Pending flushes (fsync) log: %lu;"
-			" buffer pool: %lu\n"
-			"InnoDB: %lu OS file reads, %lu OS file writes,"
-			" %lu OS fsyncs\n"
-			"InnoDB: Starting InnoDB Monitor to print further\n"
-			"InnoDB: diagnostics to the standard output.\n",
-			(ulong) n_iterations,
-			(ulong)	flush_failures,
-			(ulong) fil_n_pending_log_flushes,
-			(ulong) fil_n_pending_tablespace_flushes,
-			(ulong) os_n_file_reads, (ulong) os_n_file_writes,
-			(ulong) os_n_fsyncs);
-
-		last_printout_ms = current_ms;
-		*mon_value_was = srv_print_innodb_monitor;
-		*started_monitor = TRUE;
-		srv_print_innodb_monitor = TRUE;
-		os_event_set(lock_sys->timeout_event);
+	    && (current_ms > last_printout_ms + 2000)
+	    && !buf_lru_free_blocks_error_printed) {
+
+		ib_logf(IB_LOG_LEVEL_WARN,
+			"Difficult to find free blocks in"
+			" the buffer pool (" ULINTPF " search iterations)! "
+			ULINTPF " failed attempts to flush a page!",
+			n_iterations, flush_failures);
+		ib_logf(IB_LOG_LEVEL_INFO,
+			" Consider increasing the buffer pool size.");
+		ib_logf(IB_LOG_LEVEL_INFO,
+			"It is also possible that in your Unix version"
+			" fsync is very slow, or"
+			" completely frozen inside"
+			" the OS kernel. Then upgrading to"
+			" a newer version"
+			" of your operating system may help.");
+		ib_logf(IB_LOG_LEVEL_INFO,
+			" Pending flushes (fsync) log: " ULINTPF
+			" buffer pool: " ULINTPF
+			" OS file reads: " ULINTPF " OS file writes: "
+			ULINTPF " OS fsyncs: " ULINTPF "",
+			fil_n_pending_log_flushes,
+			fil_n_pending_tablespace_flushes,
+			os_n_file_reads,
+			os_n_file_writes,
+			os_n_fsyncs);
+
+		if (srv_print_innodb_monitor) {
+			os_event_set(lock_sys->timeout_event);
+		}
 	}
 
 }
@@ -1186,12 +1184,10 @@ buf_LRU_get_free_block(
 	buf_pool_t*	buf_pool)	/*!< in/out: buffer pool instance */
 {
 	buf_block_t*	block		= NULL;
-	ibool		freed		= FALSE;
+	bool		freed		= FALSE;
 	ulint		n_iterations	= 0;
 	ulint		flush_failures	= 0;
-	ibool		mon_value_was	= FALSE;
-	ibool		started_monitor	= FALSE;
-	ulint		started_ms	= 0;
+	ulint           started_ms      = 0;
 
 	ut_ad(!mutex_own(&buf_pool->LRU_list_mutex));
 
@@ -1199,36 +1195,15 @@ buf_LRU_get_free_block(
 loop:
 	buf_LRU_check_size_of_non_data_objects(buf_pool);
 
-	/* If there is a block in the free list, take it */
-	if (DBUG_EVALUATE_IF("simulate_lack_of_pages", true, false)) {
-
-		block = NULL;
-
-		if (srv_debug_monitor_printed)
-			DBUG_SET("-d,simulate_lack_of_pages");
-
-	} else if (DBUG_EVALUATE_IF("simulate_recovery_lack_of_pages",
-				    recv_recovery_on, false)) {
-
-		block = NULL;
+	DBUG_EXECUTE_IF("ib_lru_force_no_free_page",
+		if (n_iterations < 22) { goto not_found;});
 
-		if (srv_debug_monitor_printed)
-			DBUG_SUICIDE();
-	} else {
-
-		block = buf_LRU_get_free_only(buf_pool);
-	}
+	block = buf_LRU_get_free_only(buf_pool);
 
 	if (block) {
 
 		ut_ad(buf_pool_from_block(block) == buf_pool);
 		memset(&block->page.zip, 0, sizeof block->page.zip);
-
-		if (started_monitor) {
-			srv_print_innodb_monitor =
-				static_cast<my_bool>(mon_value_was);
-		}
-
 		return(block);
 	}
 
@@ -1273,9 +1248,7 @@ loop:
 		}
 
 		buf_LRU_handle_lack_of_free_blocks(n_iterations, started_ms,
-						   flush_failures,
-						   &mon_value_was,
-						   &started_monitor);
+						   flush_failures);
 
 		n_iterations++;
 
@@ -1314,13 +1287,8 @@ loop:
 
 	mutex_exit(&buf_pool->flush_state_mutex);
 
-	if (DBUG_EVALUATE_IF("simulate_recovery_lack_of_pages", true, false)
-	    || DBUG_EVALUATE_IF("simulate_lack_of_pages", true, false)) {
-
-		buf_pool->try_LRU_scan = false;
-	}
-
 	freed = FALSE;
+
 	if (buf_pool->try_LRU_scan || n_iterations > 0) {
 
 		/* If no block was in the free list, search from the
@@ -1345,9 +1313,9 @@ loop:
 
 	}
 
+ not_found:
 	buf_LRU_handle_lack_of_free_blocks(n_iterations, started_ms,
-					   flush_failures, &mon_value_was,
-					   &started_monitor);
+					   flush_failures);
 
 	/* If we have scanned the whole LRU and still are unable to
 	find a free block then we should sleep here to let the