MDEV-30619: Parallel Slave SQL Thread Can Update Seconds_Behind_Master with Active Workers

MDEV-31749 sporadic assert in MDEV-30619 new test

If the workers of a parallel replica are busy (potentially with long
queues), but the SQL thread has no events left to distribute (so it
goes idle), then the next event that comes from the primary will
update mi->last_master_timestamp with its timestamp, even if the
workers have not yet finished.

This patch changes the parallel replica logic which updates
last_master_timestamp after idling from using solely sql_thread_caught_up
(added in MDEV-29639) to using the latter with rli queued/dequeued
event counters.
That is, if  the queued count is equal to the dequeued count, it
means all events have been processed and the replica is considered
idle when the driver thread has also distributed all events.

Low level details of the commit include
- to make a more generalized test for Seconds_Behind_Master on
  the parallel replica, rpl_delayed_parallel_slave_sbm.test
  is renamed to rpl_parallel_sbm.test for this purpose.
- pause_sql_thread_on_next_event usage was removed
  with the MDEV-30619 fixes. Rather than remove it, we adapt it
  to the needs of this test case
- added test case to cover SBM spike of relay log read and LMT
  update that was fixed by MDEV-29639
- rpl_seconds_behind_master_spike.test is made to use
  the negate_clock_diff_with_master debug eval.

Reviewed By:
============
Andrei Elkin <andrei.elkin@mariadb.com>

mysql-test/suite/rpl/r/rpl_delayed_parallel_slave_sbm.result → mysql-test/suite/rpl/r/rpl_parallel_sbm.result

 include/master-slave.inc
 [connection master]
+#
+# MDEV-29639: Seconds_Behind_Master is incorrect for Delayed, Parallel Replicas
+#
 connection slave;
 include/stop_slave.inc
+set @@GLOBAL.debug_dbug= "d,negate_clock_diff_with_master";
+set @@GLOBAL.slave_parallel_mode= CONSERVATIVE;
 change master to master_delay=3, master_use_gtid=Slave_Pos;
-set @@GLOBAL.slave_parallel_threads=2;
 include/start_slave.inc
 connection master;
 create table t1 (a int);
+create table t2 (a int);
 include/sync_slave_sql_with_master.inc
 #
 # Pt 1) Ensure SBM is updated immediately upon arrival of the next event
@@ -25,11 +30,10 @@ connection slave;
 UNLOCK TABLES;
 include/sync_with_master_gtid.inc
 #
-# Pt 2) If the SQL thread has not entered an idle state, ensure
+# Pt 2) If the worker threads have not entered an idle state, ensure
 # following events do not update SBM
-# Stop slave IO thread so it receives both events together on restart
 connection slave;
-include/stop_slave_io.inc
+LOCK TABLES t1 WRITE;
 connection master;
 # Sleep 2 to allow a buffer between events for SBM check
 insert into t1 values (1);
@@ -37,36 +41,49 @@ insert into t1 values (1);
 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..
+# Validate SBM calculation doesn't use the second transaction because worker threads shouldn't have gone idle..
 # ..and that SBM wasn't calculated using prior committed transactions
 # ..done
 connection slave;
 UNLOCK TABLES;
-#
+include/wait_for_slave_param.inc [Relay_Master_Log_File]
+include/wait_for_slave_param.inc [Exec_Master_Log_Pos]
 # Cleanup
-# Reset master_delay
 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
+#
+# MDEV-30619: Parallel Slave SQL Thread Can Update Seconds_Behind_Master with Active Workers
+#
+connection slave;
+# Ensure the replica is fully idle before starting transactions
+# Lock t1 on slave so the first received transaction does not complete/commit
+LOCK TABLES t1 WRITE;
 connection master;
-DROP TABLE t1;
+insert into t1 values (3);
 include/save_master_gtid.inc
 connection slave;
+# Waiting for first transaction to begin..
+connection master;
+# Sleep 2 sec to create a gap between events
+INSERT INTO t2 VALUES (1);
+include/save_master_gtid.inc
+connection slave;
+# Waiting for second transaction to begin..
+connection slave;
+UNLOCK TABLES;
 include/sync_with_master_gtid.inc
