Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5
-
None
Description
This bug is seen as rare sporadic failures of rpl.rpl_start_alter_4:
ERROR 23000: Duplicate entry '2' for key 'b'
|
# Sync slave
|
include/save_master_gtid.inc
|
include/sync_with_master_gtid.inc
|
Timeout in master_gtid_wait('0-1-37,11-1-135,12-1-137', 120), current slave GTID position is: 0-1-37,11-1-130,12-1-123.
|
The bug however is real and serious and not restricted to START ALTER. It is
a race condition in the do_gco_wait() mechanism in parallel replication,
which historically has been somewhat fragile and had a number of bugs.
The bug happens when two transactions T1, T2 end up in InnoDB trying to
update the dict_stats tables at the same time, and T1 having to wait for T2.
This gets reported by InnoDB to the replication layer, which decides to
treat this as a deadlock and schedule a kill of T2.
But the deadlock is not real, since table locks on dict_stats are released
immediately (don't linger until commit). So T2 will release its locks and
both T1 and T2 can reach their commit stage before the scheduled kill
actually happens from a background thread. When this happens and they both
call mark_start_commit(), it can signal to the next GCO that it can start
(return from do_gco_wait()).
But if at this point the deadlock kill of T2 goes through, T2 will roll
back, and retry, calling unmark_start_commit(). At this point we have an
invalid state, where T2 is now running in parallel with the following GCO,
which is not supposed to happen.
In the rpl.rpl_start_alter_4 test case failure, the following GCO is a DDL
that conflicts with T2. This can result in T2 waiting on metadata lock held
by the DLL, and the DDL doing wait_for_prior_commit(T2), which is an
unhandled deadlock and hangs the server.
Maybe potentially we could also get even worse problems of memory
corruption, if the following GCOs end up freeing the GCO of T2, T2 then
later accessing freed memory.
Here is a stack trace from an rpl.rpl_start_alter_4 failure, showing T2 and
DDL stuck waiting for each other:
Thread 8 (Thread 0x7f0e001d36c0 (LWP 1857161)):
|
#7 0x0000562dc35efcfb in MDL_wait::timed_wait (this=0x7f0df4032870, owner=0x7f0df4032800, abs_timeout=0x7f0e001d0d70, set_status_on_timeout=false, wait_state_name=0x562dc4c1c210 <MDL_key::m_namespace_to_wait_state_name+48>) at /kvm/src/my/mariadb/sql/mdl.cc:1210
|
#8 0x0000562dc35f1801 in MDL_context::acquire_lock (this=0x7f0df4032870, mdl_request=0x7f0df403b9b0, lock_wait_timeout=31536000) at /kvm/src/my/mariadb/sql/mdl.cc:2409
|
#9 0x0000562dc3344af7 in open_table_get_mdl_lock (thd=0x7f0df4032718, ot_ctx=0x7f0e001d1430, mdl_request=0x7f0df403b9b0, flags=0, mdl_ticket=0x7f0e001d1090) at /kvm/src/my/mariadb/sql/sql_base.cc:1622
|
#10 0x0000562dc334599f in open_table (thd=0x7f0df4032718, table_list=0x7f0df403b520, ot_ctx=0x7f0e001d1430) at /kvm/src/my/mariadb/sql/sql_base.cc:2028
|
#11 0x0000562dc334a983 in open_and_process_table (thd=0x7f0df4032718, tables=0x7f0df403b520, counter=0x7f0e001d14c4, flags=0, prelocking_strategy=0x7f0e001d1548, has_prelocking_list=false, ot_ctx=0x7f0e001d1430) at /kvm/src/my/mariadb/sql/sql_base.cc:4148
|
#12 0x0000562dc334bcaf in open_tables (thd=0x7f0df4032718, options=..., start=0x7f0e001d14a8, counter=0x7f0e001d14c4, flags=0, prelocking_strategy=0x7f0e001d1548) at /kvm/src/my/mariadb/sql/sql_base.cc:4636
|
#13 0x0000562dc334db58 in open_and_lock_tables (thd=0x7f0df4032718, options=..., tables=0x7f0df403b520, derived=true, flags=0, prelocking_strategy=0x7f0e001d1548) at /kvm/src/my/mariadb/sql/sql_base.cc:5610
|
#14 0x0000562dc3301530 in open_and_lock_tables (thd=0x7f0df4032718, tables=0x7f0df403b520, derived=true, flags=0) at /kvm/src/my/mariadb/sql/sql_base.h:516
|
#15 0x0000562dc33a910c in mysql_insert (thd=0x7f0df4032718, table_list=0x7f0df403b520, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /kvm/src/my/mariadb/sql/sql_insert.cc:772
|
#16 0x0000562dc33fe158 in mysql_execute_command (thd=0x7f0df4032718, is_called_from_prepared_stmt=false) at /kvm/src/my/mariadb/sql/sql_parse.cc:4608
|
#17 0x0000562dc3407f0b in mysql_parse (thd=0x7f0df4032718, rawbuf=0x7f0da0096fc3 "insert into t9 values(3,2,1,1)", length=30, parser_state=0x7f0e001d1fd0) at /kvm/src/my/mariadb/sql/sql_parse.cc:8145
|
#18 0x0000562dc3973f18 in Query_log_event::do_apply_event (this=0x7f0da00a3138, rgi=0x7f0da006e650, query_arg=0x7f0da0096fc3 "insert into t9 values(3,2,1,1)", q_len_arg=30) at /kvm/src/my/mariadb/sql/log_event_server.cc:2197
|
#19 0x0000562dc397244d in Query_log_event::do_apply_event (this=0x7f0da00a3138, rgi=0x7f0da006e650) at /kvm/src/my/mariadb/sql/log_event_server.cc:1633
|
#20 0x0000562dc3967828 in Log_event::apply_event (this=0x7f0da00a3138, rgi=0x7f0da006e650) at /kvm/src/my/mariadb/sql/log_event.cc:4221
|
#21 0x0000562dc32db98e in apply_event_and_update_pos_apply (ev=0x7f0da00a3138, thd=0x7f0df4032718, rgi=0x7f0da006e650, reason=0) at /kvm/src/my/mariadb/sql/slave.cc:3955
|
#22 0x0000562dc32dc0ad in apply_event_and_update_pos_for_parallel (ev=0x7f0da00a3138, thd=0x7f0df4032718, rgi=0x7f0da006e650) at /kvm/src/my/mariadb/sql/slave.cc:4162
|
#23 0x0000562dc3693365 in rpt_handle_event (qev=0x7f0df4043da8, rpt=0x7f0da01209f0) at /kvm/src/my/mariadb/sql/rpl_parallel.cc:66
|
#24 0x0000562dc3696381 in retry_event_group (rgi=0x7f0da006e650, rpt=0x7f0da01209f0, orig_qev=0x7f0da00039d8) at /kvm/src/my/mariadb/sql/rpl_parallel.cc:1158
|
#25 0x0000562dc3697674 in handle_rpl_parallel_thread (arg=0x7f0da01209f0) at /kvm/src/my/mariadb/sql/rpl_parallel.cc:1572
|
|
|
Thread 10 (Thread 0x7f0e000a76c0 (LWP 1857157)):
|
#7 0x0000562dc3385019 in wait_for_commit::wait_for_prior_commit2 (this=0x7f0da00cefb0, thd=0x7f0db80bed98, allow_kill=true) at /kvm/src/my/mariadb/sql/sql_class.cc:8257
|
#8 0x0000562dc369d497 in wait_for_commit::wait_for_prior_commit (this=0x7f0da00cefb0, thd=0x7f0db80bed98, allow_kill=true) at /kvm/src/my/mariadb/sql/sql_class.h:2380
|
#9 0x0000562dc39334af in write_bin_log_start_alter (thd=0x7f0db80bed98, partial_alter=@0x7f0e000a3226: false, start_alter_id=129, if_exists=false) at /kvm/src/my/mariadb/sql/log.cc:637
|
#10 0x0000562dc3532255 in mysql_alter_table (thd=0x7f0db80bed98, new_db=0x7f0db80c38f0, new_name=0x7f0db80c3d50, create_info=0x7f0e000a5710, table_list=0x7f0db80caf40, recreate_info=0x7f0e000a5570, alter_info=0x7f0e000a55a0, order_num=0, order=0x0, ignore=false, if_exists=false) at /kvm/src/my/mariadb/sql/sql_table.cc:11151
|
#11 0x0000562dc35ec0c3 in Sql_cmd_alter_table::execute (this=0x7f0db80cb850, thd=0x7f0db80bed98) at /kvm/src/my/mariadb/sql/sql_alter.cc:688
|
#12 0x0000562dc3402ab8 in mysql_execute_command (thd=0x7f0db80bed98, is_called_from_prepared_stmt=false) at /kvm/src/my/mariadb/sql/sql_parse.cc:6126
|
#13 0x0000562dc3407f0b in mysql_parse (thd=0x7f0db80bed98, rawbuf=0x7f0da0132133 "alter table t9 change b b int unique, force, algorithm=copy", length=59, parser_state=0x7f0e000a6830) at /kvm/src/my/mariadb/sql/sql_parse.cc:8145
|
#14 0x0000562dc3973f18 in Query_log_event::do_apply_event (this=0x7f0da012a4a8, rgi=0x7f0da00cef70, query_arg=0x7f0da0132133 "alter table t9 change b b int unique, force, algorithm=copy", q_len_arg=59) at /kvm/src/my/mariadb/sql/log_event_server.cc:2197
|
#15 0x0000562dc397244d in Query_log_event::do_apply_event (this=0x7f0da012a4a8, rgi=0x7f0da00cef70) at /kvm/src/my/mariadb/sql/log_event_server.cc:1633
|
#16 0x0000562dc3967828 in Log_event::apply_event (this=0x7f0da012a4a8, rgi=0x7f0da00cef70) at /kvm/src/my/mariadb/sql/log_event.cc:4221
|
#17 0x0000562dc32db98e in apply_event_and_update_pos_apply (ev=0x7f0da012a4a8, thd=0x7f0db80bed98, rgi=0x7f0da00cef70, reason=0) at /kvm/src/my/mariadb/sql/slave.cc:3955
|
#18 0x0000562dc32dc0ad in apply_event_and_update_pos_for_parallel (ev=0x7f0da012a4a8, thd=0x7f0db80bed98, rgi=0x7f0da00cef70) at /kvm/src/my/mariadb/sql/slave.cc:4162
|
#19 0x0000562dc3693365 in rpt_handle_event (qev=0x7f0da003a2d8, rpt=0x7f0da011ed90) at /kvm/src/my/mariadb/sql/rpl_parallel.cc:66
|
#20 0x0000562dc369751f in handle_rpl_parallel_thread (arg=0x7f0da011ed90) at /kvm/src/my/mariadb/sql/rpl_parallel.cc:1558
|
At the time when T2 calls mark_start_commit(), the kill is already scheduled;
I don't think it's possible to get a lock wait conflict in InnoDB during
commit. So the problem is that T2 doesn't check for a deadlock kill before
doing mark_start_commit().
Therefore this patch should fix the problem and make the do_gco_wait()
robust towards spurious lock wait reports from the engine:
@@ -1496,12 +1506,24 @@ handle_rpl_parallel_thread(void *arg)
|
|
|
+ if (rgi->killed_for_retry != rpl_group_info::RETRY_KILL_NONE)
|
+ wait_for_pending_deadlock_kill(thd, rgi);
|
if (!thd->killed)
|
{
|
DEBUG_SYNC(thd, "rpl_parallel_before_mark_start_commit");
|