[MDEV-7402] 'reset master' hangs, waits for signalled COND_xid_list - JIRA

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 10.0.15
Fix Version/s: 10.0.16
Component/s: Replication
Labels:
None

Description

Two threads cause hang, here are their stack traces:

Thread X:
Waiting for LOCK_log.  

mysqld.exe!inline_mysql_mutex_lock Line 693
mysqld.exe!MYSQL_BIN_LOG::write Line 5857
mysqld.exe!THD::binlog_query Line 6288
mysqld.exe!write_bin_log Line 1999
mysqld.exe!Sql_cmd_truncate_table::truncate_table Line 529
mysqld.exe!Sql_cmd_truncate_table::execute Line 560
mysqld.exe!mysql_execute_command Line 5078
mysqld.exe!mysql_parse Line 6407
mysqld.exe!dispatch_command Line 1299
mysqld.exe!do_command Line 996
mysqld.exe!threadpool_process_request Line 233
mysqld.exe!io_completion_callback Line 568

-----

Thread Y:
Owns LOCK_xid_list, LOCK_log, LOCK_index
Waiting for:  mysql_cond_wait(&COND_xid_list, &LOCK_xid_list);

mysqld.exe!pthread_cond_timedwait Line 297
mysqld.exe!pthread_cond_wait Line 308
mysqld.exe!inline_mysql_cond_wait Line 1165
mysqld.exe!MYSQL_BIN_LOG::reset_logs Line 3919
mysqld.exe!reset_master Line 3582
mysqld.exe!reload_acl_and_cache Line 329
mysqld.exe!mysql_execute_command Line 4261
mysqld.exe!mysql_parse Line 6407
mysqld.exe!dispatch_command Line 1299
mysqld.exe!do_command Line 996
mysqld.exe!threadpool_process_request Line 233
mysqld.exe!io_completion_callback Line 568

How to repeat:
------------------
I have to make educated guess here, as no time for a perfect testcase.
Hangs within about 5 seconds on my testbed.
If you need exact testcase, let me know and I'll try produce it.

Start server with binlogging and run two threads that do some random XA, start transaction, commit, DML, and reset master.

Gliffy Diagrams

Attachments

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Elena Stepanova added a comment - 2015-01-09 19:28

XA is not needed, the deadlock can happen between two threads executing RESET MASTER:

client/mysqlslap --port=3306 --protocol=tcp -q "RESET MASTER" -c 2 --number-of-queries=100 --create-schema=test