+#
+# Cleanup
+connection master;
+DROP TABLE t1, t2;
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+include/stop_slave.inc
+set @@GLOBAL.debug_dbug= "";
+set @@GLOBAL.slave_parallel_mode= "$save_parallel_mode";
+include/start_slave.inc
 include/rpl_end.inc
-# End of rpl_delayed_parallel_slave_sbm.test
+# End of rpl_parallel_sbm.test

mysql-test/suite/rpl/r/rpl_seconds_behind_master_spike.result

@@ -3,7 +3,7 @@ include/master-slave.inc
 connection slave;
 include/stop_slave.inc
 SET @save_dbug= @@GLOBAL.debug_dbug;
-SET @@global.debug_dbug="+d,pause_sql_thread_on_fde";
+SET @@global.debug_dbug="+d,pause_sql_thread_on_fde,negate_clock_diff_with_master";
 include/start_slave.inc
 # Future events must be logged at least 2 seconds after
 # the slave starts
@@ -34,8 +34,31 @@ SET @@global.debug_dbug="-d,pause_sql_thread_on_fde";
 SET DEBUG_SYNC='now SIGNAL sql_thread_continue';
 # Wait for SQL thread to continue into normal execution
 SET DEBUG_SYNC='RESET';
+#
+# MDEV-29639
+# When receiving an event after the SQL Thread idles,
+# Seconds_Behind_Master should not update before it updates
+# last_master_timestamp
+connection slave;
+include/stop_slave.inc
+set @@global.debug_dbug="+d,pause_sql_thread_on_next_event";
+include/start_slave.inc
 connection master;
-DROP TABLE t1;
+insert into t1 values(2);
+include/save_master_gtid.inc
+connection slave;
+set debug_sync='now wait_for paused_on_event';
+connection master;
+# Sleeping 1s to create a visible SBM gap between events
+insert into t1 values(3);
+include/save_master_gtid.inc
 connection slave;
+set debug_sync='now wait_for paused_on_event';
+include/stop_slave.inc
+set debug_sync='RESET';
 SET @@global.debug_dbug=$save_dbug;
+include/start_slave.inc
+include/sync_with_master_gtid.inc
+connection master;
+DROP TABLE t1;
 include/rpl_end.inc

mysql-test/suite/rpl/t/rpl_delayed_parallel_slave_sbm-slave.opt

---slave-parallel-threads=4

mysql-test/suite/rpl/t/rpl_parallel_sbm-slave.opt

+--slave-parallel-threads=2

mysql-test/suite/rpl/t/rpl_delayed_parallel_slave_sbm.test → mysql-test/suite/rpl/t/rpl_parallel_sbm.test

 #
+#   Ensure that Seconds_Behind_Master works correctly on the parallel replica.
+#
+--source include/master-slave.inc
+--source include/have_log_bin.inc
+--source include/have_debug.inc
+
+--echo #
+--echo # MDEV-29639: Seconds_Behind_Master is incorrect for Delayed, Parallel Replicas
+--echo #
+
 #   This test ensures that after a delayed parallel slave has idled, i.e.
 # executed everything in its relay log, the next event group that the SQL
 # thread reads from the relay log will immediately be used in the
@@ -6,26 +16,21 @@
 # Seconds_Behind_Master is based on the timestamp of the new transaction,
 # rather than the last committed transaction.
 #
