Description:
When turns on variable innodb_status_output, innodb status will be printed to error log through thread srv_monitor_thread periodically. However, this variable will be turned on automatically in three situations:
1. when buffer pool is occupied by many non-date objects
2. when we can not found free block in 20 loops
3. when wen find long time semaphore waits
If everything is ok after situation 1 and 3, innodb_status_output will be restore to old value(OFF usually). But i have found some problems in situation 2.
In function buf_LRU_get_free_block, we try to use local variable mon_value_was to store the old value of srv_print_innodb_monitor, unfortunately, mon_value_was will be overwrited to 'true' forever after some loops. Put some simplified codes:
bool mon_value_was = false;
loop:
if find free blocks from free list
if (started_monitor)
srv_print_innodb_monitor = mon_value_was; (try to restore to old value)
return block;
if we can free some blocks from lru list
goto loop;
if loop_cnt > 20
mon_value_was = srv_print_innodb_monitor; (this line means assign last loop's srv_print_innodb_monitor to mon_value_was. But it should only do for one time, not every loop)
started_monitor = true;
srv_print_innodb_monitor = true;
try to flush from lru list
loop_cnt++
goto loop;
At last, even after we have got the free block, we still print all innodb status to error log which will make error log grows much faster. I have monitored this problem on product environment.
How to repeat:
Usually we have big buffer pool, in other words, most of time we can get free blocks. So it is hard to reproduce this problem by normal ways. I have modified some codes around buf_LRU_get_free_block to verify this case. But do not be nervous i only add codes through DBUG_EXECUTE_IF function. Note, it is based on mysql 8.0.13.
$ git diff storage/innobase/buf/buf0lru.cc
diff --git a/storage/innobase/buf/buf0lru.cc b/storage/innobase/buf/buf0lru.cc
index 8165f92e63a..28a7a3a2029 100644
--- a/storage/innobase/buf/buf0lru.cc
+++ b/storage/innobase/buf/buf0lru.cc
@@ -1003,6 +1003,8 @@ static bool buf_LRU_free_from_common_LRU_list(buf_pool_t *buf_pool,
ulint scanned = 0;
bool freed = false;
+ DBUG_EXECUTE_IF("ib_status_monitor_err", if (srv_status_monitor_err > 0) return(false););
+
for (buf_page_t *bpage = buf_pool->lru_scan_itr.start();
bpage != NULL && !freed &&
(scan_all || scanned < BUF_LRU_SEARCH_SCAN_THRESHOLD);
@@ -1105,6 +1107,8 @@ buf_block_t *buf_LRU_get_free_only(buf_pool_t *buf_pool) {
block = reinterpret_cast<buf_block_t *>(UT_LIST_GET_FIRST(buf_pool->free));
+ DBUG_EXECUTE_IF("ib_status_monitor_err", if (srv_status_monitor_err > 0) block = NULL;);
+
while (block != NULL) {
ut_ad(block->page.in_free_list);
ut_d(block->page.in_free_list = FALSE);
@@ -1225,6 +1229,9 @@ we put it to free list to be used.
* same as iteration 1 but sleep 10ms
@param[in,out] buf_pool buffer pool instance
@return the free control block, in state BUF_BLOCK_READY_FOR_USE */
+
+int srv_status_monitor_err = 30;
+
buf_block_t *buf_LRU_get_free_block(buf_pool_t *buf_pool) {
buf_block_t *block = NULL;
bool freed = false;
@@ -1339,6 +1348,8 @@ loop:
n_iterations++;
+ DBUG_EXECUTE_IF("ib_status_monitor_err", if (srv_status_monitor_err > 0) srv_status_monitor_err--;);
+
goto loop;
}
$ git diff storage/innobase/include/buf0lru.h
diff --git a/storage/innobase/include/buf0lru.h b/storage/innobase/include/buf0lru.h
index 7b9310a2cbb..c24a9ceb804 100644
--- a/storage/innobase/include/buf0lru.h
+++ b/storage/innobase/include/buf0lru.h
@@ -243,6 +243,7 @@ extern buf_LRU_stat_t buf_LRU_stat_cur;
Updated by buf_LRU_stat_update(). Accesses protected by memory barriers. */
extern buf_LRU_stat_t buf_LRU_stat_sum;
+extern int srv_status_monitor_err;
/** Increments the I/O counter in buf_LRU_stat_cur. */
#define buf_LRU_stat_inc_io() buf_LRU_stat_cur.io++
/** Increments the page_zip_decompress() counter in buf_LRU_stat_cur. */
1. compile in debug mode
2. restart mysql(to clean buffer pool)
3. set global debug = '+d,ib_status_monitor_err';
4. select from some tables
5. after the command has finished, you will find innodb status will be printed to error log every 20 seconds.
6. show variables like '%output%'; will show innodb_status_output is on.
Suggested fix:
Fix is easy, we just modify mon_value_was(the old value) for the first time.
@@ -1300,7 +1307,9 @@ loop:
<< " OS fsyncs. Starting InnoDB Monitor to print"
" further diagnostics to the standard output.";
- mon_value_was = srv_print_innodb_monitor;
+ if (!started_monitor) {
+ mon_value_was = srv_print_innodb_monitor;
+ }
started_monitor = true;
srv_print_innodb_monitor = true;
os_event_set(srv_monitor_event);
Description: When turns on variable innodb_status_output, innodb status will be printed to error log through thread srv_monitor_thread periodically. However, this variable will be turned on automatically in three situations: 1. when buffer pool is occupied by many non-date objects 2. when we can not found free block in 20 loops 3. when wen find long time semaphore waits If everything is ok after situation 1 and 3, innodb_status_output will be restore to old value(OFF usually). But i have found some problems in situation 2. In function buf_LRU_get_free_block, we try to use local variable mon_value_was to store the old value of srv_print_innodb_monitor, unfortunately, mon_value_was will be overwrited to 'true' forever after some loops. Put some simplified codes: bool mon_value_was = false; loop: if find free blocks from free list if (started_monitor) srv_print_innodb_monitor = mon_value_was; (try to restore to old value) return block; if we can free some blocks from lru list goto loop; if loop_cnt > 20 mon_value_was = srv_print_innodb_monitor; (this line means assign last loop's srv_print_innodb_monitor to mon_value_was. But it should only do for one time, not every loop) started_monitor = true; srv_print_innodb_monitor = true; try to flush from lru list loop_cnt++ goto loop; At last, even after we have got the free block, we still print all innodb status to error log which will make error log grows much faster. I have monitored this problem on product environment. How to repeat: Usually we have big buffer pool, in other words, most of time we can get free blocks. So it is hard to reproduce this problem by normal ways. I have modified some codes around buf_LRU_get_free_block to verify this case. But do not be nervous i only add codes through DBUG_EXECUTE_IF function. Note, it is based on mysql 8.0.13. $ git diff storage/innobase/buf/buf0lru.cc diff --git a/storage/innobase/buf/buf0lru.cc b/storage/innobase/buf/buf0lru.cc index 8165f92e63a..28a7a3a2029 100644 --- a/storage/innobase/buf/buf0lru.cc +++ b/storage/innobase/buf/buf0lru.cc @@ -1003,6 +1003,8 @@ static bool buf_LRU_free_from_common_LRU_list(buf_pool_t *buf_pool, ulint scanned = 0; bool freed = false; + DBUG_EXECUTE_IF("ib_status_monitor_err", if (srv_status_monitor_err > 0) return(false);); + for (buf_page_t *bpage = buf_pool->lru_scan_itr.start(); bpage != NULL && !freed && (scan_all || scanned < BUF_LRU_SEARCH_SCAN_THRESHOLD); @@ -1105,6 +1107,8 @@ buf_block_t *buf_LRU_get_free_only(buf_pool_t *buf_pool) { block = reinterpret_cast<buf_block_t *>(UT_LIST_GET_FIRST(buf_pool->free)); + DBUG_EXECUTE_IF("ib_status_monitor_err", if (srv_status_monitor_err > 0) block = NULL;); + while (block != NULL) { ut_ad(block->page.in_free_list); ut_d(block->page.in_free_list = FALSE); @@ -1225,6 +1229,9 @@ we put it to free list to be used. * same as iteration 1 but sleep 10ms @param[in,out] buf_pool buffer pool instance @return the free control block, in state BUF_BLOCK_READY_FOR_USE */ + +int srv_status_monitor_err = 30; + buf_block_t *buf_LRU_get_free_block(buf_pool_t *buf_pool) { buf_block_t *block = NULL; bool freed = false; @@ -1339,6 +1348,8 @@ loop: n_iterations++; + DBUG_EXECUTE_IF("ib_status_monitor_err", if (srv_status_monitor_err > 0) srv_status_monitor_err--;); + goto loop; } $ git diff storage/innobase/include/buf0lru.h diff --git a/storage/innobase/include/buf0lru.h b/storage/innobase/include/buf0lru.h index 7b9310a2cbb..c24a9ceb804 100644 --- a/storage/innobase/include/buf0lru.h +++ b/storage/innobase/include/buf0lru.h @@ -243,6 +243,7 @@ extern buf_LRU_stat_t buf_LRU_stat_cur; Updated by buf_LRU_stat_update(). Accesses protected by memory barriers. */ extern buf_LRU_stat_t buf_LRU_stat_sum; +extern int srv_status_monitor_err; /** Increments the I/O counter in buf_LRU_stat_cur. */ #define buf_LRU_stat_inc_io() buf_LRU_stat_cur.io++ /** Increments the page_zip_decompress() counter in buf_LRU_stat_cur. */ 1. compile in debug mode 2. restart mysql(to clean buffer pool) 3. set global debug = '+d,ib_status_monitor_err'; 4. select from some tables 5. after the command has finished, you will find innodb status will be printed to error log every 20 seconds. 6. show variables like '%output%'; will show innodb_status_output is on. Suggested fix: Fix is easy, we just modify mon_value_was(the old value) for the first time. @@ -1300,7 +1307,9 @@ loop: << " OS fsyncs. Starting InnoDB Monitor to print" " further diagnostics to the standard output."; - mon_value_was = srv_print_innodb_monitor; + if (!started_monitor) { + mon_value_was = srv_print_innodb_monitor; + } started_monitor = true; srv_print_innodb_monitor = true; os_event_set(srv_monitor_event);