Skip to content

M
MariaDB
Commit 07aa9859 authored by Jan Lindström's avatar Jan Lindström
Browse files
Options

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.
parent 18ccbf01
Show whitespace changes
Inline Side-by-side
Showing with 109 additions and 140 deletions
mysql-test/suite/innodb/r/innodb-lru-force-no-free-page.result 0 → 100644
View file @ 07aa9859
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
mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.test 0 → 100644
View file @ 07aa9859
--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
storage/innobase/buf/buf0lru.cc
View file @ 07aa9859
/***************************************************************************** /*****************************************************************************
Copyright (c) 1995, 2016, Oracle and/or its affiliates. All Rights Reserved. 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 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 the terms of the GNU General Public License as published by the Free Software
...@@ -90,6 +90,10 @@ during LRU eviction. */ ...@@ -90,6 +90,10 @@ during LRU eviction. */
frames in the buffer pool, we set this to TRUE */ frames in the buffer pool, we set this to TRUE */
static ibool buf_lru_switched_on_innodb_mon = FALSE; 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 These statistics are not 'of' LRU but 'for' LRU. We keep count of I/O
and page_zip_decompress() operations. Based on the statistics, and page_zip_decompress() operations. Based on the statistics,
...@@ -1045,8 +1049,6 @@ buf_LRU_get_free_block( ...@@ -1045,8 +1049,6 @@ buf_LRU_get_free_block(
ibool freed = FALSE; ibool freed = FALSE;
ulint n_iterations = 0; ulint n_iterations = 0;
ulint flush_failures = 0; ulint flush_failures = 0;
ibool mon_value_was = FALSE;
ibool started_monitor = FALSE;
MONITOR_INC(MONITOR_LRU_GET_FREE_SEARCH); MONITOR_INC(MONITOR_LRU_GET_FREE_SEARCH);
loop: loop:
...@@ -1054,6 +1056,11 @@ buf_LRU_get_free_block( ...@@ -1054,6 +1056,11 @@ buf_LRU_get_free_block(
buf_LRU_check_size_of_non_data_objects(buf_pool); 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 */ /* If there is a block in the free list, take it */
block = buf_LRU_get_free_only(buf_pool); block = buf_LRU_get_free_only(buf_pool);
...@@ -1062,16 +1069,11 @@ buf_LRU_get_free_block( ...@@ -1062,16 +1069,11 @@ buf_LRU_get_free_block(
buf_pool_mutex_exit(buf_pool); buf_pool_mutex_exit(buf_pool);
ut_ad(buf_pool_from_block(block) == buf_pool); ut_ad(buf_pool_from_block(block) == buf_pool);
memset(&block->page.zip, 0, sizeof block->page.zip); 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); return(block);
} }
freed = FALSE; freed = FALSE;
if (buf_pool->try_LRU_scan || n_iterations > 0) { if (buf_pool->try_LRU_scan || n_iterations > 0) {
/* If no block was in the free list, search from the /* If no block was in the free list, search from the
end of the LRU list and try to free a block there. end of the LRU list and try to free a block there.
...@@ -1094,6 +1096,10 @@ buf_LRU_get_free_block( ...@@ -1094,6 +1096,10 @@ buf_LRU_get_free_block(
} }
} }
#ifndef DBUG_OFF
not_found:
#endif
buf_pool_mutex_exit(buf_pool); buf_pool_mutex_exit(buf_pool);
if (freed) { if (freed) {
...@@ -1101,40 +1107,26 @@ buf_LRU_get_free_block( ...@@ -1101,40 +1107,26 @@ buf_LRU_get_free_block(
} }
if (n_iterations > 20) { if (n_iterations > 20 && !buf_lru_free_blocks_error_printed) {
ut_print_timestamp(stderr); ib_logf(IB_LOG_LEVEL_WARN,
fprintf(stderr, "Difficult to find free blocks in"
" InnoDB: Warning: difficult to find free blocks in\n" " the buffer pool (" ULINTPF " search iterations)! "
"InnoDB: the buffer pool (%lu search iterations)!\n" ULINTPF " failed attempts to flush a page!",
"InnoDB: %lu failed attempts to flush a page!" n_iterations, flush_failures);
" Consider\n" ib_logf(IB_LOG_LEVEL_INFO,
"InnoDB: increasing the buffer pool size.\n" "Consider increasing the buffer pool size.");
"InnoDB: It is also possible that" ib_logf(IB_LOG_LEVEL_INFO,
" in your Unix version\n" "Pending flushes (fsync) log: " ULINTPF
"InnoDB: fsync is very slow, or" " buffer pool: " ULINTPF
" completely frozen inside\n" " OS file reads: " ULINTPF " OS file writes: "
"InnoDB: the OS kernel. Then upgrading to" ULINTPF " OS fsyncs: " ULINTPF "",
" a newer version\n" fil_n_pending_log_flushes,
"InnoDB: of your operating system may help." fil_n_pending_tablespace_flushes,
" Look at the\n" os_n_file_reads,
"InnoDB: number of fsyncs in diagnostic info below.\n" os_n_file_writes,
"InnoDB: Pending flushes (fsync) log: %lu;" os_n_fsyncs);
" buffer pool: %lu\n"
"InnoDB: %lu OS file reads, %lu OS file writes," buf_lru_free_blocks_error_printed = true;
" %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 we have scanned the whole LRU and still are unable to /* If we have scanned the whole LRU and still are unable to
......
storage/xtradb/buf/buf0lru.cc
View file @ 07aa9859
/***************************************************************************** /*****************************************************************************
Copyright (c) 1995, 2016, Oracle and/or its affiliates. All Rights Reserved. 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 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 the terms of the GNU General Public License as published by the Free Software
...@@ -87,6 +87,10 @@ buffer pools. */ ...@@ -87,6 +87,10 @@ buffer pools. */
frames in the buffer pool, we set this to TRUE */ frames in the buffer pool, we set this to TRUE */
static ibool buf_lru_switched_on_innodb_mon = FALSE; 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 These statistics are not 'of' LRU but 'for' LRU. We keep count of I/O
and page_zip_decompress() operations. Based on the statistics, and page_zip_decompress() operations. Based on the statistics,
...@@ -1080,68 +1084,39 @@ buf_LRU_check_size_of_non_data_objects( ...@@ -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 /** 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 @param[in] n_iterations how many buf_LRU_get_free_page iterations
already completed 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, @param[in] flush_failures how many times single-page flush, if allowed,
has failed 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 static
void void
buf_LRU_handle_lack_of_free_blocks(ulint n_iterations, ulint started_ms, buf_LRU_handle_lack_of_free_blocks(
ulint flush_failures, ulint n_iterations,
ibool *mon_value_was, ulint flush_failures)
ibool *started_monitor)
{ {
static ulint last_printout_ms = 0; if (n_iterations > 20 && !buf_lru_free_blocks_error_printed) {
ib_logf(IB_LOG_LEVEL_WARN,
/* Legacy algorithm started warning after at least 2 seconds, we "Difficult to find free blocks in"
emulate this. */ " the buffer pool (" ULINTPF " search iterations)! "
const ulint current_ms = ut_time_ms(); ULINTPF " failed attempts to flush a page!",
n_iterations, flush_failures);
if ((current_ms > started_ms + 2000) ib_logf(IB_LOG_LEVEL_INFO,
&& (current_ms > last_printout_ms + 2000)) { "Consider increasing the buffer pool size.");
ib_logf(IB_LOG_LEVEL_INFO,
ut_print_timestamp(stderr); "Pending flushes (fsync) log: " ULINTPF
fprintf(stderr, " buffer pool: " ULINTPF
" InnoDB: Warning: difficult to find free blocks in\n" " OS file reads: " ULINTPF " OS file writes: "
"InnoDB: the buffer pool (%lu search iterations)!\n" ULINTPF " OS fsyncs: " ULINTPF "",
"InnoDB: %lu failed attempts to flush a page!" fil_n_pending_log_flushes,
" Consider\n" fil_n_pending_tablespace_flushes,
"InnoDB: increasing the buffer pool size.\n" os_n_file_reads,
"InnoDB: It is also possible that" os_n_file_writes,
" in your Unix version\n" os_n_fsyncs);
"InnoDB: fsync is very slow, or"
" completely frozen inside\n" buf_lru_free_blocks_error_printed = true;
"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);
} }
} }
/** The maximum allowed backoff sleep time duration, microseconds */ /** The maximum allowed backoff sleep time duration, microseconds */
...@@ -1189,9 +1164,6 @@ buf_LRU_get_free_block( ...@@ -1189,9 +1164,6 @@ buf_LRU_get_free_block(
ibool freed = FALSE; ibool freed = FALSE;
ulint n_iterations = 0; ulint n_iterations = 0;
ulint flush_failures = 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)); ut_ad(!mutex_own(&buf_pool->LRU_list_mutex));
...@@ -1199,42 +1171,20 @@ buf_LRU_get_free_block( ...@@ -1199,42 +1171,20 @@ buf_LRU_get_free_block(
loop: loop:
buf_LRU_check_size_of_non_data_objects(buf_pool); buf_LRU_check_size_of_non_data_objects(buf_pool);
/* If there is a block in the free list, take it */ DBUG_EXECUTE_IF("ib_lru_force_no_free_page",
if (DBUG_EVALUATE_IF("simulate_lack_of_pages", true, false)) { if (!buf_lru_free_blocks_error_printed) {
n_iterations = 21;
block = NULL; goto not_found;});
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 {
block = buf_LRU_get_free_only(buf_pool); block = buf_LRU_get_free_only(buf_pool);
}
if (block) { if (block) {
ut_ad(buf_pool_from_block(block) == buf_pool); ut_ad(buf_pool_from_block(block) == buf_pool);
memset(&block->page.zip, 0, sizeof block->page.zip); 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); return(block);
} }
if (!started_ms)
started_ms = ut_time_ms();
if (srv_empty_free_list_algorithm == SRV_EMPTY_FREE_LIST_BACKOFF if (srv_empty_free_list_algorithm == SRV_EMPTY_FREE_LIST_BACKOFF
&& buf_lru_manager_is_active && buf_lru_manager_is_active
&& (srv_shutdown_state == SRV_SHUTDOWN_NONE && (srv_shutdown_state == SRV_SHUTDOWN_NONE
...@@ -1272,10 +1222,7 @@ buf_LRU_get_free_block( ...@@ -1272,10 +1222,7 @@ buf_LRU_get_free_block(
: FREE_LIST_BACKOFF_LOW_PRIO_DIVIDER)); : FREE_LIST_BACKOFF_LOW_PRIO_DIVIDER));
} }
buf_LRU_handle_lack_of_free_blocks(n_iterations, started_ms, buf_LRU_handle_lack_of_free_blocks(n_iterations, flush_failures);
flush_failures,
&mon_value_was,
&started_monitor);
n_iterations++; n_iterations++;
...@@ -1314,13 +1261,8 @@ buf_LRU_get_free_block( ...@@ -1314,13 +1261,8 @@ buf_LRU_get_free_block(
mutex_exit(&buf_pool->flush_state_mutex); 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; freed = FALSE;
if (buf_pool->try_LRU_scan || n_iterations > 0) { if (buf_pool->try_LRU_scan || n_iterations > 0) {
/* If no block was in the free list, search from the /* If no block was in the free list, search from the
...@@ -1345,9 +1287,11 @@ buf_LRU_get_free_block( ...@@ -1345,9 +1287,11 @@ buf_LRU_get_free_block(
} }
buf_LRU_handle_lack_of_free_blocks(n_iterations, started_ms, #ifndef DBUG_OFF
flush_failures, &mon_value_was, not_found:
&started_monitor); #endif
buf_LRU_handle_lack_of_free_blocks(n_iterations, flush_failures);
/* If we have scanned the whole LRU and still are unable to /* If we have scanned the whole LRU and still are unable to
find a free block then we should sleep here to let the find a free block then we should sleep here to let the
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7