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

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.

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. 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.

4 files changed, 109 insertions, 140 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..d095f4e32e7
--- /dev/null
+++ b/mysql-test/suite/innodb/r/innodb-lru-force-no-free-page.result
@@ -0,0 +1,9 @@
+call mtr.add_suppression("\\[Warning\\] InnoDB: Difficult to find free blocks in the buffer pool.");
+SET SESSION debug_dbug="+d,ib_lru_force_no_free_page";
+CREATE TABLE t1 (j LONGBLOB) ENGINE = InnoDB;
+BEGIN;
+INSERT INTO t1 VALUES (repeat('abcdefghijklmnopqrstuvwxyz',200));
+COMMIT;
+SET SESSION debug_dbug="";
+DROP TABLE t1;
+FOUND /InnoDB: Difficult to find free blocks / in mysqld.1.err
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..e358446eca9
--- /dev/null
+++ b/mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.test
@@ -0,0 +1,24 @@
+--source include/have_innodb.inc
+--source include/have_debug.inc
+
+call mtr.add_suppression("\\[Warning\\] InnoDB: Difficult to find free blocks in the buffer pool.");
+
+SET SESSION debug_dbug="+d,ib_lru_force_no_free_page";
+
+CREATE TABLE t1 (j LONGBLOB) ENGINE = InnoDB;
+BEGIN;
+INSERT INTO t1 VALUES (repeat('abcdefghijklmnopqrstuvwxyz',200));
+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
+
diff --git a/storage/innobase/buf/buf0lru.cc b/storage/innobase/buf/buf0lru.cc
index a047b28f4fd..b1b63e72a45 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,10 @@ 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;
+
 /******************************************************************//**
 These statistics are not 'of' LRU but 'for' LRU.  We keep count of I/O
 and page_zip_decompress() operations.  Based on the statistics,
@@ -1045,8 +1049,6 @@ buf_LRU_get_free_block(
 	ibool		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 +1056,11 @@ loop:
 
 	buf_LRU_check_size_of_non_data_objects(buf_pool);
 
+	DBUG_EXECUTE_IF("ib_lru_force_no_free_page",
+		if (!buf_lru_free_blocks_error_printed) {
+			n_iterations = 21;
+			goto not_found;});
+
 	/* If there is a block in the free list, take it */
 	block = buf_LRU_get_free_only(buf_pool);
 
@@ -1062,16 +1069,11 @@ 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);
 	}
 
 	freed = FALSE;
+
 	if (buf_pool->try_LRU_scan || n_iterations > 0) {
 		/* If no block was in the free list, search from the
 		end of the LRU list and try to free a block there.
@@ -1094,6 +1096,10 @@ loop:
 		}
 	}
 
+#ifndef DBUG_OFF
+not_found:
+#endif
+
 	buf_pool_mutex_exit(buf_pool);
 
 	if (freed) {
@@ -1101,40 +1107,26 @@ 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,
+			"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);
+
+		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..a84f2a832f3 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,10 @@ 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;
+
 /******************************************************************//**
 These statistics are not 'of' LRU but 'for' LRU.  We keep count of I/O
 and page_zip_decompress() operations.  Based on the statistics,
@@ -1080,68 +1084,39 @@ buf_LRU_check_size_of_non_data_objects(
 }
 
 /** Diagnose failure to get a free page and request InnoDB monitor output in
-the error log if more than two seconds have been spent already.
+the error log if it has not yet printed.
 @param[in]	n_iterations	how many buf_LRU_get_free_page iterations
                                 already completed
-@param[in]	started_ms	timestamp in ms of when the attempt to get the
-                                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 flush_failures)
 {
-	static ulint last_printout_ms = 0;
-
-	/* Legacy algorithm started warning after at least 2 seconds, we
-	emulate	this. */
-	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);
+	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,
+			"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);
+
+		buf_lru_free_blocks_error_printed = true;
 	}
-
 }
 
 /** The maximum allowed backoff sleep time duration, microseconds */
@@ -1189,9 +1164,6 @@ buf_LRU_get_free_block(
 	ibool		freed		= FALSE;
 	ulint		n_iterations	= 0;
 	ulint		flush_failures	= 0;
-	ibool		mon_value_was	= FALSE;
-	ibool		started_monitor	= FALSE;
-	ulint		started_ms	= 0;
 
 	ut_ad(!mutex_own(&buf_pool->LRU_list_mutex));
 
@@ -1199,42 +1171,20 @@ 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;
-
-		if (srv_debug_monitor_printed)
-			DBUG_SUICIDE();
-	} else {
+	DBUG_EXECUTE_IF("ib_lru_force_no_free_page",
+		if (!buf_lru_free_blocks_error_printed) {
+			n_iterations = 21;
+			goto not_found;});
 
-		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);
 	}
 
-	if (!started_ms)
-		started_ms = ut_time_ms();
-
 	if (srv_empty_free_list_algorithm == SRV_EMPTY_FREE_LIST_BACKOFF
 	    && buf_lru_manager_is_active
 	    && (srv_shutdown_state == SRV_SHUTDOWN_NONE
@@ -1272,10 +1222,7 @@ loop:
 				: FREE_LIST_BACKOFF_LOW_PRIO_DIVIDER));
 		}
 
-		buf_LRU_handle_lack_of_free_blocks(n_iterations, started_ms,
-						   flush_failures,
-						   &mon_value_was,
-						   &started_monitor);
+		buf_LRU_handle_lack_of_free_blocks(n_iterations, flush_failures);
 
 		n_iterations++;
 
@@ -1314,13 +1261,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 +1287,11 @@ loop:
 
 	}
 
-	buf_LRU_handle_lack_of_free_blocks(n_iterations, started_ms,
-					   flush_failures, &mon_value_was,
-					   &started_monitor);
+#ifndef DBUG_OFF
+not_found:
+#endif
+
+	buf_LRU_handle_lack_of_free_blocks(n_iterations, 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