#1  0x00007f5e0b2a9339 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2  0x00007f5e0b2a915b in __pthread_mutex_lock (mutex=0x188e4f0) at pthread_mutex_lock.c:61
#3  0x0000000000e4fff4 in safe_mutex_lock (mp=0x188e4c8, my_flags=0, file=0xff3498 "sql/log.cc", line=3882) at mysys/thr_mutex.c:294
#4  0x000000000093199b in inline_mysql_mutex_lock (that=0x188e4c8, src_file=0xff3498 "sql/log.cc", src_line=3882) at include/mysql/psi/mysql_thread.h:689
#5  0x000000000093be3a in MYSQL_BIN_LOG::reset_logs (this=0x188e4c0, thd=0x7f5df0fd8070, create_new_log=true, init_state=0x0, init_state_len=0) at sql/log.cc:3882
#6  0x00000000006abe03 in reset_master (thd=0x7f5df0fd8070, init_state=0x0, init_state_len=0) at sql/sql_repl.cc:3582
#7  0x00000000007c729d in reload_acl_and_cache (thd=0x7f5df0fd8070, options=128, tables=0x0, write_to_binlog=0x7f5e0b5de23c) at sql/sql_reload.cc:329
#8  0x0000000000680211 in mysql_execute_command (thd=0x7f5df0fd8070) at sql/sql_parse.cc:4261
#9  0x00000000006859bd in mysql_parse (thd=0x7f5df0fd8070, rawbuf=0x7f5def872088 "RESET MASTER", length=12, parser_state=0x7f5e0b5de660) at sql/sql_parse.cc:6407
#10 0x00000000006787b2 in dispatch_command (command=COM_QUERY, thd=0x7f5df0fd8070, packet=0x7f5df0fde071 "RESET MASTER", packet_length=12) at sql/sql_parse.cc:1299
#11 0x0000000000677b57 in do_command (thd=0x7f5df0fd8070) at sql/sql_parse.cc:996
#12 0x0000000000794877 in do_handle_one_connection (thd_arg=0x7f5df0fd8070) at sql/sql_connect.cc:1375
#13 0x00000000007945ca in handle_one_connection (arg=0x7f5df0fd8070) at sql/sql_connect.cc:1289
#14 0x00007f5e0b2a6b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
#15 0x00007f5e0955d20d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#16 0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7f5e0b596700 (LWP 28262)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x0000000000e50803 in safe_cond_wait (cond=0x188eb88, mp=0x188ead8, file=0xff3180 "include/mysql/psi/mysql_thread.h", line=1165) at mysys/thr_mutex.c:493
#2  0x0000000000931e54 in inline_mysql_cond_wait (that=0x188eb88, mutex=0x188ead8, src_file=0xff3498 "sql/log.cc", src_line=3919) at include/mysql/psi/mysql_thread.h:1165
#3  0x000000000093bf52 in MYSQL_BIN_LOG::reset_logs (this=0x188e4c0, thd=0x7f5df0fe5070, create_new_log=true, init_state=0x0, init_state_len=0) at sql/log.cc:3919
#4  0x00000000006abe03 in reset_master (thd=0x7f5df0fe5070, init_state=0x0, init_state_len=0) at sql/sql_repl.cc:3582
#5  0x00000000007c729d in reload_acl_and_cache (thd=0x7f5df0fe5070, options=128, tables=0x0, write_to_binlog=0x7f5e0b59523c) at sql/sql_reload.cc:329
#6  0x0000000000680211 in mysql_execute_command (thd=0x7f5df0fe5070) at sql/sql_parse.cc:4261
#7  0x00000000006859bd in mysql_parse (thd=0x7f5df0fe5070, rawbuf=0x7f5ded055088 "RESET MASTER", length=12, parser_state=0x7f5e0b595660) at sql/sql_parse.cc:6407
#8  0x00000000006787b2 in dispatch_command (command=COM_QUERY, thd=0x7f5df0fe5070, packet=0x7f5df0feb071 "RESET MASTER", packet_length=12) at sql/sql_parse.cc:1299
#9  0x0000000000677b57 in do_command (thd=0x7f5df0fe5070) at sql/sql_parse.cc:996
#10 0x0000000000794877 in do_handle_one_connection (thd_arg=0x7f5df0fe5070) at sql/sql_connect.cc:1375
#11 0x00000000007945ca in handle_one_connection (arg=0x7f5df0fe5070) at sql/sql_connect.cc:1289
#12 0x00007f5e0b2a6b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
#13 0x00007f5e0955d20d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Show

