Bug #92108 Deadlock by concurrent show binlogs, pfs session_variables table & binlog purge
Submitted: 21 Aug 2018 17:48 Modified: 1 Oct 2018 19:36
Reporter: Shashank Sahni (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S2 (Serious)
Version:5.7.22 OS:Any
Assigned to: CPU Architecture:Any
Tags: binlog, performance_schema

[21 Aug 2018 17:48] Shashank Sahni
Description:
While running MySQL 5.7.22, we noticed occasional MySQL freezes across our fleet. Troubleshooting revealed that it was a deadlock between
1. show binlog
2. select query on performance_schema.session_variables table
3. binlog purge operation

The locking order is
1. show binlog - has LOCK_log, waiting_for LOCK_index
2. PFS_system_variable_cache::do_materialize_all - has LOCK_thd_data, LOCK_global_status_variables. waiting_for LOCK_log
3. MYSQL_BIN_LOG::purge_logs_before_data - has LOCK_index, LOCK_thd_list. waiting_for LOCK_thd_data

I am sure that this is only affecting 5.7.22 since two variables were introduced in this version
- binlog_transaction_dependency_tracking
- binlog_transaction_dependency_history_size
They are special because they are the only system variables which require a lock on the binary log, `LOCK_Log`, even when they are being read. This in combination with reading these through session variables. i.e. running  `show variables...` instead of `show global variables`, a `show binlog` and a `purge operation` causes the deadlock.

Furthermore, due to the intermediate locks - LOCK_global_status_variables and LOCK_thd_list, thread initializatioin and removal is stalled too, causing all connect attempts hanging and no cleanup during a connection close. Due to latter, its common to notice a lot of TCP connections in CLOSE_WAIT state.

1. THD::init is waiting_for LOCK_global_system_variables.
2. Global_THD_manager::remove_thd is waiting_for LOCK_thd_list.

Here is a trace using pt-pmp.

=============================
185 __lll_lock_wait(libpthread.so.0),_L_lock_1081(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::init,THD::THD,Channel_info::create_thd,Channel_info_local_socket::create_thd,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
     80 __lll_lock_wait(libpthread.so.0),_L_lock_1081(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::init,THD::THD,Channel_info::create_thd,Channel_info_tcpip_socket::create_thd,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
     18 libaio::??(libaio.so.1),LinuxAIOHandler::collect,LinuxAIOHandler::poll,os_aio_handler,fil_aio_wait,io_handler_thread,start_thread(libpthread.so.0),clone(libc.so.6)
     11 poll(libc.so.6),vio_io_wait,vio_socket_io_wait,vio_read,::??,::??,my_net_read,Protocol_classic::read_packet,Protocol_classic::get_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      8 nanosleep(libpthread.so.0),os_thread_sleep,buf_lru_manager,start_thread(libpthread.so.0),clone(libc.so.6)
      7 pthread_cond_wait,os_event::wait_low,srv_worker_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      5 __lll_lock_wait(libpthread.so.0),_L_lock_1081(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),Global_THD_manager::remove_thd,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      3 pthread_cond_wait,os_event::wait_low,buf_flush_page_cleaner_worker,start_thread(libpthread.so.0),clone(libc.so.6)
      1 sigwait(libpthread.so.0),signal_hand,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 sigwaitinfo(libc.so.6),::??,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,srv_purge_coordinator_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_resize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_dump_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,Event_queue::cond_wait,Event_queue::get_top_for_execution_if_time,Event_scheduler::run,event_scheduler_thread,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,compress_gtid_table,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_error_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,lock_wait_timeout_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,ib_wqueue_timedwait,fts_optimize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,dict_stats_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,audit_log::??(audit_log.so),start_thread(libpthread.so.0),clone(libc.so.6)
      1 poll(libc.so.6),vio_io_wait,vio_socket_io_wait,vio_read,vio_read_buff,::??,::??,my_net_read,cli_safe_read_with_ok,handle_slave_io,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event,mysqld_main,__libc_start_main(libc.so.6),_start
      1 nanosleep(libpthread.so.0),os_thread_sleep,srv_master_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_909(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),show_binlogs,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_909(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),PolyLock_lock_log::rdlock,sys_var::value_ptr,get_one_variable_ext,System_variable::init,PFS_system_variable_cache::do_materialize_all,table_session_variables::rnd_init,ha_perfschema::rnd_init,handler::ha_rnd_init,init_read_record,join_init_read_record,sub_select,JOIN::exec,TABLE_LIST::materialize_derived,join_materialize_derived,QEP_TAB::prepare_scan,sub_select,JOIN::exec,handle_query,::??,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_909(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),Binlog_sender::run,mysql_binlog_send,com_binlog_dump,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_1081(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),Log_in_use::operator,Global_THD_manager::do_for_all_thd,MYSQL_BIN_LOG::purge_logs_before_date,MYSQL_BIN_LOG::purge,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit,Xid_log_event::do_commit,Xid_apply_log_event::do_apply_event,Log_event::apply_event,apply_event_and_update_pos,handle_slave_sql,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
=====================================

How to repeat:
I've setup a test using mysql test suite which reproduces this problem on 5.7.22. PFA the patch.

Suggested fix:
The only problem I see here is the requirement of LOCK_log as rdlock() by the new system variables
- binlog_transaction_dependency_tracking
- binlog_transaction_dependency_history_size

They use PolyLock_lock_log which acquires LOCK_log as part of rdlock(). I am not sure if this lock is required for read operations too.

I would be happy to contribute a fix for this issue but would need guidance from MySQL developers to identify the incorrect behavior and for implementing the fix.
[21 Aug 2018 17:51] Shashank Sahni
Test to reproduce this deadlock

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: binlog_deadlock.patch (application/octet-stream, text), 3.96 KiB.

[21 Aug 2018 17:54] Shashank Sahni
This test contributed is based on a similar deadlock bug test case in percona's mysql distribution
https://github.com/percona/percona-server/pull/1305/files
[22 Aug 2018 7:35] Shane Bester
https://bugs.mysql.com/bug.php?id=91941
[22 Aug 2018 12:04] Sinisa Milivojevic
Hi,

Thank you for your bug report.

This seems like a duplicate of the bug:

https://bugs.mysql.com/bug.php?id=91941

However, since this report is much more clear and is a bit different, I will set it to "Verified" and not to "Duplicate".
[28 Aug 2018 22:52] Shashank Sahni
Any updates here. The issue I see here is the requirement of Lock_log while reading sys_variables. Here is the relevant Polylock_lock_log defined in sys_var.c

void PolyLock_lock_log::rdlock()
{
  mysql_mutex_lock(mysql_bin_log.get_log_lock());
}

Currently, only the two "binlog_transaction_dependency_*" variables use it. Could someone confirm if the log_lock needs to be acquired for reading these sys variables too?

Ref - https://github.com/mysql/mysql-server/blob/mysql-5.7.22/sql/sys_vars.cc#L3588-L3591
[29 Aug 2018 11:33] Sinisa Milivojevic
Yes, it has to be acquired for safety reasons. But, it is a read lock only ......
[19 Sep 2018 21:26] Stephen Griffin
Any update on this issue? Running into the same problem when mysql just hangs.

[root@tr2-mysql01 (sandbox) data]# pt-pmp -b mysqld
Wed Sep 19 11:20:18 EDT 2018
   1218 __lll_lock_wait(libpthread.so.0),_L_lock_1022(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::init,THD::THD,Channel_info::create_thd,Channel_info_tcpip_socket::create_thd,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
    269 __lll_lock_wait(libpthread.so.0),_L_lock_1022(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::init,THD::THD,Channel_info::create_thd,Channel_info_local_socket::create_thd,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
     10 nanosleep(libpthread.so.0),os_thread_sleep,buf_lru_manager,start_thread(libpthread.so.0),clone(libc.so.6)
     10 __io_getevents_0_4(libaio.so.1),LinuxAIOHandler::collect,LinuxAIOHandler::poll,os_aio_handler,fil_aio_wait,io_handler_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      5 __lll_lock_wait(libpthread.so.0),_L_lock_1022(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),THD::release_resources,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      3 pthread_cond_wait,os_event::wait_low,buf_flush_page_cleaner_worker,start_thread(libpthread.so.0),clone(libc.so.6)
      2 __lll_lock_wait(libpthread.so.0),_L_lock_1022(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),Item_func_get_system_var::fix_length_and_dec,Item_func::fix_fields,setup_fields,st_select_lex::prepare,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 sigwait(libpthread.so.0),signal_hand,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 sigwaitinfo(libc.so.6),timer_notify_thread_func,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,Stage_manager::enroll_for,MYSQL_BIN_LOG::change_stage,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,srv_purge_coordinator_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_resize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,os_event::wait_low,buf_dump_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_wait,compress_gtid_table,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,srv_error_monitor_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,lock_wait_timeout_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,ib_wqueue_timedwait,fts_optimize_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,dict_stats_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 pthread_cond_timedwait,os_event::timed_wait,os_event::wait_time_low,buf_flush_page_cleaner_coordinator,start_thread(libpthread.so.0),clone(libc.so.6)
      1 poll(libc.so.6),vio_io_wait,vio_socket_io_wait,vio_read,net_read_raw_loop,net_read_packet,my_net_read,Protocol_classic::read_packet,Protocol_classic::get_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event,mysqld_main,__libc_start_main(libc.so.6),_start
      1 nanosleep(libpthread.so.0),os_thread_sleep,srv_master_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_812(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),PolyLock_lock_log::rdlock,sys_var::value_ptr,get_one_variable_ext,System_variable::init,PFS_system_variable_cache::do_materialize_all,table_session_variables::rnd_init,ha_perfschema::rnd_init,handler::ha_rnd_init,init_read_record,join_init_read_record,sub_select,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,Prepared_statement::execute,Prepared_statement::execute_loop,mysql_sql_stmt_execute,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_812(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),MYSQL_BIN_LOG::change_stage,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_1022(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),show_status_array,show_status_array,fill_status,do_fill_table,get_schema_tables_result,JOIN::prepare_result,JOIN::exec,handle_query,execute_sqlcom_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_1022(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),MYSQL_BIN_LOG::publish_coordinates_for_global_status,MYSQL_BIN_LOG::ordered_commit,MYSQL_BIN_LOG::commit,ha_commit_trans,trans_commit_stmt,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
      1 __lll_lock_wait(libpthread.so.0),_L_lock_1022(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),Item_func_get_system_var::fix_length_and_dec,Item_func::fix_fields,Item_func::fix_func_arg,Item_func::fix_fields,setup_fields,mysql_prepare_update,mysql_update,Sql_cmd_update::try_single_table_update,Sql_cmd_update::execute,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_connection,pfs_spawn_thread,start_thread(libpthread.so.0),clone(libc.so.6)
[root@tr2-mysql01 (sandbox) data]#
[24 Sep 2018 14:41] Sinisa Milivojevic
No news on this bug.

Scheduling the bug fixing is the internal matter in our Engineering team.

When the bug gets fixed, it will be announced here, on this page.
[1 Oct 2018 19:36] Margaret Fisher
Posted by developer:
 
Changelog entry added for MySQL 8.0.14 and 5.7.25:

When the system variables binlog_transaction_dependency_tracking and
binlog_transaction_dependency_history_size were set or read, the types of
lock that were required could result in a deadlock scenario, because the same
locks were also required for working with the active binary logs. A new lock
type is now used instead for access to the transaction dependency tracking
system variables, so that this deadlock cannot occur.
[19 Oct 2018 12:19] Sinisa Milivojevic
Bug #92858 is a duplicate of this one.