From 01fafd45eba396cb051641134ec07b9e43e71483 Mon Sep 17 00:00:00 2001 From: Brandon Nesterenko Date: Sun, 26 Jan 2025 09:17:20 -0700 Subject: [PATCH] MDEV-35939: rpl.rpl_parallel_sbm: "Slave_last_event_time is not equal to Master_last_event_time" The test rpl.rpl_parallel_sbm would fail because Slave_last_event_time would not match Master_last_event_time after syncing with the master (i.e. via sync_with_master_gtid.inc). This happens because the timing statistics are updated after updating gtid_slave_pos. That is, gtid_slave_pos is updated with the transaction commit, whereas the timing statistics are updated when the relay log position is updated (i.e. after the commit). This is by design. For the test, this means there is a small amount of time after sync_with_master_gtid.inc where the SHOW SLAVE STATUS output lags behind the data state of the slave. This would cause the test to fail if comparing Slave_last_event_time to Master_last_event_time during this period, because Slave_last_event_time would not yet reflect the latest committed transaction. The fix is to add a wait_condition before the comparison to wait for the SHOW SLAVE STATUS statistics to be updated. The actual check is to wait for Seconds_Behind_Master == 0, because the slave should be idle at this point, which forces the value to be 0. The test failure can be reproduced with the following patch: diff --git a/sql/rpl_gtid.cc b/sql/rpl_gtid.cc index db5c26b6237..b346a32b573 100644 --- a/sql/rpl_gtid.cc +++ b/sql/rpl_gtid.cc @@ -300,6 +300,7 @@ rpl_slave_state::update(uint32 domain_id, uint32 server_id, uint64 sub_id, mysql_mutex_lock(&LOCK_slave_state); res= update_nolock(domain_id, server_id, sub_id, seq_no, hton, rgi); mysql_mutex_unlock(&LOCK_slave_state); + sleep(1); return res; } --- mysql-test/suite/rpl/r/rpl_parallel_sbm.result | 1 + mysql-test/suite/rpl/t/rpl_parallel_sbm.test | 9 +++++++++ 2 files changed, 10 insertions(+) diff --git a/mysql-test/suite/rpl/r/rpl_parallel_sbm.result b/mysql-test/suite/rpl/r/rpl_parallel_sbm.result index 1c00180b3cc7f..43ae0b663fadd 100644 --- a/mysql-test/suite/rpl/r/rpl_parallel_sbm.result +++ b/mysql-test/suite/rpl/r/rpl_parallel_sbm.result @@ -68,6 +68,7 @@ connection server_2; UNLOCK TABLES; include/sync_with_master_gtid.inc # MDEV-33856: New definition for Seconds_Behind_Master +# Waiting for slave timing statistics to update .. # Ensuring Slave_last_event_time is now up-to-date once event is executed # ..done # diff --git a/mysql-test/suite/rpl/t/rpl_parallel_sbm.test b/mysql-test/suite/rpl/t/rpl_parallel_sbm.test index 91c566a123499..c269c4d96cd07 100644 --- a/mysql-test/suite/rpl/t/rpl_parallel_sbm.test +++ b/mysql-test/suite/rpl/t/rpl_parallel_sbm.test @@ -154,6 +154,15 @@ UNLOCK TABLES; --source include/sync_with_master_gtid.inc --echo # MDEV-33856: New definition for Seconds_Behind_Master + +# The update of slave timing statistics (Seconds_Behind_Master, +# Slave_last_event_time, etc) lags slightly behind the update of +# gtid_slave_pos (we just called sync_with_master_gtid), so wait for SBM==0 to +# indicate the statistics have been updated +--echo # Waiting for slave timing statistics to update .. +--let $wait_condition= SELECT count(*) FROM information_schema.slave_status WHERE Seconds_Behind_Master=0 +--source include/wait_condition.inc + --echo # Ensuring Slave_last_event_time is now up-to-date once event is executed --let $slave_time_trx1_commit= query_get_value(SHOW ALL SLAVES STATUS, Slave_last_event_time, 1) --let $slave_time_trx1_commit_unix= `SELECT truncate(unix_timestamp("$slave_time_trx1_commit"),0)`