Logging and related changed based on review comments

Author: mariadb-DebarunBanerjee

mysql-test/mariadb-test-run.pl

@@ -4464,6 +4464,7 @@ ($$)
      qr/InnoDB: innodb_open_files .* should not be greater than/,
      qr/InnoDB: Trying to delete tablespace.*but there are.*pending/,
      qr/InnoDB: Tablespace 1[0-9]* was not found at .*, and innodb_force_recovery was set/,
+     qr/InnoDB: Long wait \([0-9]+ seconds\) for double-write buffer flush/,
      qr/Slave: Unknown table 't1' .* 1051/,
      qr/Slave SQL:.*(Internal MariaDB error code: [[:digit:]]+|Query:.*)/,
      qr/slave SQL thread aborted/,

storage/innobase/buf/buf0dblwr.cc

@@ -602,24 +602,20 @@ static void buf_dblwr_check_block(const buf_page_t *bpage) noexcept
 }
 #endif /* UNIV_DEBUG */
 
-void buf_dblwr_t::print_info(FILE* file)
+ATTRIBUTE_COLD void buf_dblwr_t::print_info() const noexcept
 {
   mysql_mutex_assert_owner(&mutex);
-  slot *flush_slot= active_slot == &slots[0] ? &slots[1] : &slots[0];
-  std::ostringstream log_strm;
-
-  log_strm
-    << "--------------------\n"
-    << "Innodb: Double Write\n"
-    << "--------------------\n"
-    << "Batch running : " << std::boolalpha << batch_running << "\n"
-    << "Active Slot- "
-    << "first_free: " << active_slot->first_free
-    << " reserved: " << active_slot->reserved << "\n"
-    << "Flush Slot - "
-    << "first_free: " << flush_slot->first_free
-    << " reserved: " << flush_slot->reserved << "\n";
-  fputs(log_strm.str().c_str(), file);
+  const slot *flush_slot= active_slot == &slots[0] ? &slots[1] : &slots[0];
+
+  sql_print_information("Innodb: Double Write State\n"
+      "-------------------\n"
+      "Batch running : %s\n"
+      "Active Slot - first_free: %lu reserved:  %lu\n"
+      "Flush  Slot - first_free: %lu reserved:  %lu\n"
+      "-------------------",
+      (batch_running ? "true" : "false"),
+      active_slot->first_free, active_slot->reserved,
+      flush_slot->first_free, flush_slot->reserved);
 }
 
 bool buf_dblwr_t::flush_buffered_writes(const ulint size) noexcept
@@ -644,17 +640,17 @@ bool buf_dblwr_t::flush_buffered_writes(const ulint size) noexcept
 
     if (++count < first_log_count && !(count % 5))
     {
-      ib::info() << "Long wait (" << count
-                 << " seconds) for double-write buffer flush.";
-      print_flush_info(stderr);
-      print_info(stderr);
+      sql_print_information(
+        "Long wait (%d seconds) for double-write buffer flush.", count);
+      buf_pool.print_flush_info();
+      print_info();
     }
     else if (!(count % log_count))
     {
-      ib::warn() << "Long wait (" << count
-                 << " seconds) for double-write buffer flush.";
-      print_flush_info(stderr);
-      print_info(stderr);
+      sql_print_warning(
+        "Long wait (%d seconds) for double-write buffer flush.", count);
+      buf_pool.print_flush_info();
+      print_info();
       log_count= log_count >= max_count ? max_count : log_count * 2;
     }
   }

storage/innobase/buf/buf0flu.cc

@@ -25,7 +25,6 @@ The database buffer buf_pool flush algorithm
 Created 11/11/1995 Heikki Tuuri
 *******************************************************/
 
-#include <iomanip>
 #include "univ.i"
 #include <my_service_manager.h>
 #include <mysql/service_thd_wait.h>
@@ -1375,9 +1374,10 @@ static void buf_flush_LRU_list_batch(ulint max, flush_counters_t *n) noexcept
         break;
       }
 
