Skip to content

Commit

Permalink
MDEV-14776: InnoDB Monitor output generated by specific error is floo…
Browse files Browse the repository at this point in the history 
…ding 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.
  • Loading branch information
Jan Lindström committed Jan 9, 2018
1 parent 18ccbf0 commit 07aa985
Show file tree
Hide file tree
Showing 4 changed files with 109 additions and 140 deletions.
9 changes: 9 additions & 0 deletions mysql-test/suite/innodb/r/innodb-lru-force-no-free-page.result
View file
Original file line number Diff line number Diff line change
@@ -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
24 changes: 24 additions & 0 deletions mysql-test/suite/innodb/t/innodb-lru-force-no-free-page.test
View file
Original file line number Diff line number Diff line change
@@ -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

78 changes: 35 additions & 43 deletions storage/innobase/buf/buf0lru.cc
View file
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -1045,15 +1049,18 @@ 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:
buf_pool_mutex_enter(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 */
block = buf_LRU_get_free_only(buf_pool);

Expand All @@ -1062,16 +1069,11 @@ buf_LRU_get_free_block(
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.
Expand All @@ -1094,47 +1096,37 @@ buf_LRU_get_free_block(
}
}

#ifndef DBUG_OFF
not_found:
#endif

buf_pool_mutex_exit(buf_pool);

if (freed) {
goto 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
Expand Down
138 changes: 41 additions & 97 deletions storage/xtradb/buf/buf0lru.cc
View file
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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 */
Expand Down Expand Up @@ -1189,52 +1164,27 @@ 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));

MONITOR_INC(MONITOR_LRU_GET_FREE_SEARCH);
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
Expand Down Expand Up @@ -1272,10 +1222,7 @@ buf_LRU_get_free_block(
: 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++;

Expand Down Expand Up @@ -1314,13 +1261,8 @@ buf_LRU_get_free_block(

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
Expand All @@ -1345,9 +1287,11 @@ buf_LRU_get_free_block(

}

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
Expand Down

0 comments on commit 07aa985

Please sign in to comment.