Bug #56299 mutex deadlock with COM_BINLOG_DUMP, binlog purge, and processlist/kill
Submitted: 26 Aug 2010 16:16 Modified: 7 Nov 2011 17:24
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Locking Severity:S1 (Critical)
Version:5.1.50,5.5.5 OS:Any
Assigned to: Sven Sandberg
Triage: Triaged: D1 (Critical) / R4 (High) / E4 (High)

[26 Aug 2010 16:16] Shane Bester
Description:
a master server gets deadlocked and no further connections/queries can be made.
Mutexes involved:
LOCK_thread_count, LOCK_thd_data, mysys_var->current_mutex

5.1.46sp1 stack traces for a sample deadlock:
------------
thread 5148:  insert .. causing binlog rotation
------------
ntdll.dll!NtWaitForSingleObject
ntdll.dll!RtlpWaitOnCriticalSection	
ntdll.dll!RtlEnterCriticalSection
mysqld-debug.exe!log_in_use Line 213
mysqld-debug.exe!MYSQL_BIN_LOG::purge_logs_before_date Line 3639
mysqld-debug.exe!MYSQL_BIN_LOG::rotate_and_purge Line 4527
mysqld-debug.exe!MYSQL_BIN_LOG::write Line 4413
mysqld-debug.exe!THD::binlog_query Line 3912
mysqld-debug.exe!mysql_insert Line 924
mysqld-debug.exe!mysql_execute_command Line 3198
mysqld-debug.exe!mysql_parse Line 5990
mysqld-debug.exe!dispatch_command Line 1235
mysqld-debug.exe!do_command Line 874
mysqld-debug.exe!handle_one_connection Line 1134
mysqld-debug.exe!pthread_start Line 85
mysqld-debug.exe!_callthreadstart Line 295
mysqld-debug.exe!_threadstart Line 277
kernel32.dll!BaseThreadStart

waiting for pthread_mutex_lock(&LOCK_thread_count);
thread 2320 owns the mutex.

----------------
thread 2320:   reconnecting slave doing COM_BINLOG_DUMP!
------------------
ntdll.dll!NtWaitForSingleObject
ntdll.dll!RtlpWaitOnCriticalSection
ntdll.dll!RtlEnterCriticalSection	
mysqld-debug.exe!kill_zombie_dump_threads Line 1103
mysqld-debug.exe!dispatch_command Line 1436
mysqld-debug.exe!do_command Line 874
mysqld-debug.exe!handle_one_connection Line 1134
mysqld-debug.exe!pthread_start Line 85
mysqld-debug.exe!_callthreadstart Line 295
mysqld-debug.exe!_threadstart Line 277
kernel32.dll!BaseThreadStart

waiting for pthread_mutex_lock(&tmp->LOCK_thd_data);	// Lock from delete
thread 5040 holds the mutex.

-------------
thread 5040:  KILL ....
---------------
ntdll.dll!NtWaitForSingleObject
ntdll.dll!RtlpWaitOnCriticalSection
ntdll.dll!RtlEnterCriticalSection
mysqld-debug.exe!THD::awake Line 1117
mysqld-debug.exe!kill_one_thread Line 7039
mysqld-debug.exe!sql_kill Line 7063
mysqld-debug.exe!mysql_execute_command  Line 4032
mysqld-debug.exe!mysql_parse Line 5990
mysqld-debug.exe!dispatch_command Line 1273
mysqld-debug.exe!do_command Line 874
mysqld-debug.exe!handle_one_connection Line 1134
mysqld-debug.exe!pthread_start Line 85
mysqld-debug.exe!_callthreadstart Line 295
mysqld-debug.exe!_threadstart  Line 277
kernel32.dll!BaseThreadStart

waiting for pthread_mutex_lock(mysys_var->current_mutex);
thread 5148 holds the mutex.

How to repeat:
setup working master/slave pair, with --expire-logs-days=1 --max-binlog-size=4096 on master.
in 4 threads, execute the following:

