Bug #62614 Server deadlock between RESET MASTER and PURGE BINARY LOGS
Submitted: 4 Oct 2011 8:46 Modified: 4 Jul 2014 6:41
Reporter: Kristian Nielsen Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.5.17, 5.6, 5.7 OS:Any
Assigned to: CPU Architecture:Any

[4 Oct 2011 8:46] Kristian Nielsen
Description:
PURGE BINARY LOGS takes mutexes in the wrong order, which can cause the entire
server to deadlock:

bool MYSQL_BIN_LOG::reset_logs(THD* thd)
{
  /*
    The following mutex is needed to ensure that no threads call
    'delete thd' as we would then risk missing a 'rollback' from this
    thread. If the transaction involved MyISAM tables, it should go
    into binlog even on rollback.
  */
  mysql_mutex_lock(&LOCK_thread_count);

  mysql_mutex_lock(&LOCK_log);
  mysql_mutex_lock(&LOCK_index);

Other parts of the server, for example RESET MASTER, take locks in the
opposite order (first LOCK_index then LOCK_thread_count). Thus a deadlock is
possible.

This was reproduced in MySQL 5.5.17 with this bzr revision:

    revid:vasil.dimov@oracle.com-20110909071254-jb86bz87bx33zyje

Note that since the deadlock involves LOCK_thread_count, when it occurs it
blocks any new queries from running.

How to repeat:
Here is a test case that reproduces the deadlock, hanging the server hard.

Since this is a race condition, the test case uses DEBUG_SYNC to reliably
reproduce the problem. I was actually able to reproduce without DEBUG_SYNC on
my machine (just delete all use of DEBUG_SYNC from the test case), however
this may or may not work on another machine/os/whatever.

To use the DEBUG_SYNC testcase, apply this patch:

=== modified file 'sql/log.cc'
--- sql/log.cc	2011-07-03 23:48:19 +0000
+++ sql/log.cc	2011-10-04 07:28:36 +0000
@@ -38,6 +38,7 @@
 #include "rpl_filter.h"
 #include "rpl_rli.h"
 #include "sql_audit.h"
+#include "debug_sync.h"
 
 #include <my_dir.h>
 #include <stdarg.h>
@@ -3373,6 +3374,7 @@ bool MYSQL_BIN_LOG::reset_logs(THD* thd)
 
   ha_reset_logs(thd);
 
+  DEBUG_SYNC(thd, "reset_logs_before_LOCK_thread_count");
   /*
     The following mutex is needed to ensure that no threads call
     'delete thd' as we would then risk missing a 'rollback' from this
@@ -3381,6 +3383,8 @@ bool MYSQL_BIN_LOG::reset_logs(THD* thd)
   */
   mysql_mutex_lock(&LOCK_thread_count);
 
+  DEBUG_SYNC(thd, "reset_logs_after_LOCK_thread_count");
+
   /*
     We need to get both locks to be sure that no one is trying to
     write to the index log file.
@@ -3670,8 +3674,10 @@ int MYSQL_BIN_LOG::purge_logs(const char
   DBUG_ENTER("purge_logs");
   DBUG_PRINT("info",("to_log= %s",to_log));
 
+  DEBUG_SYNC(thd, "purge_logs_before_LOCK_index");
   if (need_mutex)
     mysql_mutex_lock(&LOCK_index);
+  DEBUG_SYNC(thd, "purge_logs_after_LOCK_index");
   if ((error=find_log_pos(&log_info, to_log, 0 /*no mutex*/))) 
   {
     sql_print_error("MYSQL_BIN_LOG::purge_logs was called with file %s not "

Then run this test case:

--source include/have_log_bin.inc
--source include/have_debug_sync.inc

# Test case to reproduce a deadlock in binlog handling.
# RESET MASTER locks first LOCK_index and then LOCK_thread_count
# PURGE BINARY LOGS locks first LOCK_thread_count and LOCK_index.
# This can lead to deadlock if the two commands run in parallel, with
# one thread waiting to get LOCK_index and the other waiting for
# LOCK_thread_count

--connect(con1,localhost,root,,)
--connect(con2,localhost,root,,)

connection default;
CREATE TABLE t1 (a INT PRIMARY KEY);
FLUSH LOGS;
INSERT INTO t1 VALUES (1);
FLUSH LOGS;
INSERT INTO t1 VALUES (2);
FLUSH LOGS;
SHOW BINARY LOGS;

# Start a PURGE BINARY LOGS, pausing just before it takes the first lock.
connection con1;
SET DEBUG_SYNC= "purge_logs_before_LOCK_index SIGNAL con1_ready1 WAIT_FOR con1_cont1";
SET DEBUG_SYNC= "purge_logs_after_LOCK_index SIGNAL con1_ready2 WAIT_FOR con1_cont2 TIMEOUT 5";
send PURGE BINARY LOGS TO "master-bin.000002";
connection default;
SET DEBUG_SYNC= "now WAIT_FOR con1_ready1";

# Start RESET MASTER, pausing just before it takes the first lock.
connection con2;
SET DEBUG_SYNC= "reset_logs_before_LOCK_thread_count SIGNAL con2_ready1 WAIT_FOR con2_cont1";
send RESET MASTER;
connection default;
SET DEBUG_SYNC= "now WAIT_FOR con2_ready1";

connection default;
# Let PURGE BINARY LOGS take the first lock
SET DEBUG_SYNC= "now SIGNAL con1_cont1";
SET DEBUG_SYNC= "now WAIT_FOR con1_ready2";
# Now let con2 continue. It will take LOCK_thread_count and then wait for
# con1 to release LOCK_index.
# After 5 seconds con1 will timeout and then wait for con2 to release
# LOCK_thread_count -> deadlock.
SET DEBUG_SYNC= "now SIGNAL con2_cont1";

connection con1;
reap;
connection con2;
reap;
DROP TABLE t1;

The test case will time out due to the deadlock. The "analyze timeout" will
fail due to LOCK_thread_count blocking all queries from running. Manually
attaching gdb while the test case is running and doing `thread apply all bt`
will show how it is deadlocked.

Suggested fix:
An easy fix is to change MYSQL_BIN_LOG::reset_logs() to only lock
LOCK_thread_count _after_ LOCK_index.

But it is not clear to me if this still ensures that we do not miss a
rollback, as per the comment in the function.
[4 Oct 2011 9:48] Kristian Nielsen
It seems this was introduced with this commit:

revision-id: sven.sandberg@oracle.com-20110526105043-wykkmpktyye2kav6
parent: sergey.glukhov@oracle.com-20110526100639-o3tcac0chgy9m9ij
committer: Sven Sandberg <sven.sandberg@oracle.com>
branch nick: 5.1
timestamp: Thu 2011-05-26 12:50:43 +0200
message:
  BUG#12574820: binlog.binlog_tmp_table timing out in daily and weekly trunk run
  Problem: MYSQL_BIN_LOG::reset_logs acquires mutexes in wrong order.
  The correct order is first LOCK_thread_count and then LOCK_log. This function
  does it the other way around. This leads to deadlock when run in parallel
  with a thread that takes the two locks in correct order. For example, a thread
  that disconnects will take the locks in the correct order.
  Fix: change order of the locks in MYSQL_BIN_LOG::reset_logs:
  first LOCK_thread_count and then LOCK_log.

But I think it is wrong that LOCK_thread_count should be locked before
LOCK_index/LOCK_log. The LOCK_thread_count is a short-lived lock, holding it
blocks _all_ threads from starting a new query. LOCK_log is a long log, it is
held while doing I/O.

I could not find where a disconnecting thread will lock LOCK_log while holding
LOCK_thread_count, however if there is such a place I would suggest the
correct fix is to switch the locking order in the disconnecting thread.

In any case there are more places where LOCK_index is taken before
LOCK_thread_count. For example MYSQL_BIN_LOG::purge_logs() which calls
log_in_use(); the former holds LOCK_index and the latter takes
LOCK_thread_count.
[12 Sep 2013 18:53] MySQL Verification Team
Still happens on todays 5.7.3 code:

Thread 1: reset master
Thread 2: purge master logs before now()

Thread 1 waits for thread 2
Thread 2 waits for thread 1

Thread 1:
---------
Owns LOCK_thread_count
Owns LOCK_log
Waits for LOCK_index

	ntdll.dll!ZwWaitForSingleObject
	ntdll.dll!RtlpWaitOnCriticalSection
	ntdll.dll!RtlEnterCriticalSection
	mysqld-debug.exe!inline_mysql_mutex_lock
	mysqld-debug.exe!MYSQL_BIN_LOG::reset_logs
	mysqld-debug.exe!reset_master
	mysqld-debug.exe!reload_acl_and_cache
	mysqld-debug.exe!mysql_execute_command
	mysqld-debug.exe!mysql_parse
	mysqld-debug.exe!dispatch_command
	mysqld-debug.exe!do_command
	mysqld-debug.exe!handle_connection
	mysqld-debug.exe!pfs_spawn_thread
	mysqld-debug.exe!pthread_start
	mysqld-debug.exe!_callthreadstartex
	mysqld-debug.exe!_threadstartex

Thread 2:
---------
Owns LOCK_index
Waits for LOCK_thread_count

	ntdll.dll!ZwWaitForSingleObject
	ntdll.dll!RtlpWaitOnCriticalSection
	ntdll.dll!RtlEnterCriticalSection
	mysqld-debug.exe!inline_mysql_mutex_lock
	mysqld-debug.exe!log_in_use
	mysqld-debug.exe!MYSQL_BIN_LOG::purge_logs_before_date
	mysqld-debug.exe!purge_master_logs_before_date
	mysqld-debug.exe!mysql_execute_command
	mysqld-debug.exe!mysql_parse
	mysqld-debug.exe!dispatch_command
	mysqld-debug.exe!do_command
	mysqld-debug.exe!handle_connection
	mysqld-debug.exe!pfs_spawn_thread
	mysqld-debug.exe!pthread_start
	mysqld-debug.exe!_callthreadstartex
	mysqld-debug.exe!_threadstartex
[12 Sep 2013 18:58] MySQL Verification Team
cross referencing another deadlock problem:
http://bugs.mysql.com/bug.php?id=69954
[4 Jul 2014 6:41] Venkatesh Duggirala
This issue is fixed as part of bug#69954
(which is fixed in  5.5.39, 5.6.20, and 5.7.5 )