Skip to content

Commit 08585b0

Browse files
knielsenknielsen
committed
MDEV-31509: Lost data with FTWRL and STOP SLAVE
The largest_started_sub_id needs to be set under LOCK_parallel_entry together with testing stop_sub_id. However, in-between was the logic for do_ftwrl_wait(), which temporarily releases the mutex. This could lead to inconsistent stopping amongst worker threads and lost data. Fix by moving all the stop-related logic out from unrelated do_gco_wait() and do_ftwrl_wait() and into its own function do_stop_handling(). Reviewed-by: Andrei Elkin <andrei.elkin@mariadb.com> Signed-off-by: Kristian Nielsen <knielsen@knielsen-hq.org>
1 parent d4309d4 commit 08585b0

File tree

3 files changed

+310
-15
lines changed

3 files changed

+310
-15
lines changed

‎mysql-test/suite/rpl/r/rpl_parallel_ftwrl.result

Lines changed: 105 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,105 @@
1+
include/master-slave.inc
2+
[connection master]
3+
connection slave;
4+
include/stop_slave.inc
5+
SET @old_parallel_threads= @@GLOBAL.slave_parallel_threads;
6+
SET GLOBAL slave_parallel_threads=3;
7+
SET @old_parallel_mode= @@GLOBAL.slave_parallel_mode;
8+
SET GLOBAL slave_parallel_mode=aggressive;
9+
SET @old_dbug= @@GLOBAL.debug_dbug;
10+
CHANGE MASTER TO master_use_gtid=slave_pos;
11+
include/start_slave.inc
12+
*** MDEV-31509: Lost data with FTWRL and STOP SLAVE
13+
connection master;
14+
ALTER TABLE mysql.gtid_slave_pos ENGINE=InnoDB;
15+
CREATE TABLE t1 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB;
16+
CREATE TABLE t2 (a INT PRIMARY KEY, b INT) ENGINE=MyISAM;
17+
INSERT INTO t1 VALUES (0,0);
18+
INSERT INTO t2 VALUES (0,0);
19+
include/save_master_gtid.inc
20+
connection slave;
21+
include/sync_with_master_gtid.inc
22+
connection slave;
23+
*** Arrange for T1 to delay before entering GCO wait.
24+
SET GLOBAL debug_dbug="+d,gco_wait_delay_gtid_0_x_99";
25+
*** Arrange for T2 to wait for FTWRL to start.
26+
SET GLOBAL debug_dbug="+d,hold_worker_on_schedule";
27+
*** Arrange for T2 to delay wakeup from FTWRL pause.
28+
SET GLOBAL debug_dbug="+d,delay_ftwrl_wait_gtid_0_x_100";
29+
connection master;
30+
*** Event group T1
31+
SET SESSION gtid_seq_no=99;
32+
INSERT INTO t1 VALUES (1,1);
33+
connection slave;
34+
*** 1a. Wait for T1 to be queued.
35+
SET debug_sync="now WAIT_FOR gco_wait_paused";
36+
connection master;
37+
*** Event group T2
38+
SET SESSION gtid_seq_no=100;
39+
INSERT INTO t2 VALUES (2,2);
40+
connection slave;
41+
*** 1b. Wait for T2 to be queued.
42+
SET debug_sync= "now WAIT_FOR reached_pause";
43+
connection slave1;
44+
*** 2. Run FTWRL
45+
SET GLOBAL debug_dbug= "+d,pause_for_ftwrl_wait";
46+
FLUSH TABLES WITH READ LOCK;
47+
connection slave;
48+
SET debug_sync= "now WAIT_FOR pause_ftwrl_waiting";
49+
*** 3. Wait for T2 to be waiting for FTWRL pause
50+
SET debug_sync= "now SIGNAL continue_worker";
51+
*** 4. FTWRL completes, UNLOCK TABLES.
52+
SET debug_sync="now SIGNAL pause_ftwrl_cont";
53+
connection slave1;
54+
UNLOCK TABLES;
55+
connection slave;
56+
*** T2 is now ready to proceed after FTWRL pause, but did not wake up yet.
57+
SET debug_sync="now WAIT_FOR pause_wait_started";
58+
*** 5. STOP SLAVE is run.
59+
connection slave1;
60+
SET GLOBAL debug_dbug="+d,rpl_parallel_wait_for_done_trigger";
61+
STOP SLAVE;
62+
connection slave;
63+
SET debug_sync="now WAIT_FOR wait_for_done_waiting";
64+
*** 5. T2 wakes up after FTWRL pause, reaches wait_for_prior_commit().
65+
SET debug_sync="now SIGNAL pause_wait_continue";
66+
*** 6. T1 starts.
67+
SET debug_sync="now SIGNAL gco_wait_cont";
68+
connection slave1;
69+
connection slave;
70+
include/wait_for_slave_to_stop.inc
71+
connection master;
72+
SELECT * FROM t1 ORDER BY a;
73+
a b
74+
0 0
75+
1 1
76+
SELECT * FROM t2 ORDER BY a;
77+
a b
78+
0 0
79+
2 2
80+
include/save_master_gtid.inc
81+
connection slave;
82+
include/start_slave.inc
83+
include/sync_with_master_gtid.inc
84+
SELECT @@GLOBAL.gtid_slave_pos;
85+
@@GLOBAL.gtid_slave_pos
86+
0-1-100
87+
SELECT * FROM t1 ORDER BY a;
88+
a b
89+
0 0
90+
1 1
91+
SELECT * FROM t2 ORDER BY a;
92+
a b
93+
0 0
94+
2 2
95+
*** Clean up.
96+
connection slave;
97+
include/stop_slave.inc
98+
SET DEBUG_SYNC= "RESET";
99+
SET GLOBAL slave_parallel_threads= @old_parallel_threads;
100+
SET GLOBAL slave_parallel_mode= @old_parallel_mode;
101+
SET GLOBAL debug_dbug=@old_dbug;
102+
include/start_slave.inc
103+
connection master;
104+
DROP TABLE t1, t2;
105+
include/rpl_end.inc

