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.

3 files changed, 44 insertions, 0 deletions

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