Bug #33343690 ER_IB_MSG_277 and ER_IB_MSG_275 messages are excessively logged

After bug#32634620 the server counts the files that are added to LRU of files against `innodb_open_files` limit. However, this leads to a problem. On a duration of an IO the file is being temporarily removed from the LRU. This allows additional files to be opened within the `innodb_open_files` limit. After the IOs are done, the number of opened files can exceed the `innodb_open_files` limit by 10-20. Assuming this case, there are a lot of files in the LRU that can be easily closed. As a call to `close_file_in_all_LRU` will succeed in this case, the loop in `Fil_shard::mutex_acquire_and_get_space` tries to close only 3 files from the LRU before giving up (and allowing the file to be opened either way). Closing 3 files is not enough to get LRU size below the limit. Also, additionally the `close_file_in_all_LRU` while closing 3rd file will print an abundant amount of info messages to log.
This is fixed by moving closer to logic before the WL#8619, we constantly try to close files for 5 seconds before reporting it takes too long and retrying with flushing the tablespaces.
Added throttling to messages printed by `Fil_system::close_file_in_all_LRU`.
Don't print message `ER_IB_MSG_277` when there is no files in current shard. Changed message to warn about the low `innodb_open_files`.

RB#27009

Author: Marcin Babij

storage/innobase/fil/fil0fil.cc

@@ -52,6 +52,7 @@ The tablespace memory cache */
 #include "mtr0log.h"
 #include "my_dbug.h"
 #include "ut0new.h"
+#include "ut0ut.h"
 
 #include "clone0api.h"
 #include "os0file.h"
@@ -1570,7 +1571,7 @@ class Fil_system {
   The caller must hold the mutex.
   @param[in]	print_info	if true, prints information why it close a file
   @return true if success, false if should retry later */
-  [[nodiscard]] bool close_file_in_all_LRU(bool print_info);
+  bool close_file_in_all_LRU(bool print_info);
 
   /** Opens all log files and system tablespace data files in
   all shards. */
@@ -1765,6 +1766,11 @@ class Fil_system {
   /** Free the data structures required for recovery. */
   void free_scanned_files() { m_dirs.clear(); }
 
+  /** Throttles info messages when closing files in LRU lists. */
+  bool should_print_close_by_lru_info() {
+    return m_close_by_LRU_info_throttler.apply();
+  }
+
 #ifdef UNIV_HOTBACKUP
   /** Extends all tablespaces to the size stored in the space header.
   During the mysqlbackup --apply-log phase we extended the spaces
@@ -1818,6 +1824,9 @@ class Fil_system {
   /** n_open is not allowed to exceed this */
   const size_t m_max_n_open;
 
+  /** Throttles info messages when closing files in LRU lists. */
+  ib::Throttler m_close_by_LRU_info_throttler;
+
   /** Maximum space id in the existing tables, or assigned during
   the time mysqld has been up; at an InnoDB startup we scan the
   data dictionary and set here the maximum of the space id's of
@@ -2904,8 +2913,10 @@ bool Fil_system::close_file_in_all_LRU(bool print_info) {
     shard->mutex_acquire();
 
     if (print_info) {
-      ib::info(ER_IB_MSG_277, shard->id(),
-               ulonglong{UT_LIST_GET_LEN(shard->m_LRU)});
+      const auto len = ulonglong{UT_LIST_GET_LEN(shard->m_LRU)};
+      if (len > 0) {
+        ib::info(ER_IB_MSG_277, shard->id(), len);
+      }
     }
 
     bool success = shard->close_files_in_LRU(print_info);
@@ -3046,15 +3057,20 @@ bool Fil_shard::mutex_acquire_and_get_space(space_id_t space_id,
     /* Reserve an open slot for this shard. So that this
     shard's open file succeeds. */
 
-    while (fil_system->m_max_n_open <= s_n_spaces_in_lru &&
-           !fil_system->close_file_in_all_LRU(i > 1)) {
+    while (fil_system->m_max_n_open <= s_n_spaces_in_lru) {
+      if (!fil_system->close_file_in_all_LRU(false)) {
+        std::this_thread::yield();
+      }
       if (ut_time_monotonic() - start_time >= PRINT_INTERVAL_SECS) {
         start_time = ut_time_monotonic();
 
         ib::warn(ER_IB_MSG_279) << "Trying to close a file for "
                                 << start_time - begin_time << " seconds"
                                 << ". Configuration only allows for "
                                 << fil_system->m_max_n_open << " open files.";
+        fil_system->close_file_in_all_LRU(
+            fil_system->should_print_close_by_lru_info());
+        break;
       }
     }
 

storage/innobase/include/ut0ut.h

@@ -942,6 +942,47 @@ struct Wait_stats {
   bool any_waits() const { return (wait_loops != 0); }
 };
 
+namespace ib {
+
+/** Allows to monitor an event processing times, allowing to throttle the
+processing to one per THROTTLE_DELAY_SEC. */
+class Throttler {
+ public:
+  Throttler() : m_last_applied_time(0) {}
+
+  /** Checks if the item should be processed or ignored to not process them more
+  frequently than one per THROTTLE_DELAY_SEC. */
+  bool apply() {
+    const auto current_time = std::chrono::steady_clock::now();
+    const auto current_time_in_sec =
+        std::chrono::duration_cast<std::chrono::seconds>(
+            current_time.time_since_epoch())
+            .count();
+    auto last_apply_time = m_last_applied_time.load();
+    if (last_apply_time + THROTTLE_DELAY_SEC <
+        static_cast<uint64_t>(current_time_in_sec)) {
+      if (m_last_applied_time.compare_exchange_strong(last_apply_time,
+                                                      current_time_in_sec)) {
+        return true;
+      }
+      /* Any race condition with other threads would mean someone just changed
+      the `m_last_apply_time` and will print the message. We don't want
+      to retry the operation again. */
+    }
+    return false;
+  }
+
+ private:
+  /* Time when the last item was not throttled. Stored as number of seconds
+  since epoch. */
+  std::atomic<uint64_t> m_last_applied_time;
+
+  /** Throttle all items within that amount seconds from the last non throttled
+  one. */
+  static constexpr uint64_t THROTTLE_DELAY_SEC = 10;
+};
+}  // namespace ib
+
 #include "ut0ut.ic"
 
 #endif /* !ut0ut_h */