‎mysql-test/suite/rpl/t/rpl_parallel_ftwrl.test

Lines changed: 143 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,143 @@
1+
--source include/have_innodb.inc
2+
--source include/have_debug.inc
3+
--source include/have_debug_sync.inc
4+
--source include/have_binlog_format_mixed.inc
5+
--source include/master-slave.inc
6+
7+
--connection slave
8+
--source include/stop_slave.inc
9+
SET @old_parallel_threads= @@GLOBAL.slave_parallel_threads;
10+
SET GLOBAL slave_parallel_threads=3;
11+
SET @old_parallel_mode= @@GLOBAL.slave_parallel_mode;
12+
SET GLOBAL slave_parallel_mode=aggressive;
13+
SET @old_dbug= @@GLOBAL.debug_dbug;
14+
CHANGE MASTER TO master_use_gtid=slave_pos;
15+
--source include/start_slave.inc
16+
17+
--echo *** MDEV-31509: Lost data with FTWRL and STOP SLAVE
18+
# The bug was as follows:
19+
# 1. Event groups T1 and T2 are queued but not started yet.
20+
# 2. FLUSH TABLE WITH READ LOCKS starts, sets rpl_parallel_entry::pause_sub_id
21+
# 3. T2 Sees pause_sub_id, goes to wait for the pause to complete.
22+
# 4. FTWRL completes, UNLOCK TABLES is run.
23+
# 5. STOP SLAVE is run, sets rpl_parallel_entry::stop_sub_id.
24+
# 6. T2 wakes up after FTWRL pause, only now sets
25+
# rpl_parallel_entry::largest_started_sub_id. This is the bug,
26+
# largest_started_sub_id is set too late here.
27+
# 7. T1 starts, it sees stop_sub_id<T1, so T1 is skipped due to STOP SLAVE.
28+
# 8. T2 continues, its check for stop_sub_id was before STOP SLAVE. So T2 is
29+
# wrongly applied, silently losing transaction T1.
30+
31+
32+
--connection master
33+
ALTER TABLE mysql.gtid_slave_pos ENGINE=InnoDB;
34+
CREATE TABLE t1 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB;
35+
CREATE TABLE t2 (a INT PRIMARY KEY, b INT) ENGINE=MyISAM;
36+
INSERT INTO t1 VALUES (0,0);
37+
INSERT INTO t2 VALUES (0,0);
38+
--source include/save_master_gtid.inc
39+
40+
--connection slave
41+
--source include/sync_with_master_gtid.inc
42+
43+
--connection slave
44+
--echo *** Arrange for T1 to delay before entering GCO wait.
45+
SET GLOBAL debug_dbug="+d,gco_wait_delay_gtid_0_x_99";
46+
--echo *** Arrange for T2 to wait for FTWRL to start.
47+
SET GLOBAL debug_dbug="+d,hold_worker_on_schedule";
48+
--echo *** Arrange for T2 to delay wakeup from FTWRL pause.
49+
SET GLOBAL debug_dbug="+d,delay_ftwrl_wait_gtid_0_x_100";
50+
51+
--connection master
52+
--echo *** Event group T1
53+
SET SESSION gtid_seq_no=99;
54+
INSERT INTO t1 VALUES (1,1);
55+
56+
--connection slave
57+
--echo *** 1a. Wait for T1 to be queued.
58+
SET debug_sync="now WAIT_FOR gco_wait_paused";
59+
60+
--connection master
61+
--echo *** Event group T2
62+
SET SESSION gtid_seq_no=100;
63+
INSERT INTO t2 VALUES (2,2);
64+
65+
--connection slave
66+
--echo *** 1b. Wait for T2 to be queued.
67+
SET debug_sync= "now WAIT_FOR reached_pause";
68+
69+
--connection slave1
70+
--echo *** 2. Run FTWRL
71+
SET GLOBAL debug_dbug= "+d,pause_for_ftwrl_wait";
72+
send FLUSH TABLES WITH READ LOCK;
73+
74+
--connection slave
75+
SET debug_sync= "now WAIT_FOR pause_ftwrl_waiting";
76+
77+
--echo *** 3. Wait for T2 to be waiting for FTWRL pause
78+
SET debug_sync= "now SIGNAL continue_worker";
79+
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE state LIKE "%Waiting due to global read lock%" and command="Slave_worker";
80+
--source include/wait_condition.inc
81+
82+
--echo *** 4. FTWRL completes, UNLOCK TABLES.
83+
SET debug_sync="now SIGNAL pause_ftwrl_cont";
84+
85+
--connection slave1
86+
reap;
87+
UNLOCK TABLES;
88+
89+
--connection slave
90+
--echo *** T2 is now ready to proceed after FTWRL pause, but did not wake up yet.
91+
SET debug_sync="now WAIT_FOR pause_wait_started";
92+
93+
--echo *** 5. STOP SLAVE is run.
94+
--connection slave1
95+
SET GLOBAL debug_dbug="+d,rpl_parallel_wait_for_done_trigger";
96+
send STOP SLAVE;
97+
98+
--connection slave
99+
SET debug_sync="now WAIT_FOR wait_for_done_waiting";
100+
101+
--echo *** 5. T2 wakes up after FTWRL pause, reaches wait_for_prior_commit().
102+
SET debug_sync="now SIGNAL pause_wait_continue";
103+
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE state LIKE "%Waiting for prior transaction to commit%" and command="Slave_worker";
104+
--source include/wait_condition.inc
105+
106+
--echo *** 6. T1 starts.
107+
SET debug_sync="now SIGNAL gco_wait_cont";
108+
109+
--connection slave1
110+
reap;
111+
112+
--connection slave
113+
--source include/wait_for_slave_to_stop.inc
114+
115+
--connection master
116+
SELECT * FROM t1 ORDER BY a;
117+
SELECT * FROM t2 ORDER BY a;
118+
--source include/save_master_gtid.inc
119+
120+
--connection slave
121+
--source include/start_slave.inc
122+
--source include/sync_with_master_gtid.inc
123+
124+
# The bug here was that T2 was errorneously replicated while T1 was
125+
# being skipped due to STOP SLAVE. So the @@gtid_slave_pos was at T2,
126+
# but we were missing the data from T1.
127+
SELECT @@GLOBAL.gtid_slave_pos;
128+
SELECT * FROM t1 ORDER BY a;
129+
SELECT * FROM t2 ORDER BY a;
130+
131+
--echo *** Clean up.
132+
--connection slave
133+
--source include/stop_slave.inc
134+
SET DEBUG_SYNC= "RESET";
135+
SET GLOBAL slave_parallel_threads= @old_parallel_threads;
136+
SET GLOBAL slave_parallel_mode= @old_parallel_mode;
137+
SET GLOBAL debug_dbug=@old_dbug;
138+
--source include/start_slave.inc
139+
140+
--connection master
141+
DROP TABLE t1, t2;
142+
143+
--source include/rpl_end.inc

