Bug #93878 innodb_status_output fails to restore to old value

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);

Hello yuhui wang,

Thank you for the report.
Please note that in order to submit contributions you must first sign the Oracle Contribution Agreement (OCA). More details are described in "Contributions" tab.

regards,
Umesh

I have already sent out the OCA.
Thank you for the notification.

Posted by developer:
 
I've fixed this issue as part of
Bug #33789526 srv_error_monitor_thread shouldn't call functions which can deadlock

Fixed as of the upcoming 8.0.29 release:

Enabling and disabling of the standard monitor by InnoDB is
now performed independently of the user-settable innodb_status_output
variable. This change addresses an issue in which the monitor was enabled
by InnoDB in a particular scenario but not set back to its previous value.
Thanks to Yuhui Wang for the contribution.