From eecd4f1459214b84207b426ed87e12fd89f236af Mon Sep 17 00:00:00 2001 From: Brandon Nesterenko Date: Wed, 8 Feb 2023 10:32:35 -0700 Subject: [PATCH] MDEV-30608: rpl.rpl_delayed_parallel_slave_sbm sometimes fails with Seconds_Behind_Master should not have used second transaction timestamp One of the constraints added in the MDEV-29639 patch, is that only the first event after idling should update last_master_timestamp; and as long as the replica has more events to execute, the variable should not be updated. The corresponding test, rpl_delayed_parallel_slave_sbm.test, aims to verify this; however, if the IO thread takes too long to queue events, the SQL thread can appear to catch up too fast. This fix ensures that the relay log has been fully written before executing the events. Note that the underlying cause of this test failure needs to be addressed as a bug-fix, this is a temporary fix to stop test failures. To track work on the bug-fix for the underlying issue, please see MDEV-30619. --- .../rpl/r/rpl_delayed_parallel_slave_sbm.result | 12 ++++++++++++ .../rpl/t/rpl_delayed_parallel_slave_sbm.test | 17 +++++++++++++++++ sql/slave.cc | 15 +++++++++++++++ 3 files changed, 44 insertions(+) diff --git a/mysql-test/suite/rpl/r/rpl_delayed_parallel_slave_sbm.result b/mysql-test/suite/rpl/r/rpl_delayed_parallel_slave_sbm.result index f783b1e0783..b00a8a5e1d7 100644 --- a/mysql-test/suite/rpl/r/rpl_delayed_parallel_slave_sbm.result +++ b/mysql-test/suite/rpl/r/rpl_delayed_parallel_slave_sbm.result @@ -35,9 +35,19 @@ connection master; insert into t1 values (1); # Sleep 3 to create gap between events insert into t1 values (2); +include/save_master_pos.inc connection slave; LOCK TABLES t1 WRITE; +SET @@global.debug_dbug="+d,pause_sql_thread_on_next_event"; START SLAVE IO_THREAD; +# Before we start processing the events, we ensure both transactions +# were written into the relay log. Otherwise, if the IO thread takes too +# long to queue the events, the sql thread can think it has caught up +# too quickly. +SET DEBUG_SYNC='now WAIT_FOR paused_on_event'; +include/sync_io_with_master.inc +SET @@global.debug_dbug="-d,pause_sql_thread_on_next_event"; +SET DEBUG_SYNC='now SIGNAL sql_thread_continue'; # Wait for first transaction to complete SQL delay and begin execution.. # Validate SBM calculation doesn't use the second transaction because SQL thread shouldn't have gone idle.. # ..and that SBM wasn't calculated using prior committed transactions @@ -50,6 +60,8 @@ UNLOCK TABLES; include/stop_slave.inc CHANGE MASTER TO master_delay=0; set @@GLOBAL.slave_parallel_threads=4; +SET @@global.debug_dbug=""; +SET DEBUG_SYNC='RESET'; include/start_slave.inc connection master; DROP TABLE t1; diff --git a/mysql-test/suite/rpl/t/rpl_delayed_parallel_slave_sbm.test b/mysql-test/suite/rpl/t/rpl_delayed_parallel_slave_sbm.test index 4bcb7ad9e3f..1ac1bc14468 100644 --- a/mysql-test/suite/rpl/t/rpl_delayed_parallel_slave_sbm.test +++ b/mysql-test/suite/rpl/t/rpl_delayed_parallel_slave_sbm.test @@ -12,9 +12,12 @@ # --source include/master-slave.inc +--source include/have_debug.inc +--source include/have_debug_sync.inc --connection slave --source include/stop_slave.inc +--let $old_debug_dbug= `SELECT @@global.debug_dbug` --let $master_delay= 3 --eval change master to master_delay=$master_delay, master_use_gtid=Slave_Pos --let $old_slave_threads= `SELECT @@GLOBAL.slave_parallel_threads` @@ -82,12 +85,24 @@ sleep 3; --eval insert into t1 values ($insert_ctr) --inc $insert_ctr --let $ts_trx_after_ins= `SELECT UNIX_TIMESTAMP()` +--source include/save_master_pos.inc --connection slave LOCK TABLES t1 WRITE; +SET @@global.debug_dbug="+d,pause_sql_thread_on_next_event"; + START SLAVE IO_THREAD; +--echo # Before we start processing the events, we ensure both transactions +--echo # were written into the relay log. Otherwise, if the IO thread takes too +--echo # long to queue the events, the sql thread can think it has caught up +--echo # too quickly. +SET DEBUG_SYNC='now WAIT_FOR paused_on_event'; +--source include/sync_io_with_master.inc +SET @@global.debug_dbug="-d,pause_sql_thread_on_next_event"; +SET DEBUG_SYNC='now SIGNAL sql_thread_continue'; + --echo # Wait for first transaction to complete SQL delay and begin execution.. --let $wait_condition= SELECT count(*) FROM information_schema.processlist WHERE state LIKE 'Waiting for table metadata lock%' AND command LIKE 'Slave_Worker'; --source include/wait_condition.inc @@ -120,6 +135,8 @@ UNLOCK TABLES; --source include/stop_slave.inc --eval CHANGE MASTER TO master_delay=0 --eval set @@GLOBAL.slave_parallel_threads=$old_slave_threads +--eval SET @@global.debug_dbug="$old_debug_dbug" +SET DEBUG_SYNC='RESET'; --source include/start_slave.inc --connection master diff --git a/sql/slave.cc b/sql/slave.cc index c788a206435..42c293dfce4 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -4135,6 +4135,21 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli, int exec_res; Log_event_type typ= ev->get_type_code(); + DBUG_EXECUTE_IF( + "pause_sql_thread_on_next_event", + { + /* + Temporarily unlock data_lock so we can check-in with the IO thread + */ + mysql_mutex_unlock(&rli->data_lock); + DBUG_ASSERT(!debug_sync_set_action( + thd, + STRING_WITH_LEN( + "now SIGNAL paused_on_event WAIT_FOR sql_thread_continue"))); + DBUG_SET("-d,pause_sql_thread_on_next_event"); + mysql_mutex_lock(&rli->data_lock); + }); + /* Even if we don't execute this event, we keep the master timestamp, so that seconds behind master shows correct delta (there are events