‎sql/rpl_parallel.cc

Lines changed: 62 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -369,7 +369,7 @@ register_wait_for_prior_event_group_commit(rpl_group_info *rgi,
369369
Do not start parallel execution of this event group until all prior groups
370370
have reached the commit phase that are not safe to run in parallel with.
371371
*/
372-
static bool
372+
static void
373373
do_gco_wait(rpl_group_info *rgi, group_commit_orderer *gco,
374374
bool *did_enter_cond, PSI_stage_info *old_stage)
375375
{
@@ -421,19 +421,45 @@ do_gco_wait(rpl_group_info *rgi, group_commit_orderer *gco,
421421
&entry->LOCK_parallel_entry);
422422
} while (wait_count > entry->count_committing_event_groups);
423423
}
424+
}
425+
426+
427+
static bool
428+
do_stop_handling(rpl_group_info *rgi)
429+
{
430+
bool should_stop= false;
431+
rpl_parallel_entry *entry= rgi->parallel_entry;
432+
433+
mysql_mutex_assert_owner(&entry->LOCK_parallel_entry);
424434

425-
if (entry->force_abort && rgi->gtid_sub_id > entry->stop_sub_id)
435+
if (unlikely(entry->force_abort) && rgi->gtid_sub_id > entry->stop_sub_id)
426436
{
427437
/*
428438
We are stopping (STOP SLAVE), and this event group need not be applied
429439
before we can safely stop. So return a flag that will cause us to skip,
430440
rather than execute, the following events. Once all queued events have
431441
been skipped, the STOP SLAVE is complete (for this thread).
432442
*/
433-
return true;
443+
should_stop= true;
434444
}
435-
else
436-
return false;
445+
446+
if (unlikely(entry->stop_on_error_sub_id <= rgi->wait_commit_sub_id))
447+
{
448+
rgi->worker_error= 1;
449+
should_stop= true;
450+
}
451+
452+
if (likely(!should_stop))
453+
{
454+
/*
455+
Since we did not decide to stop, bump the largest_started_sub_id while
456+
still holding LOCK_parallel_entry.
457+
*/
458+
if (rgi->gtid_sub_id > entry->largest_started_sub_id)
459+
entry->largest_started_sub_id= rgi->gtid_sub_id;
460+
}
461+
462+
return should_stop;
437463
}
438464

