Description:
The value of 'Seconds_Behind_Master' (SBM) reports distorted number when executing a new event after rotate event.
The issue is happening only on MTS enabled Slaves. The distorted number is coming while the Slave is executing new event after Master rotate binlog for a period of time. After the rotate event is executed, the slave updates last_master_timestamp to the timestamp in the rotate event.
If master executes a new event after a period of time, and SBM is calculated while this event is executing by SQL thread, the SBM value end up in getting the time interval between rotate event and the new event, which confuses the users.
How to repeat:
rpl_sbm_rotate_event.test
--source include/master-slave.inc
--source include/have_binlog_format_row.inc
--echo #
--echo # Test Case 1
--echo #
--echo # Verify SBM should be nearly 0 after master rotate binlog
--echo # for a period of time.
--echo #
--echo # Step1: Rotate binlog, then sleep 3 seconds and sync slave
--echo # with master, make sure SBM is 0
--echo # Step2: Execute a small event on master
--echo # Step3: Varify SBM(SBM should be the time executed in Step2).
--echo #
create table t(id int not null);
insert into t values(1);
flush binary logs;
--sleep 3
--source include/sync_slave_sql_with_master.inc
--source include/rpl_connection_master.inc
insert into t values(2);
--echo #
--echo # Calculate the SBM, it should be nearly 0.
--echo #
--source include/rpl_connection_slave.inc
--let $loops=10
while ($loops)
{
--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] <= 1
--let $assert_text= Seconds_Behind_Master should be nearly 0
--source include/assert.inc
--dec $loops
}
--echo #
--echo # Test Case 2
--echo #
--echo # Verify SBM should be nearly 0 after master rotate binlog
--echo # for a period of time.
--echo #
--echo # Step1: Rotate binlog, then sleep 3 seconds and sync slave
--echo # with master, make sure SBM is 0
--echo # Step2: Stop SQL thread(Let IO thread receive events from
--echo # master and SQL thread does not execute it)
--echo # Step3: Execute a small event on master
--echo # Step4: Start SQL thread
--echo # Step5: Varify SBM(SBM should be the time interval between
--echo # Step2 and Step4).
--echo #
--source include/rpl_connection_master.inc
flush binary logs;
--sleep 3
--source include/sync_slave_sql_with_master.inc
--echo [on slave]
stop slave sql_thread;
--source include/rpl_connection_master.inc
insert into t values(3);
--source include/rpl_connection_slave.inc
start slave;
--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] <= 1
--let $assert_text= Seconds_Behind_Master should be nearly 0
--source include/assert.inc
--echo ==== Clean up ====
--source include/rpl_connection_master.inc
DROP TABLE t;
--source include/sync_slave_sql_with_master.inc
--source include/rpl_end.inc
rpl_sbm_rotate_event-slave.opt
--slave-parallel-workers=4 --slave-parallel-type=LOGICAL_CLOCK
Suggested fix:
diff --git a/sql/log_event.cc b/sql/log_event.cc
index 90d9470..bf0395c 100644
--- a/sql/log_event.cc
+++ b/sql/log_event.cc
@@ -7103,13 +7104,26 @@ int Rotate_log_event::do_update_pos(Relay_log_info *rli)
if (rli->is_parallel_exec())
{
+ /*
+ If we update last_master_timestamp in Rotate_log_event and no events are executed
+ for a period of time, Seconds_Behind_Master may show a large value until the SQL
+ thread finishes executing the new event, because the Rotate_log_event has old
+ timestamps. In such cases, if we execute SHOW SLAVE STATUS several times in a
+ relatively short period, we may see this value change between 0 and a relatively
+ large value.
+
+ So we do not update last_master_timestamp in Rotate_log_event, when
+ rpl->last_master_timestamp is 0(which indicates that GAQ is empty, all slave
+ workers are waiting for events from the Coordinator).
+ */
bool real_event= server_id && !is_artificial_event();
+ bool should_update_ts= real_event && (rli->last_master_timestamp > 0);
rli->reset_notified_checkpoint(0,
real_event ?
common_header->when.tv_sec +
(time_t) exec_time : 0,
true/*need_data_lock=true*/,
- real_event? true : false);
+ should_update_ts);
}
/*
Description: The value of 'Seconds_Behind_Master' (SBM) reports distorted number when executing a new event after rotate event. The issue is happening only on MTS enabled Slaves. The distorted number is coming while the Slave is executing new event after Master rotate binlog for a period of time. After the rotate event is executed, the slave updates last_master_timestamp to the timestamp in the rotate event. If master executes a new event after a period of time, and SBM is calculated while this event is executing by SQL thread, the SBM value end up in getting the time interval between rotate event and the new event, which confuses the users. How to repeat: rpl_sbm_rotate_event.test --source include/master-slave.inc --source include/have_binlog_format_row.inc --echo # --echo # Test Case 1 --echo # --echo # Verify SBM should be nearly 0 after master rotate binlog --echo # for a period of time. --echo # --echo # Step1: Rotate binlog, then sleep 3 seconds and sync slave --echo # with master, make sure SBM is 0 --echo # Step2: Execute a small event on master --echo # Step3: Varify SBM(SBM should be the time executed in Step2). --echo # create table t(id int not null); insert into t values(1); flush binary logs; --sleep 3 --source include/sync_slave_sql_with_master.inc --source include/rpl_connection_master.inc insert into t values(2); --echo # --echo # Calculate the SBM, it should be nearly 0. --echo # --source include/rpl_connection_slave.inc --let $loops=10 while ($loops) { --let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] <= 1 --let $assert_text= Seconds_Behind_Master should be nearly 0 --source include/assert.inc --dec $loops } --echo # --echo # Test Case 2 --echo # --echo # Verify SBM should be nearly 0 after master rotate binlog --echo # for a period of time. --echo # --echo # Step1: Rotate binlog, then sleep 3 seconds and sync slave --echo # with master, make sure SBM is 0 --echo # Step2: Stop SQL thread(Let IO thread receive events from --echo # master and SQL thread does not execute it) --echo # Step3: Execute a small event on master --echo # Step4: Start SQL thread --echo # Step5: Varify SBM(SBM should be the time interval between --echo # Step2 and Step4). --echo # --source include/rpl_connection_master.inc flush binary logs; --sleep 3 --source include/sync_slave_sql_with_master.inc --echo [on slave] stop slave sql_thread; --source include/rpl_connection_master.inc insert into t values(3); --source include/rpl_connection_slave.inc start slave; --let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] <= 1 --let $assert_text= Seconds_Behind_Master should be nearly 0 --source include/assert.inc --echo ==== Clean up ==== --source include/rpl_connection_master.inc DROP TABLE t; --source include/sync_slave_sql_with_master.inc --source include/rpl_end.inc rpl_sbm_rotate_event-slave.opt --slave-parallel-workers=4 --slave-parallel-type=LOGICAL_CLOCK Suggested fix: diff --git a/sql/log_event.cc b/sql/log_event.cc index 90d9470..bf0395c 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -7103,13 +7104,26 @@ int Rotate_log_event::do_update_pos(Relay_log_info *rli) if (rli->is_parallel_exec()) { + /* + If we update last_master_timestamp in Rotate_log_event and no events are executed + for a period of time, Seconds_Behind_Master may show a large value until the SQL + thread finishes executing the new event, because the Rotate_log_event has old + timestamps. In such cases, if we execute SHOW SLAVE STATUS several times in a + relatively short period, we may see this value change between 0 and a relatively + large value. + + So we do not update last_master_timestamp in Rotate_log_event, when + rpl->last_master_timestamp is 0(which indicates that GAQ is empty, all slave + workers are waiting for events from the Coordinator). + */ bool real_event= server_id && !is_artificial_event(); + bool should_update_ts= real_event && (rli->last_master_timestamp > 0); rli->reset_notified_checkpoint(0, real_event ? common_header->when.tv_sec + (time_t) exec_time : 0, true/*need_data_lock=true*/, - real_event? true : false); + should_update_ts); } /*