Elena Stepanova added a comment - 2015-01-09 19:28 XA is not needed, the deadlock can happen between two threads executing RESET MASTER: client/mysqlslap --port=3306 --protocol=tcp -q "RESET MASTER" -c 2 --number-of-queries=100 --create-schema=test #1 0x00007f5e0b2a9339 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0 #2 0x00007f5e0b2a915b in __pthread_mutex_lock (mutex=0x188e4f0) at pthread_mutex_lock.c:61 #3 0x0000000000e4fff4 in safe_mutex_lock (mp=0x188e4c8, my_flags=0, file=0xff3498 "sql/log.cc", line=3882) at mysys/thr_mutex.c:294 #4 0x000000000093199b in inline_mysql_mutex_lock (that=0x188e4c8, src_file=0xff3498 "sql/log.cc", src_line=3882) at include/mysql/psi/mysql_thread.h:689 #5 0x000000000093be3a in MYSQL_BIN_LOG::reset_logs (this=0x188e4c0, thd=0x7f5df0fd8070, create_new_log=true, init_state=0x0, init_state_len=0) at sql/log.cc:3882 #6 0x00000000006abe03 in reset_master (thd=0x7f5df0fd8070, init_state=0x0, init_state_len=0) at sql/sql_repl.cc:3582 #7 0x00000000007c729d in reload_acl_and_cache (thd=0x7f5df0fd8070, options=128, tables=0x0, write_to_binlog=0x7f5e0b5de23c) at sql/sql_reload.cc:329 #8 0x0000000000680211 in mysql_execute_command (thd=0x7f5df0fd8070) at sql/sql_parse.cc:4261 #9 0x00000000006859bd in mysql_parse (thd=0x7f5df0fd8070, rawbuf=0x7f5def872088 "RESET MASTER", length=12, parser_state=0x7f5e0b5de660) at sql/sql_parse.cc:6407 #10 0x00000000006787b2 in dispatch_command (command=COM_QUERY, thd=0x7f5df0fd8070, packet=0x7f5df0fde071 "RESET MASTER", packet_length=12) at sql/sql_parse.cc:1299 #11 0x0000000000677b57 in do_command (thd=0x7f5df0fd8070) at sql/sql_parse.cc:996 #12 0x0000000000794877 in do_handle_one_connection (thd_arg=0x7f5df0fd8070) at sql/sql_connect.cc:1375 #13 0x00000000007945ca in handle_one_connection (arg=0x7f5df0fd8070) at sql/sql_connect.cc:1289 #14 0x00007f5e0b2a6b50 in start_thread (arg=<optimized out>) at pthread_create.c:304 #15 0x00007f5e0955d20d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112 #16 0x0000000000000000 in ?? () Thread 2 (Thread 0x7f5e0b596700 (LWP 28262)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162 #1 0x0000000000e50803 in safe_cond_wait (cond=0x188eb88, mp=0x188ead8, file=0xff3180 "include/mysql/psi/mysql_thread.h", line=1165) at mysys/thr_mutex.c:493 #2 0x0000000000931e54 in inline_mysql_cond_wait (that=0x188eb88, mutex=0x188ead8, src_file=0xff3498 "sql/log.cc", src_line=3919) at include/mysql/psi/mysql_thread.h:1165 #3 0x000000000093bf52 in MYSQL_BIN_LOG::reset_logs (this=0x188e4c0, thd=0x7f5df0fe5070, create_new_log=true, init_state=0x0, init_state_len=0) at sql/log.cc:3919 #4 0x00000000006abe03 in reset_master (thd=0x7f5df0fe5070, init_state=0x0, init_state_len=0) at sql/sql_repl.cc:3582 #5 0x00000000007c729d in reload_acl_and_cache (thd=0x7f5df0fe5070, options=128, tables=0x0, write_to_binlog=0x7f5e0b59523c) at sql/sql_reload.cc:329 #6 0x0000000000680211 in mysql_execute_command (thd=0x7f5df0fe5070) at sql/sql_parse.cc:4261 #7 0x00000000006859bd in mysql_parse (thd=0x7f5df0fe5070, rawbuf=0x7f5ded055088 "RESET MASTER", length=12, parser_state=0x7f5e0b595660) at sql/sql_parse.cc:6407 #8 0x00000000006787b2 in dispatch_command (command=COM_QUERY, thd=0x7f5df0fe5070, packet=0x7f5df0feb071 "RESET MASTER", packet_length=12) at sql/sql_parse.cc:1299 #9 0x0000000000677b57 in do_command (thd=0x7f5df0fe5070) at sql/sql_parse.cc:996 #10 0x0000000000794877 in do_handle_one_connection (thd_arg=0x7f5df0fe5070) at sql/sql_connect.cc:1375 #11 0x00000000007945ca in handle_one_connection (arg=0x7f5df0fe5070) at sql/sql_connect.cc:1289 #12 0x00007f5e0b2a6b50 in start_thread (arg=<optimized out>) at pthread_create.c:304 #13 0x00007f5e0955d20d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Hide

Permalink

Kristian Nielsen added a comment - 2015-01-19 15:15

Ok to push with testcase as discussed.

Show

Kristian Nielsen added a comment - 2015-01-19 15:15 Ok to push with testcase as discussed.

'reset master' hangs, waits for signalled COND_xid_list

Details

Description

Gliffy Diagrams

Attachments

Activity

People

Dates

Time Tracking

Agile