439465

@@ -480,15 +506,25 @@ do_ftwrl_wait(rpl_group_info *rgi,
480506
mysql_cond_wait(&entry->COND_parallel_entry, &entry->LOCK_parallel_entry);
481507
} while (sub_id > entry->pause_sub_id);
482508

509+
DBUG_EXECUTE_IF("delay_ftwrl_wait_gtid_0_x_100", {
510+
if (rgi->current_gtid.domain_id == 0 &&
511+
rgi->current_gtid.seq_no == 100) {
512+
/*
513+
Simulate delayed wakeup from the mysql_cond_wait(). To do this, we
514+
need to have the LOCK_parallel_entry mutex released during the wait.
515+
*/
516+
mysql_mutex_unlock(&entry->LOCK_parallel_entry);
517+
debug_sync_set_action(thd,
518+
STRING_WITH_LEN("now SIGNAL pause_wait_started WAIT_FOR pause_wait_continue"));
519+
mysql_mutex_lock(&entry->LOCK_parallel_entry);
520+
}
521+
});
483522
/*
484523
We do not call EXIT_COND() here, as this will be done later by our
485524
caller (since we set *did_enter_cond to true).
486525
*/
487526
}
488527

489-
if (sub_id > entry->largest_started_sub_id)
490-
entry->largest_started_sub_id= sub_id;
491-
492528
DBUG_RETURN(aborted);
493529
}
494530

