MDEV-25215 Excessive logging "InnoDB: Cannot close file"

In commit 45ed9dd957eebc7fc84feb2509f4aa6baa908a95 (MDEV-23855)
when removing fil_system.LRU we failed to rate-limit the output
for reporting violations of innodb_open_files or open_files_limit.

If the server is run with a small limit of open files that is
well below the number of .ibd files that are being accessed by
the workload, and if at the same time innodb_log_file_size is
very small so that log checkpoints will occur frequently,
the process of enforcing the open files limit may be run very often.

fil_space_t::try_to_close(): Display at most one message per call,
and only if at least 5 seconds have elapsed since the last time a
message was output.

fil_node_open_file(): Only output a summary message if
fil_space_t::try_to_close() displayed a message during this run.
(Note: multiple threads may execute fil_node_open_file() on
different files at the same time.)

fil_space_t::get(): Do not dereference a null pointer if n & STOPPING.
This was caught by the test case below.

Unfortunately, it is not possible to create a fully deterministic
test case (expecting exactly 1 message to be emitted). The following with
--innodb-open-files=10 --innodb-log-file-size=4m
would occasionally fail to find the message in the log:

--source include/have_innodb.inc
--source include/have_partition.inc
--source include/have_sequence.inc

call mtr.add_suppression("InnoDB: innodb_open_files=10 is exceeded");

CREATE TABLE t1 (pk INT AUTO_INCREMENT PRIMARY KEY) ENGINE=InnoDB
PARTITION BY key (pk) PARTITIONS 100;

INSERT INTO t1 SELECT * FROM seq_1_to_100;
--disable_query_log
let $n=400;
while ($n)
{
BEGIN; DELETE FROM t1; ROLLBACK;
dec $n;
}
--enable_query_log

let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err;
let SEARCH_PATTERN= \[Note\] InnoDB: Cannot close file;
-- source include/search_pattern_in_file.inc

DROP TABLE t1;

2 files changed, 25 insertions, 12 deletions

diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.cc
index b9421df3ffb..39049f237e1 100644
--- a/storage/innobase/fil/fil0fil.cc
+++ b/storage/innobase/fil/fil0fil.cc
@@ -97,13 +97,22 @@ bool fil_space_t::try_to_close(bool print_info)
 
     if (const auto n= space->set_closing())
     {
-      if (print_info)
-        ib::info() << "Cannot close file " << node->name
-                   << " because of "
-                   << (n & PENDING)
-                   << ((n & NEEDS_FSYNC)
-                       ? " pending operations and pending fsync"
-                       : " pending operations");
+      if (!print_info)
+        continue;
+      print_info= false;
+      const time_t now= time(nullptr);
+      if (now - fil_system.n_open_exceeded_time < 5)
+        continue; /* We display messages at most once in 5 seconds. */
+      fil_system.n_open_exceeded_time= now;
+
+      if (n & PENDING)
+        sql_print_information("InnoDB: Cannot close file %s because of "
+                              UINT32PF " pending operations%s", node->name,
+                              n & PENDING,
+                              (n & NEEDS_FSYNC) ? " and pending fsync" : "");
+      else if (n & NEEDS_FSYNC)
+        sql_print_information("InnoDB: Cannot close file %s because of "
+                              "pending fsync", node->name);
       continue;
     }
 
@@ -424,15 +433,18 @@ static bool fil_node_open_file(fil_node_t *node)
   ut_ad(node->space->purpose != FIL_TYPE_TEMPORARY);
   ut_ad(node->space->referenced());
 
+  const auto old_time= fil_system.n_open_exceeded_time;
+
   for (ulint count= 0; fil_system.n_open >= srv_max_n_open_files; count++)
   {
     if (fil_space_t::try_to_close(count > 1))
       count= 0;
     else if (count >= 2)
     {
-      ib::warn() << "innodb_open_files=" << srv_max_n_open_files
-                 << " is exceeded (" << fil_system.n_open
-                 << ") files stay open)";
+      if (old_time != fil_system.n_open_exceeded_time)
+        sql_print_warning("InnoDB: innodb_open_files=" ULINTPF
+                          " is exceeded (" ULINTPF " files stay open)",
+                          srv_max_n_open_files, fil_system.n_open);
       break;
     }
     else
@@ -1470,8 +1482,7 @@ fil_space_t *fil_space_t::get(ulint id)
 
   if (n & STOPPING)
     space= nullptr;
-
-  if ((n & CLOSING) && !space->prepare())
+  else if ((n & CLOSING) && !space->prepare())
     space= nullptr;
 
   return space;
diff --git a/storage/innobase/include/fil0fil.h b/storage/innobase/include/fil0fil.h
index 57b103518d5..10fec4d0871 100644
--- a/storage/innobase/include/fil0fil.h
+++ b/storage/innobase/include/fil0fil.h
@@ -1387,6 +1387,8 @@ public:
   sized_ilist<fil_space_t, unflushed_spaces_tag_t> unflushed_spaces;
   /** number of currently open files; protected by mutex */
   ulint n_open;
+  /** last time we noted n_open exceeding the limit; protected by mutex */
+  time_t n_open_exceeded_time;
 	ulint		max_assigned_id;/*!< maximum space id in the existing
 					tables, or assigned during the time
 					mysqld has been up; at an InnoDB