Bug #94664 Binlog related deadlock leads to all incoming connection choked.
Submitted: 15 Mar 2019 3:24 Modified: 21 Mar 2019 0:37
Reporter: Yanmin Qiao Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.7.24 OS:Any
Assigned to: CPU Architecture:Any
Tags: binlog, deadlock

[15 Mar 2019 3:24] Yanmin Qiao
Description:
Binlog related deadlock leads to all incoming connection choked.

The binlog deadlock involves three locks:
LOCK_index, LOCK_log and a thd's LOCK_thd_data.

and involves three connection handling threads:
- Thread1 ran "PURGE BINARY LOGS BEFORE ..."
- Thread2 ran "SHOW BINARY LOGS"
- Thread3 ran "SHOW VARIABLES"

The backtrace of the deadlocked threads:

Thread1 (PURGE BINARY LOGS BEFORE ...)

inline_mysql_mutex_lock
Adjust_offset::operator()                       BLOCKED-ON thd->LOCK_thd_data (thd 0x000000052dd4d000)
Do_THD::operator()
std::for_each
Global_THD_manager::do_for_all_thd
adjust_linfo_offsets
MYSQL_BIN_LOG::remove_logs_from_index
MYSQL_BIN_LOG::purge_logs
MYSQL_BIN_LOG::purge_logs_before_date           LOCKED LOCK_index
purge_master_logs_before_date
mysql_execute_command
mysql_parse
dispatch_command
do_command
handle_connection

-----------

Thread2 (SHOW BINARY LOGS)

native_mutex_lock
my_mutex_lock
inline_mysql_mutex_lock
MYSQL_BIN_LOG::lock_index
show_binlogs                                    LOCKED LOCK_log; BLOCKED-ON LOCK_index
mysql_execute_command
mysql_parse
dispatch_command
do_command
handle_connection

-----------

Thread3 (SHOW VARIABLES)

native_mutex_lock
my_mutex_lock
inline_mysql_mutex_lock
PolyLock_lock_log::rdlock                       BLOCKED-ON LOCK_log
AutoRLock::{ctor}
sys_var::value_ptr
get_one_variable_ext
System_variable::init                           ***** LOCKED LOCK_global_system_variables
System_variable::System_variable
PFS_system_variable_cache::do_materialize_all   LOCKED thd->LOCK_thd_data (thd 0x000000052dd4d000)
table_session_variables::rnd_init
ha_perfschema::rnd_init
handler::ha_rnd_init
init_read_record
join_init_read_record
sub_select
do_select
JOIN::exec
TABLE_LIST::materialize_derived
join_materialize_derived
QEP_TAB::prepare_scan
sub_select
do_select
JOIN::exec
handle_query
execute_sqlcom_select
mysql_execute_command
mysql_parse
dispatch_command
do_command
handle_connection

-----------

Since Thread3 was blocked on LOCK_log while holding LOCK_global_system_variables, all new
connection handling threads were blocked on the LOCK_global_system_variables, example backtrace
of the incoming connection thread:

native_mutex_lock
my_mutex_lock
inline_mysql_mutex_lock
THD::init                                       BLOCKED-ON LOCK_global_system_variables
THD::THD
Channel_info::create_thd
Channel_info_tcpip_socket::create_thd
init_new_thd
handle_connection

How to repeat:
Create three connections:
- connection1 run "PURGE BINARY LOGS BEFORE ..."
- connection2 run "SHOW BINARY LOGS"
- connection3 run "SHOW VARIABLES"

Repeat until the deadlock happens.  When this deadlock happens, no connection will be established.
[19 Mar 2019 16:01] MySQL Verification Team
Hi,
verified in first try. Thanks for the report
Bogdan
[20 Mar 2019 2:40] Yanmin Qiao
Here is our proposed fix.  Made by Howard Su.

Attachment: junsu_binlog_lock_order.diff (application/octet-stream, text), 566 bytes.

[20 Mar 2019 3:37] MySQL Verification Team
Hi,

In order to submit contributions you must first sign the Oracle Contribution Agreement (OCA).
For additional information please check http://www.oracle.com/technetwork/community/oca-486395.html.
If you have any questions, please contact the MySQL community team. 

all best
Bogdan
[20 Mar 2019 23:02] Sveta Smirnova
Isn't it duplicate of bug #92108?
[21 Mar 2019 0:37] MySQL Verification Team
Good find Sveta, I missed that one.

It is duplucate of https://bugs.mysql.com/bug.php?id=92108 (fixed in 5.7.25)