@@ -646,7 +682,17 @@ rpl_pause_for_ftwrl(THD *thd)
646682
mysql_mutex_unlock(&rpt->LOCK_rpl_thread);
647683
++e->need_sub_id_signal;
648684
if (e->pause_sub_id == (uint64)ULONGLONG_MAX)
685+
{
649686
e->pause_sub_id= e->largest_started_sub_id;
687+
DBUG_EXECUTE_IF("pause_for_ftwrl_wait", {
688+
mysql_mutex_unlock(&e->LOCK_parallel_entry);
689+
debug_sync_set_action(thd,
690+
STRING_WITH_LEN("now "
691+
"SIGNAL pause_ftwrl_waiting "
692+
"WAIT_FOR pause_ftwrl_cont"));
693+
mysql_mutex_lock(&e->LOCK_parallel_entry);
694+
});
695+
}
650696
thd->ENTER_COND(&e->COND_parallel_entry, &e->LOCK_parallel_entry,
651697
&stage_waiting_for_ftwrl_threads_to_pause, &old_stage);
652698
thd->set_time_for_next_stage();
@@ -1284,14 +1330,15 @@ handle_rpl_parallel_thread(void *arg)
12841330
event_gtid_sub_id= rgi->gtid_sub_id;
12851331
rgi->thd= thd;
12861332

1287-
mysql_mutex_lock(&entry->LOCK_parallel_entry);
1288-
skip_event_group= do_gco_wait(rgi, gco, &did_enter_cond, &old_stage);
1333+
DBUG_EXECUTE_IF("gco_wait_delay_gtid_0_x_99", {
1334+
if (rgi->current_gtid.domain_id == 0 && rgi->current_gtid.seq_no == 99) {
1335+
debug_sync_set_action(thd,
1336+
STRING_WITH_LEN("now SIGNAL gco_wait_paused WAIT_FOR gco_wait_cont"));
1337+
} });
12891338

1290-
if (unlikely(entry->stop_on_error_sub_id <= rgi->wait_commit_sub_id))
1291-
{
1292-
skip_event_group= true;
1293-
rgi->worker_error= 1;
1294-
}
1339+
mysql_mutex_lock(&entry->LOCK_parallel_entry);
1340+
do_gco_wait(rgi, gco, &did_enter_cond, &old_stage);
1341+
skip_event_group= do_stop_handling(rgi);
12951342
if (likely(!skip_event_group))
12961343
skip_event_group= do_ftwrl_wait(rgi, &did_enter_cond, &old_stage);
12971344

0 commit comments

Comments
 (0)