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.
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.