-      bool reached_half= UT_LIST_GET_LEN(buf_pool.free) >= free_limit / 2;
-
-      if (reached_half && neighbors && space->is_rotational())
+      if (neighbors && space->is_rotational() &&
+          /* Skip neighbourhood flush from LRU list if we haven't yet reached
+          half of the free page target. */
+          UT_LIST_GET_LEN(buf_pool.free) * 2 >= free_limit)
         n->flushed+= buf_flush_try_neighbors(space, page_id, bpage,
                                              neighbors == 1,
                                              n->flushed, max);
@@ -2343,9 +2343,9 @@ static void buf_flush_page_cleaner() noexcept
     {
       std::this_thread::sleep_for(std::chrono::seconds(1));
       /* Cover the logging code in debug mode. */
-      print_flush_info(stderr);
+      buf_pool.print_flush_info();
       buf_dblwr.lock();
-      buf_dblwr.print_info(stderr);
+      buf_dblwr.print_info();
       buf_dblwr.unlock();
     });
     lsn_limit= buf_flush_sync_lsn;
@@ -2553,7 +2553,8 @@ static void buf_flush_page_cleaner() noexcept
     n= n >= n_flushed ? n - n_flushed : 0;
     /* It is critical to generate free pages to keep the system alive. Make
     sure we are not hindered by dirty pages in LRU tail. */
-    n= std::max(n, std::min(srv_max_io_capacity, buf_pool.LRU_scan_depth));
+    n= std::max<ulint>(n, std::min<ulint>(srv_max_io_capacity,
+                                          buf_pool.LRU_scan_depth));
     goto LRU_flush;
   }
 
@@ -2595,7 +2596,7 @@ ATTRIBUTE_COLD void buf_pool_t::LRU_warn() noexcept
   {
     sql_print_warning("InnoDB: Could not free any blocks in the buffer pool!"
                       " Consider increasing innodb_buffer_pool_size.");
-    print_flush_info(stderr);
+    buf_pool.print_flush_info();
   }
 }
 
@@ -2676,48 +2677,51 @@ void buf_flush_sync() noexcept
   thd_wait_end(nullptr);
 }
 
-void print_flush_info(FILE* file)
+ATTRIBUTE_COLD void buf_pool_t::print_flush_info() const noexcept
 {
   /* We do dirty read of UT_LIST count variable. */
-  ulint lru_size= UT_LIST_GET_LEN(buf_pool.LRU);
-  ulint dirty_size= UT_LIST_GET_LEN(buf_pool.flush_list);
-  ulint free_size= UT_LIST_GET_LEN(buf_pool.free);
+  ulint lru_size= UT_LIST_GET_LEN(LRU);
+  ulint dirty_size= UT_LIST_GET_LEN(flush_list);
+  ulint free_size= UT_LIST_GET_LEN(free);
   ulint dirty_pct= lru_size ? dirty_size * 100 / (lru_size + free_size) : 0;
+  sql_print_information("Innodb: Buffer Pool pages \n"
+    "-------------------\n"
+    "LRU   Pages: %lu\n"
+    "Free  Pages: %lu\n"
+    "Dirty Pages: %lu : %lu%%\n"
+    "-------------------",
+    lru_size, free_size, dirty_size, dirty_pct);
 
   lsn_t lsn= log_sys.get_lsn();
   lsn_t clsn= log_sys.last_checkpoint_lsn;
+  sql_print_information("Innodb: LSN flush parameters\n"
+    "-------------------\n"
+    "System LSN     : %" PRIu64 "\n"
+    "Checkpoint  LSN: %" PRIu64 "\n"
+    "Flush ASync LSN: %" PRIu64 "\n"
+    "Flush Sync  LSN: %" PRIu64 "\n"
+    "-------------------",
+    lsn, clsn, buf_flush_async_lsn, buf_flush_sync_lsn);
+
   lsn_t age= lsn - clsn;
   lsn_t age_pct= log_sys.max_checkpoint_age
       ? age * 100 / log_sys.max_checkpoint_age : 0;
-
-  std::ostringstream log_strm;
-  log_strm
-    << "-------------------\n"
-    << "Innodb: Buffer Pool\n"
-    << "-------------------\n"
-    << "LRU Pages : " << lru_size << "\n"
-    << "Free Pages: " << free_size << "\n"
-    << "DirtyPages: " << dirty_size << " : " << dirty_pct << "%\n"
-    << "----------------------------\n"
-    << "Innodb: Flush LSN Parameter \n"
-    << "----------------------------\n"
-    << "System LSN     : " << lsn << "\n"
-    << "Checkpoint LSN : " << clsn << "\n"
-    << "Flush ASync LSN: " << buf_flush_async_lsn << "\n"
-    << "Flush Sync LSN : " << buf_flush_sync_lsn << "\n"
-    << "--------------------------\n"
-    << "Innodb: LSN Age Parameters\n"
-    << "--------------------------\n"
-    << "Current Age   : " << age <<  " : " << age_pct  << "%\n"
-    << "Max Age(Async): " << log_sys.max_modified_age_async << "\n"
-    << "Max Age(Sync) : " << log_sys.max_checkpoint_age << "\n"
-    << "Capacity      : " << log_sys.log_capacity << "\n"
-    << "--------------------------\n"
-    << "Innodb: Pending IO count \n"
-    << "-------------------------\n"
-    << "Pending  Read: " << os_aio_pending_reads_approx() << "\n"
-    << "Pending Write: " << os_aio_pending_writes_approx() << "\n";
-  fputs(log_strm.str().c_str(), file);
+  sql_print_information("Innodb: LSN age parameters\n"
+    "-------------------\n"
+    "Current Age   : %" PRIu64 " : %" PRIu64 "%%\n"
+    "Max Age(Async): %" PRIu64 "\n"
+    "Max Age(Sync) : %" PRIu64 "\n"
+    "Capacity      : %" PRIu64 "\n"
+    "-------------------",
+    age, age_pct, log_sys.max_modified_age_async, log_sys.max_checkpoint_age,
+    log_sys.log_capacity);
+
+  sql_print_information("Innodb: Pending IO count\n"
+    "-------------------\n"
+    "Pending  Read: %zu\n"
+    "Pending Write: %zu\n"
+    "-------------------",
+    os_aio_pending_reads_approx(), os_aio_pending_writes_approx());
 }
 
 #ifdef UNIV_DEBUG