-# References:
-#   MDEV-29639: Seconds_Behind_Master is incorrect for Delayed, Parallel
-#               Replicas
-#
-
---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 $save_dbug= `SELECT @@GLOBAL.debug_dbug`
+--let $save_parallel_mode= `SELECT @@GLOBAL.slave_parallel_mode`
+set @@GLOBAL.debug_dbug= "d,negate_clock_diff_with_master";
+set @@GLOBAL.slave_parallel_mode= CONSERVATIVE;
 --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`
-set @@GLOBAL.slave_parallel_threads=2;
 --source include/start_slave.inc
 
 --connection master
+--let insert_ctr= 0
 create table t1 (a int);
+create table t2 (a int);
 --source include/sync_slave_sql_with_master.inc
 
 --echo #
@@ -40,7 +45,6 @@ LOCK TABLES t1 WRITE;
 sleep 2;
 
 --let $ts_trx_before_ins= `SELECT UNIX_TIMESTAMP()`
---let insert_ctr= 0
 --eval insert into t1 values ($insert_ctr)
 --inc $insert_ctr
 --source include/save_master_gtid.inc
@@ -66,15 +70,13 @@ UNLOCK TABLES;
 --source include/sync_with_master_gtid.inc
 
 --echo #
---echo # Pt 2) If the SQL thread has not entered an idle state, ensure
+--echo # Pt 2) If the worker threads have not entered an idle state, ensure
 --echo # following events do not update SBM
 
---echo # Stop slave IO thread so it receives both events together on restart
 --connection slave
---source include/stop_slave_io.inc
+LOCK TABLES t1 WRITE;
 
 --connection master
-
 --echo # Sleep 2 to allow a buffer between events for SBM check
 sleep 2;
 --let $ts_trxpt2_before_ins= `SELECT UNIX_TIMESTAMP()`
@@ -88,29 +90,14 @@ sleep 3;
 --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
 
---echo # Validate SBM calculation doesn't use the second transaction because SQL thread shouldn't have gone idle..
+--echo # Validate SBM calculation doesn't use the second transaction because worker threads shouldn't have gone idle..
 --let $sbm_after_trx_no_idle= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
 --let $timestamp_trxpt2_arrive= `SELECT UNIX_TIMESTAMP()`
-if (`SELECT $sbm_after_trx_no_idle < $timestamp_trxpt2_arrive - $ts_trx_after_ins`)
+if (`SELECT $sbm_after_trx_no_idle < $timestamp_trxpt2_arrive - $ts_trx_after_ins - 1`)
 {
     --let $cmpv= `SELECT $timestamp_trxpt2_arrive - $ts_trx_after_ins`
     --echo # SBM $sbm_after_trx_no_idle was more recent than time since last transaction ($cmpv seconds)
@@ -127,24 +114,86 @@ if (`SELECT $sbm_after_trx_no_idle > ($seconds_since_idling + 1)`)
 
 --connection slave
 UNLOCK TABLES;
+--source include/sync_with_master.inc
 
---echo #
 --echo # Cleanup
-
---echo # Reset master_delay
 --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
 
+
+--echo #
+--echo # MDEV-30619: Parallel Slave SQL Thread Can Update Seconds_Behind_Master with Active Workers
+--echo #
+
+#   This test ensures that a parallel slave will not update
+# Seconds_Behind_Master after the SQL Thread has idled if the worker threads
+# are still executing events. To test this, two events are executed on the
+# primary with $sleep seconds in-between them. Once the second event begins
+# execution on the replica, Seconds_Behind_Master is queried to ensure it
+# reflects the value of the first transaction, rather than the second.
+
+--connection slave
+--echo # Ensure the replica is fully idle before starting transactions
+--let $wait_condition= SELECT count(*) FROM information_schema.processlist WHERE state LIKE 'Slave has read all relay log%';
+--source include/wait_condition.inc
+--let $wait_condition= SELECT count(*)=2 FROM information_schema.processlist WHERE state LIKE 'Waiting for work from SQL thread';
+--source include/wait_condition.inc
+
+--echo # Lock t1 on slave so the first received transaction does not complete/commit
+LOCK TABLES t1 WRITE;
+
+--connection master
+--let $ts_t1_before_master_ins= `SELECT UNIX_TIMESTAMP()`
+--eval insert into t1 values ($insert_ctr)
+--inc $insert_ctr
+--source include/save_master_gtid.inc
+
+--connection slave
+--echo # Waiting for first transaction to begin..
+--let $wait_condition= SELECT count(*) FROM information_schema.processlist WHERE state LIKE 'Waiting for table metadata lock';
+--source include/wait_condition.inc
+
+--let $sbm_1= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
+
 --connection master
-DROP TABLE t1;
+--let $sleep = 2
+--echo # Sleep $sleep sec to create a gap between events
+sleep $sleep;
+INSERT INTO t2 VALUES (1);
 --source include/save_master_gtid.inc
 
 --connection slave
+--echo # Waiting for second transaction to begin..
+--let $wait_condition= SELECT count(*) FROM information_schema.processlist WHERE state LIKE 'Waiting for prior transaction to start commit%';
+--source include/wait_condition.inc
+
+--let $sbm_2= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
+
+if (`SELECT $sbm_1 + $sleep > $sbm_2`)
+{
+    --echo # Seconds_Behind_Masters: $sbm_1 $sbm_2_0
+    --die Two successive Seconds_Behind_Master timestamps must be separated by the sleep parameter value or greater
+}
+
+--connection slave
+UNLOCK TABLES;
 --source include/sync_with_master_gtid.inc
 
+
+--echo #
+--echo # Cleanup
+
+--connection master
+DROP TABLE t1, t2;
+--source include/save_master_gtid.inc
+
+--connection slave
+--source include/sync_with_master_gtid.inc
+--source include/stop_slave.inc
+--eval  set @@GLOBAL.debug_dbug= "$save_dbug"
+--evalp set @@GLOBAL.slave_parallel_mode= "$save_parallel_mode"
+--source include/start_slave.inc
+
 --source include/rpl_end.inc
---echo # End of rpl_delayed_parallel_slave_sbm.test
+--echo # End of rpl_parallel_sbm.test

mysql-test/suite/rpl/t/rpl_seconds_behind_master_spike.test

@@ -27,7 +27,7 @@
 --connection slave
 --source include/stop_slave.inc
 SET @save_dbug= @@GLOBAL.debug_dbug;
-SET @@global.debug_dbug="+d,pause_sql_thread_on_fde";
+SET @@global.debug_dbug="+d,pause_sql_thread_on_fde,negate_clock_diff_with_master";
 --source include/start_slave.inc
 
 --let $sleep_time=2
@@ -93,11 +93,93 @@ SET DEBUG_SYNC='now SIGNAL sql_thread_continue';
 # Reset last sql_thread_continue signal
 SET DEBUG_SYNC='RESET';
 
-# Cleanup
+
+--echo #
+--echo # MDEV-29639
+--echo # When receiving an event after the SQL Thread idles,
+--echo # Seconds_Behind_Master should not update before it updates
+--echo # last_master_timestamp
+
+--connection slave
+--source include/stop_slave.inc
+set @@global.debug_dbug="+d,pause_sql_thread_on_next_event";
+--source include/start_slave.inc
+
 --connection master
-DROP TABLE t1;
+insert into t1 values(2);
+--source include/save_master_gtid.inc
+
+# Each event after starting will trigger a pause, so continually send signal
+# sql_thread_continue until caught up
+--connection slave
+--let $caught_up=0
+--let $tries= 0
+set debug_sync='now wait_for paused_on_event';
+--disable_query_log
+while (!$caught_up)
+{
+    set debug_sync='now signal sql_thread_continue';
+    --let $slave_gtid= `SELECT @@global.gtid_slave_pos`
+    if (`SELECT strcmp("$master_pos","$slave_gtid") = 0`)
+    {
+        --inc $caught_up
+    }
+    --inc $tries
+    # Wait 30s
+    if (`SELECT $tries > 300`)
+    {
+        --die Replica failed to sync with primary
+    }
+    sleep 0.1;
+}
+--enable_query_log
+
+--connection master
+--echo # Sleeping 1s to create a visible SBM gap between events
+sleep 1;
+insert into t1 values(3);
+--source include/save_master_gtid.inc
 
 --connection slave
+set debug_sync='now wait_for paused_on_event';
+--let $sbm= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
+
+if ($sbm)
+{
+    --echo # Expected Seconds_Behind_Master to be 0 but was $sbm
+    --die Seconds_Behind_Master should not show updates before last_master_timestamp is updated
+}
+
+# Continually send signal sql_thread_continue until caught up
+--let $caught_up=0
+--let $tries= 0
+--disable_query_log
+while (!$caught_up)
+{
+    set debug_sync='now signal sql_thread_continue';
+    --let $slave_gtid= `SELECT @@global.gtid_slave_pos`
+    if (`SELECT strcmp("$master_pos","$slave_gtid") = 0`)
+    {
+        --inc $caught_up
+    }
+    --inc $tries
+    # Wait 30s
+    if (`SELECT $tries > 300`)
+    {
+        --die Replica failed to sync with primary
+    }
+    sleep 0.1;
+}
+--enable_query_log
+
+# Cleanup
+--source include/stop_slave.inc
+set debug_sync='RESET';
 SET @@global.debug_dbug=$save_dbug;
+--source include/start_slave.inc
+--source include/sync_with_master_gtid.inc
+
+--connection master
+DROP TABLE t1;
 
 --source include/rpl_end.inc

sql/slave.cc

@@ -1857,8 +1857,10 @@ static int get_master_version_and_clock(MYSQL* mysql, Master_info* mi)
       (master_row= mysql_fetch_row(master_res)))
   {
     mysql_mutex_lock(&mi->data_lock);
-    mi->clock_diff_with_master=
-      (long) (time((time_t*) 0) - strtoul(master_row[0], 0, 10));
+    mi->clock_diff_with_master= DBUG_EVALUATE_IF(
+        "negate_clock_diff_with_master", 0,
+        (long) (time((time_t *) 0) - strtoul(master_row[0], 0, 10)));
+
     mysql_mutex_unlock(&mi->data_lock);
   }
   else if (check_io_slave_killed(mi, NULL))
@@ -3187,6 +3189,14 @@ static bool send_show_master_info_data(THD *thd, Master_info *mi, bool full,
       else
       {
         idle= mi->rli.sql_thread_caught_up;
+
+        /*
+          The idleness of the SQL thread is needed for the parallel slave
+          because events can be ignored before distribution to a worker thread.
+          That is, Seconds_Behind_Master should still be calculated and visible
+          while the slave is processing ignored events, such as those skipped
+          due to slave_skip_counter.
+        */
         if (mi->using_parallel() && idle && !mi->rli.parallel.workers_idle())
           idle= false;
       }
@@ -4146,7 +4156,6 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli,
               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);
         });
 
@@ -4163,7 +4172,8 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli,
       the user might be surprised to see a claim that the slave is up to date
       long before those queued events are actually executed.
      */
-    if ((!rli->mi->using_parallel()) && event_can_update_last_master_timestamp(ev))
+    if ((!rli->mi->using_parallel()) &&
+        event_can_update_last_master_timestamp(ev))
     {
       rli->last_master_timestamp= ev->when + (time_t) ev->exec_time;
       rli->sql_thread_caught_up= false;
@@ -4218,9 +4228,22 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli,
 
     if (rli->mi->using_parallel())
     {
-      if (unlikely((rli->last_master_timestamp == 0 ||
-                    rli->sql_thread_caught_up) &&
-                   event_can_update_last_master_timestamp(ev)))
+      /*
+        rli->sql_thread_caught_up is checked and negated here to ensure that
+        the value of Seconds_Behind_Master in SHOW SLAVE STATUS is consistent
+        with the update of last_master_timestamp. It was previously unset
+        immediately after reading an event from the relay log; however, for the
+        duration between that unset and the time that LMT would be updated
+        could lead to spikes in SBM.
+
+        The check for queued_count == dequeued_count ensures the worker threads
+        are all idle (i.e. all events have been executed).
+      */
+      if ((unlikely(rli->last_master_timestamp == 0) ||
+           (rli->sql_thread_caught_up &&
+            (rli->last_inuse_relaylog->queued_count ==
+             rli->last_inuse_relaylog->dequeued_count))) &&
+          event_can_update_last_master_timestamp(ev))
       {
         if (rli->last_master_timestamp < ev->when)
         {