MDEV-35155: Small innodb_log_file_size may lead to excessive writing

Any InnoDB write workload is marking data pages in the buffer pool dirty.
To make the changes durable, it suffices to write to the write-ahead log
to facilitate crash recovery. The longer we keep pages dirty in the
buffer pool, the better, because the same pages could be modified again
and a single write to the file system could cover several changes.

Eventually, we must write out dirty pages, so that we can advance the
log checkpoint, that is, allow the start of the recovery log to be
discarded. (On a clean shutdown, a full checkpoint to the end of the log
will be made.)

A write workload can be bound by innodb_buffer_pool_size
(we must write out changes and evict data pages to make room for others)
or by innodb_log_file_size
(we must advance the log checkpoint before the tail of the circular
ib_logfile0 would overwrite the previous checkpoint).

In innodb_log_file_size bound workloads, we failed to set an optimal
target for the next checkpoint LSN. If we write out too few pages, then
all writer threads may occasionally be blocked in log_free_check() while
the buf_flush_page_cleaner() thread is resolving the situation. If we
write out too many pages, then the I/O subsystem will be loaded
unnecessarily and there will be some write amplification in case some of
the unnecessarily written pages would be modified soon afterwards.

log_close(): Return the target LSN for buf_flush_ahead(lsn),
bitwise-ORed with the "furious" flag, or the special values 0
indicating that no flushing is needed, which is the usual case.

log_checkpoint_margin(): Use a similar page checkpoint target as
log_close() for the !not_furious case.

mtr_flush_ahead(): A wrapper for buf_flush_ahead().

mtr_t::commit_log_release(): Make some common code non-inline in order
to reduce code duplication.

buf_flush_ahead(lsn, furious=false): Avoid an unnecessary wake-up of the
page cleaner if it is scheduled to wake up once per second.

Co-developed-by: Alessandro Vetere
Reviewed by: Vladislav Lesin

Author: dr-m

storage/innobase/buf/buf0flu.cc

@@ -2191,10 +2191,24 @@ ATTRIBUTE_COLD void buf_flush_ahead(lsn_t lsn, bool furious) noexcept
     if (limit < lsn)
     {
       limit= lsn;
-      buf_pool.page_cleaner_set_idle(false);
-      pthread_cond_signal(&buf_pool.do_flush_list);
       if (furious)
+      {
+        /* Request any concurrent threads to wait for this batch to complete,
+        in log_free_check(). */
         log_sys.set_check_for_checkpoint();
+        /* Immediately wake up buf_flush_page_cleaner(), even when it
+        is in the middle of a 1-second my_cond_timedwait(). */
+      wake:
+        buf_pool.page_cleaner_set_idle(false);
+        pthread_cond_signal(&buf_pool.do_flush_list);
+      }
+      else if (buf_pool.page_cleaner_idle())
+        /* In non-furious mode, concurrent writes to the log will remain
+        possible, and we are gently requesting buf_flush_page_cleaner()
+        to do more work to avoid a later call with furious=true.
+        We will only wake the buf_flush_page_cleaner() from an indefinite
+        my_cond_wait(), but we will not disturb the regular 1-second sleep. */
+        goto wake;
     }
     mysql_mutex_unlock(&buf_pool.flush_list_mutex);
   }

storage/innobase/include/mtr0mtr.h