storage/innobase/dict/dict0dict.cc

@@ -1014,7 +1014,7 @@ void dict_sys_t::lock_wait(SRW_LOCK_ARGS(const char *file, unsigned line)) noexc
 
   if (waited >= threshold)
   {
-    print_flush_info(stderr);
+    buf_pool.print_flush_info();
     ib::fatal() << fatal_msg;
   }
 

storage/innobase/include/buf0buf.h

@@ -1951,6 +1951,9 @@ class buf_pool_t
   /** Issue a warning that we could not free up buffer pool pages. */
   ATTRIBUTE_COLD void LRU_warn() noexcept;
 
+  /** Print buffer pool flush state information. */
+  ATTRIBUTE_COLD void print_flush_info() const noexcept;
+
 private:
   /** Temporary memory for page_compressed and encrypted I/O */
   struct io_buf_t

storage/innobase/include/buf0dblwr.h

@@ -160,9 +160,8 @@ class buf_dblwr_t
     mysql_mutex_unlock(&mutex);
   }
 
-  /** Print double write state information.
-  @param file log file for write */
-  void print_info(FILE* file);
+  /** Print double write state information. */
+  ATTRIBUTE_COLD void print_info() const noexcept;
 };
 
 /** The doublewrite buffer */

storage/innobase/include/buf0flu.h

@@ -135,7 +135,3 @@ void buf_flush_sync_batch(lsn_t lsn) noexcept;
 /** Synchronously flush dirty blocks.
 NOTE: The calling thread is not allowed to hold any buffer page latches! */
 void buf_flush_sync() noexcept;
-
-/** Print buffer pool flush state information.
-@param file log file for write */
-void print_flush_info(FILE* file);

storage/innobase/srv/srv0srv.cc

@@ -1220,7 +1220,7 @@ void srv_monitor_task(void*)
 			now -= start;
 			ulong waited = static_cast<ulong>(now / 1000000);
 			if (waited >= threshold) {
-				print_flush_info(stderr);
+				buf_pool.print_flush_info();
 				ib::fatal() << dict_sys.fatal_msg;
 			}