From d1ab89037a518fcffbc50c24e4bd94e4ec33aed0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marko=20M=C3=A4kel=C3=A4?= Date: Tue, 5 Dec 2017 12:50:35 +0200 Subject: [PATCH] MDEV-13670/MDEV-14550 Error log flood : "InnoDB: page_cleaner: 1000ms intended loop took N ms. The settings might not be optimal." Silence the error log output that was introduced in MySQL 5.7 (MariaDB 10.2.2) if log_warnings=2 or less. We should still figure out what these messages really indicate and how to solve the problems. pc_sleep_if_needed(): Add a parameter for the current time, so that there will be fewer successive calls to ut_time_ms() with no I/O between them. buf_flush_page_cleaner_coordinator(): Exit the first loop whenever shutdown has been requested. At the start of the loop, call ut_time_ms() only once. Do not display the message if log_warnings=2 or less. --- storage/innobase/buf/buf0flu.cc | 27 ++++++++++++++------------- 1 file changed, 14 insertions(+), 13 deletions(-) diff --git a/storage/innobase/buf/buf0flu.cc b/storage/innobase/buf/buf0flu.cc index b497e4f84e8..9426d140e71 100644 --- a/storage/innobase/buf/buf0flu.cc +++ b/storage/innobase/buf/buf0flu.cc @@ -28,6 +28,7 @@ Created 11/11/1995 Heikki Tuuri #include "ha_prototypes.h" #include #include +#include #include "buf0flu.h" #include "buf0buf.h" @@ -2690,21 +2691,21 @@ than a second @retval OS_SYNC_TIME_EXCEEDED if timeout was exceeded @param next_loop_time time when next loop iteration should start @param sig_count zero or the value returned by previous call of - os_event_reset() */ + os_event_reset() +@param cur_time current time as in ut_time_ms() */ static ulint pc_sleep_if_needed( /*===============*/ ulint next_loop_time, - int64_t sig_count) + int64_t sig_count, + ulint cur_time) { /* No sleep if we are cleaning the buffer pool during the shutdown with everything else finished */ if (srv_shutdown_state == SRV_SHUTDOWN_FLUSH_PHASE) return OS_SYNC_TIME_EXCEEDED; - ulint cur_time = ut_time_ms(); - if (next_loop_time > cur_time) { /* Get sleep interval in micro seconds. We use ut_min() to avoid long sleep in case of wrap around. */ @@ -3200,6 +3201,7 @@ DECLARE_THREAD(buf_flush_page_cleaner_coordinator)(void*) ulint last_pages = 0; while (srv_shutdown_state == SRV_SHUTDOWN_NONE) { + ulint curr_time = ut_time_ms(); /* The page_cleaner skips sleep if the server is idle and there are no pending IOs in the buffer pool @@ -3209,23 +3211,22 @@ DECLARE_THREAD(buf_flush_page_cleaner_coordinator)(void*) || n_flushed == 0) { ret_sleep = pc_sleep_if_needed( - next_loop_time, sig_count); - - if (srv_shutdown_state != SRV_SHUTDOWN_NONE) { - break; - } - } else if (ut_time_ms() > next_loop_time) { + next_loop_time, sig_count, curr_time); + } else if (curr_time > next_loop_time) { ret_sleep = OS_SYNC_TIME_EXCEEDED; } else { ret_sleep = 0; } + if (srv_shutdown_state != SRV_SHUTDOWN_NONE) { + break; + } + sig_count = os_event_reset(buf_flush_event); if (ret_sleep == OS_SYNC_TIME_EXCEEDED) { - ulint curr_time = ut_time_ms(); - - if (curr_time > next_loop_time + 3000 + if (global_system_variables.log_warnings > 2 + && curr_time > next_loop_time + 3000 && !(test_flags & TEST_SIGINT)) { if (warn_count == 0) { ib::info() << "page_cleaner: 1000ms"