MySQL Bugs: #69954: 4-way deadlock: zombies, purging binlogs, show processlist, show binlogs

Bug #69954	4-way deadlock: zombies, purging binlogs, show processlist, show binlogs
Submitted:	7 Aug 2013 15:31	Modified:	23 Jun 2014 15:50
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.5.34	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	deadlock, expire_logs_days, hang

Description:
Thread1: a reconnecting slave
Thread2: show processlist
Thread3: dml doing binlog rotation due to expire_logs_days
Thread4: show binlogs

Thread1 waits for Thread4
Thread4 waits for Thread3
Thread3 waits for Thread2
Thread2 waits for Thread1

Thread1:
--------
Waits for mysys_var->current_mutex (owned by Thread4)
Owns tmp->LOCK_thd_data

	ntdll.dll!ZwWaitForSingleObject
	ntdll.dll!RtlpWaitOnCriticalSection
	ntdll.dll!RtlEnterCriticalSection
	mysqld.exe!inline_mysql_mutex_lock
	mysqld.exe!THD::awake
	mysqld.exe!kill_zombie_dump_threads
	mysqld.exe!dispatch_command
	mysqld.exe!do_command
	mysqld.exe!do_handle_one_connection
	mysqld.exe!handle_one_connection
	mysqld.exe!pthread_start
	mysqld.exe!_callthreadstartex
	mysqld.exe!_threadstartex
	kernel32.dll!BaseThreadInitThunk
	ntdll.dll!RtlUserThreadStart

Thread2:
--------
Waits for tmp->LOCK_thd_data (owned by Thread1)
Owns LOCK_thread_count

	ntdll.dll!ZwWaitForSingleObject
	ntdll.dll!RtlpWaitOnCriticalSection
	ntdll.dll!RtlEnterCriticalSection
	mysqld.exe!inline_mysql_mutex_lock
	mysqld.exe!mysqld_list_processes
	mysqld.exe!mysql_execute_command
	mysqld.exe!mysql_parse
	mysqld.exe!dispatch_command
	mysqld.exe!do_command
	mysqld.exe!do_handle_one_connection
	mysqld.exe!handle_one_connection
	mysqld.exe!pthread_start
	mysqld.exe!_callthreadstartex
	mysqld.exe!_threadstartex
	kernel32.dll!BaseThreadInitThunk
	ntdll.dll!RtlUserThreadStart

Thread3:
--------
Waits for LOCK_thread_count (owned by Thread2)
Owns LOCK_index

	mysqld.exe!inline_mysql_mutex_lock
	mysqld.exe!log_in_use
	mysqld.exe!MYSQL_BIN_LOG::purge_logs_before_date
	mysqld.exe!MYSQL_BIN_LOG::purge
	mysqld.exe!MYSQL_BIN_LOG::rotate_and_purge
	mysqld.exe!MYSQL_BIN_LOG::unlog
	mysqld.exe!ha_commit_trans
	mysqld.exe!trans_commit_stmt
	mysqld.exe!mysql_execute_command
	mysqld.exe!mysql_parse
	mysqld.exe!dispatch_command
	mysqld.exe!do_command
	mysqld.exe!do_handle_one_connection
	mysqld.exe!handle_one_connection
	mysqld.exe!pthread_start
	mysqld.exe!_callthreadstartex
	mysqld.exe!_threadstartex
	kernel32.dll!BaseThreadInitThunk
	ntdll.dll!RtlUserThreadStart

Thread4:
--------
Waits for LOCK_index (owned by Thread3)
Owns mysys_var->current_mutex

	mysqld.exe!inline_mysql_mutex_lock
	mysqld.exe!MYSQL_BIN_LOG::lock_index
	mysqld.exe!show_binlogs
	mysqld.exe!mysql_execute_command
	mysqld.exe!mysql_parse
	mysqld.exe!dispatch_command
	mysqld.exe!do_command
	mysqld.exe!do_handle_one_connection
	mysqld.exe!handle_one_connection
	mysqld.exe!pthread_start
	mysqld.exe!_callthreadstartex
	mysqld.exe!_threadstartex
	kernel32.dll!BaseThreadInitThunk
	ntdll.dll!RtlUserThreadStart

Verified on 5.5.23 and 5.5.34 master.
Because LOCK_thread_count is involved, no new connections can be 
made and kill -9 is the only way out.

How to repeat:
It can take some time to repeat.

1. Setup master/slave replication with --max_binlog_size=4k --expire_logs_days=1

2. Run against the master:
   insert into ....
   show processlist
   show binary logs

3. Run against the slave:   stop slave;   start slave;  select sleep(1);

Also affects 5.6.14

cross referencing another replication deadlock http://bugs.mysql.com/bug.php?id=62614

Documented fix as follows in the 5.5.39, 5.6.20, and 5.7.5 changelogs:
  A group of threads involved in acquiring locks could deadlock when the
  following events occurred:
  
    -Dump thread reconnects from slave; on master, a new dump thread tries
    to kill zombie dump threads; having acquired thread's LOCK_thd_data,
    it is about to acquire mysys_var->current_mutex ( which LOCK_log)
  
    -Application thread executing show binary logs, having acquired
    LOCK_log and about to acquire LOCK_index.
  
    -Application thread executing PURGE BINARY LOGS; having acquired
  LOCK_index, it is about to acquire LOCK_thread_count.
  
    -Application thread executing show processlist (or SELECT * FROM
  INFORMATION_SCHEMA.PROCESSLIST), having acquired LOCK_thread_count and
  about to acquire zombie dump thread's LOCK_thd_data.
  
  This leads to the 4 threads deadlocking in the same order which the
  threads are listed.
  
  This problem arises because there are ordering rules for LOCK_log and
  LOCK_index, as well as rules for ordering LOCK_thread_count and
  LOCK_thd_data, but there are no rules for ordering across these two sets
  of locks. This was because the internal mysqld_list_processes() function
  invoked by SHOW PROCESSES acquired LOCK_thread_count for the complete
  lifetime of the function as well as acquiring and releasing each
  thread's LOCK_thd_data. Now this function takes a copy of the threads
  from the global thread list and performs its traversal on these only
  after releasing LOCK_thread_count. During this traversal, removal from
  the global thread list is blocked using LOCK_thd_remove such that the
  copies the would otherwise be destroyed by the removal remain valid
  during traversal. The locking order following this fix is shown here:

LOCK_thd_remove -> LOCK_thd_data ->
   LOCK_log -> LOCK_index -> LOCK_thread_count

Closed.

Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Bug#62614 is fixed as part of this bug

Good stuff.

5.5 $ bzr log -r 4640
------------------------------------------------------------
revno: 4640
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.5
timestamp: Thu 2014-05-08 18:13:01 +0530
message:
  Bug#17283409  4-WAY DEADLOCK: ZOMBIES, PURGING BINLOGS,
  SHOW PROCESSLIST, SHOW BINLOGS
  
  Problem:  A deadlock was occurring when 4 threads were
  involved in acquiring locks in the following way
  Thread 1: Dump thread ( Slave is reconnecting, so on
                Master, a new dump thread is trying kill
                zombie dump threads. It acquired thread's
                LOCK_thd_data and it is about to acquire
                mysys_var->current_mutex ( which LOCK_log)
  Thread 2: Application thread is executing show binlogs and
                 acquired LOCK_log and it is about to acquire
                 LOCK_index.
  Thread 3: Application thread is executing Purge binary logs
                 and acquired LOCK_index and it is about to
                 acquire LOCK_thread_count.
  Thread 4: Application thread is executing show processlist
                 and acquired LOCK_thread_count and it is
                 about to acquire zombie dump thread's
                 LOCK_thd_data.
  Deadlock Cycle:
       Thread 1 -> Thread 2 -> Thread 3-> Thread 4 ->Thread 1
  
  The same above deadlock was observed even when thread 4 is
  executing 'SELECT * FROM information_schema.processlist' command and
  acquired LOCK_thread_count and it is about to acquire zombie
  dump thread's LOCK_thd_data.
  
  Analysis:
  There are four locks involved in the deadlock.  LOCK_log,
  LOCK_thread_count, LOCK_index and LOCK_thd_data.
  LOCK_log, LOCK_thread_count, LOCK_index are global mutexes
  where as LOCK_thd_data is local to a thread.
  We can divide these four locks in two groups.
  Group 1 consists of LOCK_log and LOCK_index and the order
  should be LOCK_log followed by LOCK_index.
  Group 2 consists of other two mutexes
  LOCK_thread_count, LOCK_thd_data and the order should
  be LOCK_thread_count followed by LOCK_thd_data.
  Unfortunately, there is no specific predefined lock order defined
  to follow in the MySQL system when it comes to locks across these
  two groups. In the above problematic example,
  there is no problem in the way we are acquiring the locks
  if you see each thread individually.
  But If you combine all 4 threads, they end up in a deadlock.
  
  Fix: 
  Since everything seems to be fine in the way threads are taking locks,
  In this patch We are changing the duration of the locks in Thread 4
  to break the deadlock. i.e., before the patch, Thread 4
  ('show processlist' command) mysqld_list_processes()
  function acquires LOCK_thread_count for the complete duration
  of the function and it also acquires/releases
  each thread's LOCK_thd_data.
  
  LOCK_thread_count is used to protect addition and
  deletion of threads in global threads list. While show
  process list is looping through all the existing threads,
  it will be a problem if a thread is exited but there is no problem
  if a new thread is added to the system. Hence a new mutex is
  introduced "LOCK_thd_remove" which will protect deletion
  of a thread from global threads list. All threads which are
  getting exited should acquire LOCK_thd_remove
  followed by LOCK_thread_count. (It should take LOCK_thread_count
  also because other places of the code still thinks that exit thread
  is protected with LOCK_thread_count. In this fix, we are changing
  only 'show process list' query logic )
  (Eg: unlink_thd logic will be protected with
  LOCK_thd_remove).
  
  Logic of mysqld_list_processes(or file_schema_processlist)
  will now be protected with 'LOCK_thd_remove' instead of
  'LOCK_thread_count'.
  
  Now the new locking order after this patch is:
  LOCK_thd_remove -> LOCK_thd_data -> LOCK_log ->
  LOCK_index -> LOCK_thread_count

5.5 $ bzr log -r 4641   
------------------------------------------------------------
revno: 4641
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.5
timestamp: Fri 2014-05-09 09:52:15 +0530
message:
  Bug#17283409  4-WAY DEADLOCK: ZOMBIES, PURGING BINLOGS,
  SHOW PROCESSLIST, SHOW BINLOGS
  
  Fixing post push test failure (MTR does not like giving
  127.0.0.1 for localhost incase of --embedded run, it thinks
  it is an external ip address)

Is it possible for a server kill thread to become Thread 4 in the commit message scenario and thus be affected by the same issue? close_connections in mysqld.cc locks LOCK_thread_count and then all the individual LOCK_thd_data.

Or is it guaranteed that at least one of Thread 1 - 3 may not exist then?

To answer my own question, bug 73531.

How can we conclude that 'mysys_var->current_mutex' and 'LOCK_log' are the same data?