---
insert into t1 values ('aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
show full processlist;
select id from information_schema.processlist order by rand() limit 1 into @a;
kill @a;
---

the slave thread will keep reconnecting as needed.  the binlog will be
rotated frequently after4k inserts are reached.
[27 Aug 2010 5:25] Shane Bester
testcase. run against a master with --max-binlog-size=4k. slave will reconnect a few times due to kill. hangup in a few seconds.

Attachment: bug56299.c (text/plain), 6.35 KiB.

[27 Aug 2010 5:31] Shane Bester
testcase will not work against 5.0 since it uses information_schema.processlist.

master is running like this:
mysqld --no-defaults --console --skip-gr --skip-na --log-bin --expire-logs-days=1 --server-id=1 --max-binlog-size=4096

slave is running like this:
mysqld --no-defaults --server-id=2 --port=3307 --skip-gr --skip-na --console

make sure the slave binlog dump thread is killed many times, and slave reconnects by itself.
[5 Nov 2010 17:00] Sven Sandberg
The deadlock happens when the following four things happen at the same time:
 - An old dump thread is waiting for the binlog to grow.
 - The slave server that replicates from the old dump thread tries to reconnect.
   During reconnection, the new dump thread tries to kill the old dump thread.
 - A KILL statement tries to kill the old dump thread.
 - An INSERT statement causes a binlog rotation.

The following lists the stacks for the four threads. Control flow go from top to bottom in the list, so the stack top is in the bottom. Lines that either do function calls or acquire a lock are listed.

old dump thread:
sql_parse:1440:dispatch_command
sql_repl.cc:668:mysql_binlog_send
log.cc:4879:MYSQL_BIN_LOG::wait_for_update
  This thread is waiting without holding any mutexes. It has just set
  THD::mysys_var::current_mutex = LOCK_log

INSERT thread:
sql_insert.cc:921:mysql_insert
sql_class.cc:3913:THD::binlog_query
log.cc:4263:MYSQL_BIN_LOG::write                   LOCK_log *
log.cc:4411:MYSQL_BIN_LOG::write
log.cc:4524:MYSQL_BIN_LOG::rotate_and_purge
log.cc:3631:MYSQL_BIN_LOG::purge_logs_before_date  LOCK_index
log.cc:3639:MYSQL_BIN_LOG::purge_logs_before_date
sql_repl.cc:215:log_in_use                         LOCK_thread_count *

COM_BINLOG_DUMP thread:
sql_parse.cc:1435:dispatch_command
sql_repl.cc:1096:kill_zombie_dump_threads          LOCK_thread_count *
sql_repl.cc:1106:kill_zombie_dump_threads          old_dump_thd.LOCK_thd_data *

KILL thread:
sql_parse.cc:4031:mysql_execute_command
sql_parse.cc:7063:sql_kill
sql_parse.cc:7014:kill_one_thread                  old_dump_thd.LOCK_thd_data *
sql_parse.cc:7038:kill_one_thread
sql_class.cc:1092:old_dump_thd.awake               old_dump_thd.mysys_var.mutex
sql_class.cc:1117:old_dump_thd.awake       old_dump_thd.mysys_var.current_mutex
                                           = LOCK_log *

Deadlock summary:
 - INSERT takes LOCK_log before LOCK_thread_count
 - COM_BINLOG_DUMP takes LOCK_thread_count before old_dump_thd.LOCK_thd_data
 - KILL takes old_dump_thd.LOCK_thd_data before LOCK_log

Which thread has wrong lock order?
 - It's probably necessary that kill_zombie_dump_threads takes
   LOCK_thread_count before old_dump_thd.LOCK_thd_data, because that prevents
   old_dump_thd from being deleted under the feet of kill_zombie_dump_threads.
 - KILL is a generic statement that probably has a reason to take locks in
   this order.
 - So the lock order should be:
     LOCK_thread_count, THD::LOCK_thd_data, LOCK_log
   So it's the log rotation that violates lock order by taking LOCK_log before
   LOCK_thread count. And in fact, it seems unnecessary to block creating or
   destroying threads just because we rotate the log.

We can fix the bug as follows:
 - Associate a counter with each binlog file.
 - Increase and decrease the counter as dump threads start or stop reading a
   log.
 - In log_in_use, just read the counter instead of iterating through all active
   threads in the system.
 - Protect the counters with LOCK_index.
 - Enforce this lock order:
   LOCK_thread_count, THD::LOCK_thd_data, LOCK_log, LOCK_index

It seems that LOCK_index is always held anyways in all places when we need to access the counters, so we are only removing complexity, not adding complexity.
[7 Nov 2011 17:24] Jon Stephens
Fixed in 5.6.4. Closed.
[7 Nov 2011 18:25] Paul Dubois
Changelog entry:

Deadlock could occur when these four things happened at the same
time: 1) An old dump thread was waiting for the binary log to grow.
2) The slave server that replicates from the old dump thread tried to
reconnect. During reconnection, the new dump thread tried to kill the
old dump thread. 3) A KILL statement tried to kill the old dump
thread. 4) An INSERT statement caused a binary log rotation.
[28 Mar 2012 11:08] Simon Mudd
Even though 5.6 may be out "soon", 5.5 is GA. So how can you close this ticket  when you fix the problem in the current "development version", without commenting on the problem that's reported in the GA MySQL 5.5 version? You even mark this as S1: Critical...
[28 Mar 2012 11:30] Shane Bester
I checked the code, and it really looks fixed in 5.5.19.

Patch is visible here:
http://lists.mysql.com/commits/141642

And listed here:
http://dev.mysql.com/doc/refman/5.5/en/news-5-5-19.html
[29 Mar 2012 5:42] Simon Mudd
Shane, thanks for checking and confirming that this is fixed in the current GA (5.5) version. That missing info is important and it is good it's now provided in this bug report.