Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.1(EOL)
-
None
Description
Note: 10.0 might also be affected, I encountered the problem on 10.1 because that's where tests were running.
|
Stack trace from 10.1 commit 539b3ca87 |
Thread 6 (Thread 0x7fb11fc80700 (LWP 19403)):
|
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
|
#1 0x00007fb122e5d626 in safe_cond_wait (cond=0x7fb0f5c538e8, mp=0x7fb0f5c53838, file=0x7fb122f13120 "10.1/include/mysql/psi/mysql_thread.h", line=1165) at 10.1/mysys/thr_mutex.c:493
|
#2 0x00007fb12259a66b in inline_mysql_cond_wait (that=0x7fb0f5c538e8, mutex=0x7fb0f5c53838, src_file=0x7fb122f13988 "10.1/sql/sql_class.cc", src_line=6853) at 10.1/include/mysql/psi/mysql_thread.h:1165
|
#3 0x00007fb1225aad83 in wait_for_commit::wait_for_prior_commit2 (this=0x7fb0f5c53838, thd=0x7fb10c96e070) at 10.1/sql/sql_class.cc:6853
|
#4 0x00007fb12258a451 in wait_for_commit::wait_for_prior_commit (this=0x7fb0f5c53838, thd=0x7fb10c96e070) at 10.1/sql/sql_class.h:1780
|
#5 0x00007fb12258a760 in THD::wait_for_prior_commit (this=0x7fb10c96e070) at 10.1/sql/sql_class.h:3781
|
#6 0x00007fb12281077f in ha_commit_one_phase (thd=0x7fb10c96e070, all=true) at 10.1/sql/handler.cc:1536
|
#7 0x00007fb12281009d in ha_commit_trans (thd=0x7fb10c96e070, all=true) at 10.1/sql/handler.cc:1406
|
#8 0x00007fb122720121 in trans_commit (thd=0x7fb10c96e070) at 10.1/sql/transaction.cc:236
|
#9 0x00007fb1225e6650 in mysql_execute_command (thd=0x7fb10c96e070) at 10.1/sql/sql_parse.cc:4864
|
#10 0x00007fb1225ecfaa in mysql_parse (thd=0x7fb10c96e070, rawbuf=0x7fb0f5d0ab79 "COMMIT", length=6, parser_state=0x7fb11fc7fa60) at 10.1/sql/sql_parse.cc:7165
|
#11 0x00007fb122902c8c in Query_log_event::do_apply_event (this=0x7fb0f5d18670, rgi=0x7fb0f5c53800, query_arg=0x7fb0f5d0ab79 "COMMIT", q_len_arg=6) at 10.1/sql/log_event.cc:4287
|
#12 0x00007fb122901f11 in Query_log_event::do_apply_event (this=0x7fb0f5d18670, rgi=0x7fb0f5c53800) at 10.1/sql/log_event.cc:4013
|
#13 0x00007fb12254a5da in Log_event::apply_event (this=0x7fb0f5d18670, rgi=0x7fb0f5c53800) at 10.1/sql/log_event.h:1347
|
#14 0x00007fb12254014f in apply_event_and_update_pos (ev=0x7fb0f5d18670, thd=0x7fb10c96e070, rgi=0x7fb0f5c53800, rpt=0x7fb0f5e221b0) at 10.1/sql/slave.cc:3274
|
#15 0x00007fb122777043 in rpt_handle_event (qev=0x7fb0f5d47970, rpt=0x7fb0f5e221b0) at 10.1/sql/rpl_parallel.cc:49
|
#16 0x00007fb1227792ec in handle_rpl_parallel_thread (arg=0x7fb0f5e221b0) at 10.1/sql/rpl_parallel.cc:942
|
#17 0x00007fb121cc7b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
|
#18 0x00007fb11fd5c95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
|
#19 0x0000000000000000 in ?? ()
|
|
|
Thread 5 (Thread 0x7fb11ebb5700 (LWP 19404)):
|
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:216
|
#1 0x00007fb122e5d92d in safe_cond_timedwait (cond=0x7fb11e65b218, mp=0x7fb11e65b168, abstime=0x7fb11ebb1a70, file=0x7fb122f69680 "10.1/include/mysql/psi/mysql_thread.h", line=1202) at 10.1/mysys/thr_mutex.c:547
|
#2 0x00007fb1227153d9 in inline_mysql_cond_timedwait (that=0x7fb11e65b218, mutex=0x7fb11e65b168, abstime=0x7fb11ebb1a70, src_file=0x7fb122f698e8 "10.1/sql/mdl.cc", src_line=1066) at 10.1/include/mysql/psi/mysql_thread.h:1202
|
#3 0x00007fb122716549 in MDL_wait::timed_wait (this=0x7fb11e65b168, owner=0x7fb11e65b120, abs_timeout=0x7fb11ebb1a70, set_status_on_timeout=false, wait_state_name=0x7fb12370a8b0) at 10.1/sql/mdl.cc:1066
|
#4 0x00007fb122717f2d in MDL_context::acquire_lock (this=0x7fb11e65b168, mdl_request=0x7fb11ebb1b40, lock_wait_timeout=31536000) at 10.1/sql/mdl.cc:2039
|
#5 0x00007fb1227186f2 in MDL_context::upgrade_shared_lock (this=0x7fb11e65b168, mdl_ticket=0x7fb11e44c0c0, new_type=MDL_EXCLUSIVE, lock_wait_timeout=31536000) at 10.1/sql/mdl.cc:2232
|
#6 0x00007fb12257763d in wait_while_table_is_used (thd=0x7fb11e65b070, table=0x7fb0f55dce70, function=HA_EXTRA_PREPARE_FOR_RENAME) at 10.1/sql/sql_base.cc:1874
|
#7 0x00007fb12269cbf7 in mysql_inplace_alter_table (thd=0x7fb11e65b070, table_list=0x7fb11e664128, table=0x7fb0f55dce70, altered_table=0x7fb11e656070, ha_alter_info=0x7fb11ebb1f80, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fb11ebb1ff0, alter_ctx=0x7fb11ebb2b80) at 10.1/sql/sql_table.cc:7036
|
#8 0x00007fb1226a147c in mysql_alter_table (thd=0x7fb11e65b070, new_db=0x7fb11e664708 "test", new_name=0x0, create_info=0x7fb11ebb3780, table_list=0x7fb11e664128, alter_info=0x7fb11ebb36f0, order_num=0, order=0x0, ignore=false) at 10.1/sql/sql_table.cc:8821
|
#9 0x00007fb122710ecd in Sql_cmd_alter_table::execute (this=0x7fb11e6648a8, thd=0x7fb11e65b070) at 10.1/sql/sql_alter.cc:325
|
#10 0x00007fb1225e8c79 in mysql_execute_command (thd=0x7fb11e65b070) at 10.1/sql/sql_parse.cc:5558
|
#11 0x00007fb1225ecfaa in mysql_parse (thd=0x7fb11e65b070, rawbuf=0x7fb0f5d041b9 "ALTER TABLE table10_innodb ADD COLUMN `default` INTEGER DEFAULT 5", length=65, parser_state=0x7fb11ebb4a60) at 10.1/sql/sql_parse.cc:7165
|
#12 0x00007fb122902c8c in Query_log_event::do_apply_event (this=0x7fb0f5d15e30, rgi=0x7fb0f5c53000, query_arg=0x7fb0f5d041b9 "ALTER TABLE table10_innodb ADD COLUMN `default` INTEGER DEFAULT 5", q_len_arg=65) at 10.1/sql/log_event.cc:4287
|
#13 0x00007fb122901f11 in Query_log_event::do_apply_event (this=0x7fb0f5d15e30, rgi=0x7fb0f5c53000) at 10.1/sql/log_event.cc:4013
|
#14 0x00007fb12254a5da in Log_event::apply_event (this=0x7fb0f5d15e30, rgi=0x7fb0f5c53000) at 10.1/sql/log_event.h:1347
|
#15 0x00007fb12254014f in apply_event_and_update_pos (ev=0x7fb0f5d15e30, thd=0x7fb11e65b070, rgi=0x7fb0f5c53000, rpt=0x7fb0f5e22380) at 10.1/sql/slave.cc:3274
|
#16 0x00007fb122777043 in rpt_handle_event (qev=0x7fb0f5d46a70, rpt=0x7fb0f5e22380) at 10.1/sql/rpl_parallel.cc:49
|
#17 0x00007fb1227792ec in handle_rpl_parallel_thread (arg=0x7fb0f5e22380) at 10.1/sql/rpl_parallel.cc:942
|
#18 0x00007fb121cc7b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
|
#19 0x00007fb11fd5c95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
|
#20 0x0000000000000000 in ?? ()
|
|
|
Thread 2 (Thread 0x7fb0fd7f5700 (LWP 19439)):
|
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:216
|
#1 0x00007fb122e5d92d in safe_cond_timedwait (cond=0x7fb10d88adf8, mp=0x7fb10d88ad10, abstime=0x7fb0fd7f3490, file=0x7fb122eff5a0 "10.1/include/mysql/psi/mysql_thread.h", line=1202) at 10.1/mysys/thr_mutex.c:547
|
#2 0x00007fb122536c6c in inline_mysql_cond_timedwait (that=0x7fb10d88adf8, mutex=0x7fb10d88ad10, abstime=0x7fb0fd7f3490, src_file=0x7fb122effcb0 "10.1/sql/slave.cc", src_line=791) at 10.1/include/mysql/psi/mysql_thread.h:1202
|
#3 0x00007fb12253880d in terminate_slave_thread (thd=0x7fb0f5d64070, term_lock=0x7fb10d88ad10, term_cond=0x7fb10d88adf8, slave_running=0x7fb10d88b7ec, skip_lock=true) at 10.1/sql/slave.cc:791
|
#4 0x00007fb1225381af in terminate_slave_threads (mi=0x7fb10d887000, thread_mask=3, skip_lock=true) at 10.1/sql/slave.cc:636
|
#5 0x00007fb12261425e in stop_slave (thd=0x7fb0fcaa2070, mi=0x7fb10d887000, net_report=true) at 10.1/sql/sql_repl.cc:3186
|
#6 0x00007fb1225e1658 in mysql_execute_command (thd=0x7fb0fcaa2070) at 10.1/sql/sql_parse.cc:3530
|
#7 0x00007fb1225ecfaa in mysql_parse (thd=0x7fb0fcaa2070, rawbuf=0x7fb0f3a97088 "STOP SLAVE SQL_THREAD, IO_THREAD", length=32, parser_state=0x7fb0fd7f4200) at 10.1/sql/sql_parse.cc:7165
|
#8 0x00007fb1225dbfba in dispatch_command (command=COM_QUERY, thd=0x7fb0fcaa2070, packet=0x7fb102b48071 "STOP SLAVE SQL_THREAD, IO_THREAD", packet_length=32) at 10.1/sql/sql_parse.cc:1462
|
#9 0x00007fb1225dad8a in do_command (thd=0x7fb0fcaa2070) at 10.1/sql/sql_parse.cc:1090
|
#10 0x00007fb12270c1df in do_handle_one_connection (thd_arg=0x7fb0fcaa2070) at 10.1/sql/sql_connect.cc:1347
|
#11 0x00007fb12270bf24 in handle_one_connection (arg=0x7fb0fcaa2070) at 10.1/sql/sql_connect.cc:1258
|
#12 0x00007fb121cc7b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
|
#13 0x00007fb11fd5c95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
|
#14 0x0000000000000000 in ?? ()
|
All threads' stack traces are attached (threads1 and threads1_full).
|
Processlist |
+-----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+-------------------------------------------------------------------+----------+ |
| Id | User | Host | db | Command | Time | State | Info | Progress | |
+-----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+-------------------------------------------------------------------+----------+ |
| 25 | root | localhost:41433 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 26 | root | localhost:41435 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 27 | root | localhost:41437 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 28 | root | localhost:41439 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 29 | root | localhost:41441 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 30 | root | localhost:41443 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 31 | root | localhost:41445 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 32 | root | localhost:41447 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 33 | root | localhost:41449 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 34 | root | localhost:41451 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 35 | root | localhost:41453 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 36 | root | localhost:41455 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 37 | root | localhost:41457 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 38 | root | localhost:41459 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 39 | root | localhost:41461 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 40 | root | localhost:41463 | NULL | Query | 124675 | init | SHOW SLAVE STATUS | 0.000 | |
| 98 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 99 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 100 | system user | | test | Connect | 124749 | Waiting for prior transaction to commit | COMMIT | 0.000 | |
| 101 | system user | | test | Connect | 124750 | Waiting for prior transaction to commit | COMMIT | 0.000 | |
| 102 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 103 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 104 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 105 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to commit | NULL | 0.000 | |
| 106 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 107 | system user | | test | Connect | 124749 | Waiting for prior transaction to commit | COMMIT | 0.000 | |
| 108 | system user | | test | Connect | 124749 | Waiting for prior transaction to commit | COMMIT | 0.000 | |
| 109 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 110 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 111 | system user | | test | Connect | 124750 | Waiting for prior transaction to commit | COMMIT | 0.000 | |
| 112 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 113 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 114 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 115 | system user | | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL | 0.000 | |
| 116 | system user | | NULL | Connect | 124750 | Waiting for prior transaction to commit | NULL | 0.000 | |
| 117 | system user | | test | Connect | 124756 | Waiting for table metadata lock | ALTER TABLE table10_innodb ADD COLUMN `default` INTEGER DEFAULT 5 | 0.000 | |
| 118 | system user | | NULL | Connect | 124690 | Reading event from the relay log | NULL | 0.000 | |
| 127 | system user | | NULL | Connect | 124690 | Waiting for master to send event | NULL | 0.000 | |
| 130 | root | localhost:41537 | NULL | Query | 124675 | Killing slave | STOP SLAVE SQL_THREAD, IO_THREAD | 0.000 | |
| 134 | root | localhost:52917 | test | Query | 0 | init | show processlist | 0.000 |
|
+-----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+-------------------------------------------------------------------+----------+ |
|
Slave command line |
/home/elenst/git/10.1/sql/mysqld --no-defaults --basedir=/home/elenst/git/10.1 --datadir=/home/elenst/test_results/analyze6_slave/data --lc-messages-dir=/home/elenst/git/10.1/sql/share --character-sets-dir=/home/elenst/git/10.1/sql/share/charsets --tmpdir=/home/elenst/test_results/analyze6_slave/tmp --core-file --max-allowed-packet=128Mb --port=10722 --socket=/home/elenst/test_results/analyze6_slave/mysql.sock --pid-file=/home/elenst/test_results/analyze6_slave/mysql.pid --general-log --general-log-file=/home/elenst/test_results/analyze6_slave/mysql.log --server_id=2 --report-host=127.0.0.1 --report_port=10722 --log_bin_trust_function_creators=1 --slave-skip-errors=1054,1317,1049,1305,1539,1505 --slave-parallel-mode=optimistic --binlog_commit_wait_count=20 --binlog_commit_wait_usec=1000000 --slave-parallel-threads=20 --innodb --sql-mode=no_engine_substitution
|
SHOW SLAVE STATUS hangs.
|
gtid_slave_pos |
+------------------+ |
| @@gtid_slave_pos |
|
+------------------+ |
| 0-1-846 |
|
+------------------+ |
Master's binlog is attached (mysql-bin.*).
Slave is running without binary logging.
Master's general log is attached (master.log).
Slave's general and error logs are attached (slave.log, slave.err).
Attachments
Activity
Preliminary analyis suggests that the problem could be when using optimistic
parallel replication, and the very first event after slave start is a DDL
statement.
It looks like in this case, the code is not correctly ensuring that the DDL
will be completed before trying to run any further statements:
gco= e->current_gco;
|
if (likely(gco)) {
|
...
|
if (gtid_flags & Gtid_log_event::FL_DDL)
|
flags|= (force_switch_flag= group_commit_orderer::FORCE_SWITCH);
|
I will investigate further and try to come up with an mtr test case.
Another occurrence of presumably the same problem was mentioned in MDEV-8039. I don't have a running instance of that occurrence anymore, though.