Bug #101200 All commits are unnecessarily blocked for more than 1ms at binlog rotate
Submitted: 16 Oct 2020 3:25 Modified: 16 Oct 2020 11:46
Reporter: Yoshinori Matsunobu (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S5 (Performance)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any

[16 Oct 2020 3:25] Yoshinori Matsunobu
Description:
On binlog file rotate, MYSQL_BIN_LOG::new_file_impl() is called, and it calls ha_flush_logs() with LOCK_log mutex as follows.

```
  mysql_mutex_assert_owner(&LOCK_log);
  mysql_mutex_assert_owner(&LOCK_index);

  if (DBUG_EVALUATE_IF("expire_logs_always", 0, 1) &&
      (error = ha_flush_logs())) {
    goto end;
  }
```

ha_flush_logs() calls innobase_flush_logs(), which calls gtid_persistor.wait_flush(true, true, true, nullptr). Clone_persist_gtid::wait_flush() calls Clone_persist_gtid::wait_thread(), and it calls Clone_Sys::wait() defined at storage/innobase/include/clone0clone.h.

The wait() function is defined like this (you can see from clone0clone.h).

```
    int err = 0;
    bool wait = true;
    is_timeout = false;

    /* Call function once before waiting. */
    err = func(false, wait);

    while (!is_timeout && wait && err == 0) {
...
      std::this_thread::sleep_for(sleep_time);
...

The "func" is wait_cond defined at Clone_persist_gtid::wait_thread(). It returns 0 when it does not need to wait. So the while condition ("!is_timeout && wait && err == 0") is almost always true, so it enters sleep_for() even though it is not necessary. The sleep_time is 1ms which is defined at Clone_persist_gtid::wait_thread() too.

The problem is the entire functions are executed during holding LOCK_log mutex. So all other commits are blocked for at least 1ms.

How to repeat:
Run any write intensive benchmarks and rotating binlogs. Run some off cpu profilers like offcputime.py. Or you may just confirm by gdb and flushing logs.

Suggested fix:
Don't sleep while holding a global mutex, if it's not necessary.
[16 Oct 2020 11:46] MySQL Verification Team
Hi Mr. Matsunobu,

Thank you for your performance enhancement request.

We have studied your code analysis and we agree with you fully.

Verified as reported.