Bug #121726 START REPLICA deadlocks with SET GLOBAL max_relay_log_size, max_binlog_size or gtid_mode

Submitted: 10 Nov 4:29
Reporter: Derrick Yang (OCA) Email Updates:
Status: Open Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:trunk, 8.0.40, 8.4.0, 9.7.2, 26.7.0 OS:Linux
Assigned to: CPU Architecture:Any

[10 Nov 4:29] Derrick Yang
Description:
A START REPLICA that runs at the same time as one of these statements can
deadlock the replica:

  SET GLOBAL max_relay_log_size = ...
  SET GLOBAL max_binlog_size = ...   (while max_relay_log_size = 0, the default)
  SET GLOBAL gtid_mode = ...

Once the deadlock forms:

1. START REPLICA and the SET never return.
2. KILL of the START REPLICA session hangs too, and so does every new
   client connection. Existing sessions hang on any statement that reads
   or writes a global system variable.
3. The only way out is to kill mysqld.

It affects plain asynchronous replication with an on-disk relay log; the
test below uses the default applier. No plugin or special configuration is
needed, and none of the code involved depends on the applier type.

Root cause:
This is the same three-thread cycle that was fixed for slave_net_timeout
in BUG#14236151 (Bug #65692) and for binlog_encryption in BUG#29515210 (whose comment in
Sys_var_binlog_encryption::global_update() describes it). Those fixes
were never applied to the three setters above.

  START REPLICA   holds channel_map            waits on start_cond for the new thread
  new IO/SQL thr  holds mi/rli->run_lock       waits for LOCK_global_system_variables
  SET GLOBAL ...  holds LOCK_global_system_variables   waits for channel_map

1. start_slave_cmd() takes channel_map.wrlock() (rpl_replica.cc:789) and
   keeps it for the whole statement. start_slave_thread() then waits on
   start_cond (:2085) until the new thread reports that it has started.
2. The new IO thread takes mi->run_lock (:5460) and builds its THD
   (:5465) before it broadcasts start_cond (:5493). The SQL thread does the
   same with rli->run_lock (:7161, :7165, :7329). The THD constructor calls
   THD::init() -> plugin_thdvar_init(), which takes
   LOCK_global_system_variables (sql_plugin.cc:2866).
3. sys_var::update() holds LOCK_global_system_variables around
   global_update() and the update function (set_var.cc:357-360). Three of
   those take channel_map.wrlock() while it is held:
     fix_max_binlog_size()              sys_vars.cc:2846
     fix_max_relay_log_size()           sys_vars.cc:2987
     Sys_var_gtid_mode::global_update() sys_vars.cc:4309

KILL cannot break the cycle. THD::awake() locks the victim's current_mutex
to broadcast its condition (sql_class.cc:1715-1723). For the waiting START
REPLICA, that mutex is the run_lock that the new thread holds while it
waits for LOCK_global_system_variables, so the KILL statement blocks on
it. The SET waits in a plain rwlock wait that does not check thd->killed.
The new thread is not yet in the THD manager, so it cannot be killed.

The window is open as long as START REPLICA holds channel_map. A SET that
arrives in that time blocks on channel_map while it holds
LOCK_global_system_variables. If the new thread has not finished its THD
constructor by then, the cycle closes. For START REPLICA without a thread
option, the window lasts until the SQL thread has started.

The binlog_encryption fix had a regression test,
rpl_deadlock_globalsystemvariable_channelmap. It was removed together
with the keyring_file plugin (WL#15938), so no test covers this pattern
now.

How to repeat:
Debug build. Run the attached MTR test (suite rpl, replica option file
included):

  ./mtr rpl.rpl_start_replica_setter_deadlock_repro

It uses the existing sync point after_locking_channel_map_in_start_replica
to hold START REPLICA after it has taken channel_map, so that the SET is
sure to arrive in the window. The sync point makes the window wider; it
does not create the cycle. Steps:

1. START REPLICA IO_THREAD, held at the sync point.
2. SET GLOBAL max_relay_log_size = 16384 in another session. The test
   waits until performance_schema shows that this session holds
   LOCK_global_system_variables.
3. Release START REPLICA and wait 5 s.
4. KILL the START REPLICA session and wait 5 s.
5. Try a new client connection with a 5 s timeout.
6. SIGKILL the replica and restart it, because nothing else recovers it.

Result on trunk (performance_schema output from the test):

  START REPLICA IO_THREAD   waiting for wait/synch/cond/sql/Source_info::start_cond
  replica_io                waiting for wait/synch/mutex/sql/LOCK_global_system_variables
  SET GLOBAL max_relay_log_size = 16384   still running

  LOCK_global_system_variables   held by  SET GLOBAL max_relay_log_size = 16384
  Relay_log_info::run_lock       held by  START REPLICA IO_THREAD
  Source_info::run_lock          held by  replica_io

  KILL <start_id>           waiting for wait/synch/mutex/sql/Source_info::run_lock
  new connection exit code: 124   (killed by the timeout)

The same deadlock also happens with:
- SET GLOBAL max_binlog_size = 8192 (max_relay_log_size = 0)
- SET GLOBAL gtid_mode = ON_PERMISSIVE (from ON)
- START REPLICA SQL_THREAD with SET GLOBAL max_relay_log_size

SET GLOBAL replica_net_timeout, which already has the BUG#14236151 fix,
does not deadlock in the same sequence.

Suggested fix:
Apply the BUG#14236151 / BUG#29515210 fix to the three setters: release
LOCK_global_system_variables before channel_map.wrlock() and take it
again before returning. The AutoWLock in sys_var::update() unlocks it at
scope exit. The attached patch (sql/sys_vars.cc only, +48 -23) does this.

1. max_relay_log_size and max_binlog_size. Both update functions call a
   new helper, which reads both variables after it takes channel_map.
   Concurrent setters are serialized by channel_map, so every relay log
   ends up with the value written last. fix_replica_net_timeout() also
   reads its variable inside channel_map without
   LOCK_global_system_variables. mysql_bin_log.set_max_size() stays under
   LOCK_global_system_variables.

     static void update_relay_log_max_sizes() {
       mysql_mutex_assert_owner(&LOCK_global_system_variables);
       mysql_mutex_unlock(&LOCK_global_system_variables);

       channel_map.wrlock();
       const ulong size = max_relay_log_size ? max_relay_log_size : max_binlog_size;
       for (mi_map::iterator it = channel_map.begin(); it != channel_map.end();
            it++) {
         Master_info *mi = it->second;
         if (mi != nullptr) mi->rli->relay_log.set_max_size(size);
       }
       channel_map.unlock();

       mysql_mutex_lock(&LOCK_global_system_variables);
     }

2. gtid_mode. Release LOCK_global_system_variables after
   Gtid_mode::lock.trywrlock() succeeds and before channel_map.wrlock().
   Take it again at the end of the shared err: exit, after
   global_tsid_lock, LOCK_log, channel_map and Gtid_mode::lock are
   released. All paths after channel_map.wrlock() leave through err:.
   Gtid_mode::lock still rejects a concurrent SET gtid_mode.
   LOCK_global_system_variables must not be taken again while LOCK_log is
   held, because fix_max_binlog_size() takes LOCK_log while it holds
   LOCK_global_system_variables.

Limitations:
With this change Gtid_mode::sysvar_mode, the storage shown by
@@GLOBAL.gtid_mode, is written without LOCK_global_system_variables.
No server logic reads it after startup (the server uses
global_gtid_mode, which is still set under all four locks). Readers
see the old or the new value, and no longer block during the binary
log rotation that follows.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.060 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.