@@ -645,17 +645,6 @@ struct mtr_t {
   /** Note that log_sys.latch is no longer being held exclusively. */
   void flag_wr_unlock() noexcept { ut_ad(m_latch_ex); m_latch_ex= false; }
 
-  /** type of page flushing is needed during commit() */
-  enum page_flush_ahead
-  {
-    /** no need to trigger page cleaner */
-    PAGE_FLUSH_NO= 0,
-    /** asynchronous flushing is needed */
-    PAGE_FLUSH_ASYNC,
-    /** furious flushing is needed */
-    PAGE_FLUSH_SYNC
-  };
-
 private:
   /** Handle any pages that were freed during the mini-transaction. */
   void process_freed_pages();
@@ -702,29 +691,31 @@ struct mtr_t {
   /** Commit the mini-transaction log.
   @tparam pmem log_sys.is_mmap()
   @param mtr   mini-transaction
-  @param lsns  {start_lsn,flush_ahead} */
+  @param lsns  {start_lsn,flush_ahead_lsn} */
   template<bool pmem>
-  static void commit_log(mtr_t *mtr, std::pair<lsn_t,page_flush_ahead> lsns)
-    noexcept;
+  static void commit_log(mtr_t *mtr, std::pair<lsn_t,lsn_t> lsns) noexcept;
+
+  /** Release log_sys.latch. */
+  void commit_log_release() noexcept;
 
   /** Append the redo log records to the redo log buffer.
-  @return {start_lsn,flush_ahead} */
-  std::pair<lsn_t,page_flush_ahead> do_write();
+  @return {start_lsn,flush_ahead_lsn} */
+  std::pair<lsn_t,lsn_t> do_write() noexcept;
 
   /** Append the redo log records to the redo log buffer.
   @tparam mmap log_sys.is_mmap()
   @param mtr   mini-transaction
   @param len   number of bytes to write
-  @return {start_lsn,flush_ahead} */
+  @return {start_lsn,flush_ahead_lsn} */
   template<bool mmap> static
-  std::pair<lsn_t,page_flush_ahead> finish_writer(mtr_t *mtr, size_t len);
+  std::pair<lsn_t,lsn_t> finish_writer(mtr_t *mtr, size_t len);
 
   /** The applicable variant of commit_log() */
-  static void (*commit_logger)(mtr_t *, std::pair<lsn_t,page_flush_ahead>);
+  static void (*commit_logger)(mtr_t *, std::pair<lsn_t,lsn_t>);
   /** The applicable variant of finish_writer() */
-  static std::pair<lsn_t,page_flush_ahead> (*finisher)(mtr_t *, size_t);
+  static std::pair<lsn_t,lsn_t> (*finisher)(mtr_t *, size_t);
 
-  std::pair<lsn_t,page_flush_ahead> finish_write(size_t len)
+  std::pair<lsn_t,lsn_t> finish_write(size_t len)
   { return finisher(this, len); }
 public:
   /** Update finisher when spin_wait_delay is changing to or from 0. */

storage/innobase/log/log0log.cc

@@ -1304,10 +1304,10 @@ ATTRIBUTE_COLD static void log_checkpoint_margin() noexcept
     }
 
     const lsn_t lsn= log_sys.get_lsn();
-    const lsn_t checkpoint= log_sys.last_checkpoint_lsn;
-    const lsn_t sync_lsn= checkpoint + log_sys.max_checkpoint_age;
+    const lsn_t max_age= log_sys.max_checkpoint_age;
+    const lsn_t age= lsn_t(lsn - log_sys.last_checkpoint_lsn);
 
-    if (lsn <= sync_lsn)
+    if (age <= max_age)
     {
 #ifndef DBUG_OFF
     skip_checkpoint:
@@ -1320,7 +1320,7 @@ ATTRIBUTE_COLD static void log_checkpoint_margin() noexcept
     log_sys.latch.wr_unlock();
 
     /* We must wait to prevent the tail of the log overwriting the head. */
-    buf_flush_wait_flushed(std::min(sync_lsn, checkpoint + (1U << 20)));
+    buf_flush_wait_flushed(lsn - max_age);
     /* Sleep to avoid a thundering herd */
     std::this_thread::sleep_for(std::chrono::milliseconds(10));
   }

storage/innobase/mtr/mtr0mtr.cc

@@ -40,10 +40,10 @@ Created 11/26/1995 Heikki Tuuri
 #include "my_cpu.h"
 
 #ifdef HAVE_PMEM
-void (*mtr_t::commit_logger)(mtr_t *, std::pair<lsn_t,page_flush_ahead>);
+void (*mtr_t::commit_logger)(mtr_t *, std::pair<lsn_t,lsn_t>);
 #endif
 
-std::pair<lsn_t,mtr_t::page_flush_ahead> (*mtr_t::finisher)(mtr_t *, size_t);
+std::pair<lsn_t,lsn_t> (*mtr_t::finisher)(mtr_t *, size_t);
 
 void mtr_t::finisher_update()
 {
@@ -335,9 +335,25 @@ void mtr_t::release()
   m_memo.clear();
 }
 
+ATTRIBUTE_NOINLINE void mtr_t::commit_log_release() noexcept
+{
+  if (m_latch_ex)
+  {
+    log_sys.latch.wr_unlock();
+    m_latch_ex= false;
+  }
+  else
+    log_sys.latch.rd_unlock();
+}
+
+static ATTRIBUTE_NOINLINE ATTRIBUTE_COLD
+void mtr_flush_ahead(lsn_t flush_lsn) noexcept
+{
+  buf_flush_ahead(flush_lsn, bool(flush_lsn & 1));
+}
+
 template<bool mmap>
-void mtr_t::commit_log(mtr_t *mtr, std::pair<lsn_t,page_flush_ahead> lsns)
-  noexcept
+void mtr_t::commit_log(mtr_t *mtr, std::pair<lsn_t,lsn_t> lsns) noexcept
 {
   size_t modified= 0;
 
@@ -378,25 +394,12 @@ void mtr_t::commit_log(mtr_t *mtr, std::pair<lsn_t,page_flush_ahead> lsns)
     buf_pool.page_cleaner_wakeup();
     mysql_mutex_unlock(&buf_pool.flush_list_mutex);
 
-    if (mtr->m_latch_ex)
-    {
-      log_sys.latch.wr_unlock();
-      mtr->m_latch_ex= false;
-    }
-    else
-      log_sys.latch.rd_unlock();
-
+    mtr->commit_log_release();
     mtr->release();
   }
   else
   {
-    if (mtr->m_latch_ex)
-    {
-      log_sys.latch.wr_unlock();
-      mtr->m_latch_ex= false;
-    }
-    else
-      log_sys.latch.rd_unlock();
+    mtr->commit_log_release();
 
     for (auto it= mtr->m_memo.rbegin(); it != mtr->m_memo.rend(); )
     {
@@ -456,8 +459,11 @@ void mtr_t::commit_log(mtr_t *mtr, std::pair<lsn_t,page_flush_ahead> lsns)
 
   mariadb_increment_pages_updated(modified);
 
-  if (UNIV_UNLIKELY(lsns.second != PAGE_FLUSH_NO))
-    buf_flush_ahead(mtr->m_commit_lsn, lsns.second == PAGE_FLUSH_SYNC);
+  if (UNIV_UNLIKELY(lsns.second != 0))
+  {
+    ut_ad(lsns.second < mtr->m_commit_lsn);
+    mtr_flush_ahead(lsns.second);
+  }
 }
 
 /** Commit a mini-transaction. */
@@ -480,7 +486,7 @@ void mtr_t::commit()
     }
 
     ut_ad(!srv_read_only_mode);
-    std::pair<lsn_t,page_flush_ahead> lsns{do_write()};
+    std::pair<lsn_t,lsn_t> lsns{do_write()};
     process_freed_pages();
 #ifdef HAVE_PMEM
     commit_logger(this, lsns);
@@ -971,24 +977,44 @@ std::pair<lsn_t,byte*> log_t::append_prepare(size_t size, bool ex) noexcept
 
 /** Finish appending data to the log.
 @param lsn  the end LSN of the log record
-@return whether buf_flush_ahead() will have to be invoked */
-static mtr_t::page_flush_ahead log_close(lsn_t lsn) noexcept
+@return lsn for invoking buf_flush_ahead() on, with "furious" flag in the LSB
+@retval 0 if buf_flush_ahead() will not have to be invoked */
+static lsn_t log_close(lsn_t lsn) noexcept
 {
   ut_ad(log_sys.latch_have_any());
 
   const lsn_t checkpoint_age= lsn - log_sys.last_checkpoint_lsn;
+  const lsn_t max_age= log_sys.max_modified_age_async;
 
   if (UNIV_UNLIKELY(checkpoint_age >= log_sys.log_capacity) &&
       /* silence message on create_log_file() after the log had been deleted */
       checkpoint_age != lsn)
     log_overwrite_warning(lsn);
-  else if (UNIV_LIKELY(checkpoint_age <= log_sys.max_modified_age_async))
-    return mtr_t::PAGE_FLUSH_NO;
-  else if (UNIV_LIKELY(checkpoint_age <= log_sys.max_checkpoint_age))
-    return mtr_t::PAGE_FLUSH_ASYNC;
-
-  log_sys.set_check_for_checkpoint();
-  return mtr_t::PAGE_FLUSH_SYNC;
+  else if (UNIV_LIKELY(checkpoint_age <= max_age))
+    return 0;
+
+  /* The last checkpoint is too old. Let us set an appropriate
+  checkpoint age target, that is, a checkpoint LSN target that is the
+  current LSN minus the maximum age. Let us see if are exceeding the
+  log_checkpoint_margin() limit that will involve a synchronous wait
+  in each write operation. */
+
+  const bool furious{checkpoint_age >= log_sys.max_checkpoint_age};
+
+  /* If furious==true, we could set a less aggressive target
+  (lsn - log_sys.max_checkpoint_age) instead of what we will be using
+  in both cases (lsn - log_sys.max_checkpoint_age_async).
+
+  The aim of the more aggressive target is that mtr_flush_ahead() will
+  request more progress in buf_flush_page_cleaner() sooner, so that it
+  will be less likely that several threads will end up waiting in
+  log_checkpoint_margin(). That function will use the less aggressive
+  limit (lsn - log_sys.max_checkpoint_age) in order to minimize the
+  synchronous wait time. */
+  if (furious)
+    log_sys.set_check_for_checkpoint();
+
+  return ((lsn - max_age) & ~lsn_t{1}) | lsn_t{furious};
 }
 
 inline void mtr_t::page_checksum(const buf_page_t &bpage)
@@ -1034,7 +1060,7 @@ inline void mtr_t::page_checksum(const buf_page_t &bpage)
   m_log.close(l + 4);
 }
 
-std::pair<lsn_t,mtr_t::page_flush_ahead> mtr_t::do_write()
+std::pair<lsn_t,lsn_t> mtr_t::do_write() noexcept
 {
   ut_ad(!recv_no_log_write);
   ut_ad(is_logged());
@@ -1186,8 +1212,7 @@ inline void log_t::append(byte *&d, const void *s, size_t size) noexcept
 }
 
 template<bool mmap>
-std::pair<lsn_t,mtr_t::page_flush_ahead>
-mtr_t::finish_writer(mtr_t *mtr, size_t len)
+std::pair<lsn_t,lsn_t> mtr_t::finish_writer(mtr_t *mtr, size_t len)
 {
   ut_ad(log_sys.is_latest());
   ut_ad(!recv_no_log_write);