Bug #53167 Seconds_Behind_Master is wrong after start slave
Submitted: 26 Apr 2010 15:34 Modified: 29 Nov 2010 22:04
Reporter: Sven Sandberg Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.1+ OS:Any
Assigned to: Daogang Qu
Tags: Seconds_Behind_Master, start slave
Triage: Triaged: D3 (Medium)

[26 Apr 2010 15:34] Sven Sandberg
Description:
When a slave server has an existing relay log and the user issues START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong value for Seconds_Behind_Master until the first event from the relay log has finished executing. The displayed value for Seconds_Behind_Master is calculated based on the timestamp of the relay log's Format_Description_Log_Event. This can be a very big number if the relay log was created long ago.

After BUG#52166 has been fixed, this bug still exists. However, the time window during which the wrong value is displayed is much smaller. Before BUG#52166 has been fixed, the time window is from when START SLAVE is executed to *after* the first event from the relay log has been processed. After BUG#52166 has been fixed, the time window is from when START SLAVE is executed to *before* the first event from the relay log has been processed, i.e., almost immediately.

How to repeat:
--source include/master-slave.inc
--source include/have_binlog_format_statement.inc

--let $master_datadir= `SELECT @@datadir`

--sleep 2

CREATE TABLE t1 (a VARCHAR(100));

--eval CREATE FUNCTION delay_on_slave(seconds INT) RETURNS INT BEGIN IF @@server_id = 2 THEN RETURN SLEEP(seconds); ELSE RETURN 0; END IF; END
--sync_slave_with_master

--sleep 2

# Seconds_Behind_Master = 0, ok
--let $sbm= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
--echo Seconds_Behind_Master 1= $sbm

--connection master
INSERT INTO t1 VALUES ('let slave get synced');
INSERT INTO t1 VALUES ('let slave get synced');
--sync_slave_with_master

# Seconds_Behind_Master = 0, ok
--let $sbm= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
--echo Seconds_Behind_Master 2= $sbm

--source include/stop_slave.inc
--source include/start_slave.inc

# Seconds_Behind_Master = 0, ok
--let $sbm= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
--echo Seconds_Behind_Master 3= $sbm

--connection master
INSERT INTO t1 VALUES (delay_on_slave(4));
--save_master_pos
--connection slave

--sleep 2

# Now Seconds_Behind_Master is wrong. It is calculated based on the
# timestamp of the Format_description_log_event.
--let $sbm= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
--let $pos= query_get_value(SHOW SLAVE STATUS, Exec_Master_Log_Pos, 1)
--let $now= `SELECT NOW()`
--echo Seconds_Behind_Master 4= $sbm pos=$pos now=$now
--exec $MYSQL_BINLOG $master_datadir/master-bin.000001 | grep '^#'

--sleep 4

--let $sbm= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
--echo Seconds_Behind_Master 5= $sbm

--sync_with_master
[26 Apr 2010 15:51] Valerii Kravchuk
What exact trees should we use to verify this bug?
[26 Apr 2010 16:36] Sven Sandberg
It should exist in all 5.1 trees and up.
(BUG#52166 has not yet been pushed.)
[16 Aug 2010 8:41] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/115757

3192 Dao-Gang.Qu@sun.com	2010-08-16
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the relay log's
      Format_Description_Log_Event. This can be a very big number if the relay
      log was created long ago.
      
      The Timestamp recorded in Format_Description_Log_Event is not available
      when executing the Format_Description_Log_Event on slave. So do not assign
      the Timestamp of the Format_Description_Log_Event to last_master_timestamp.
      The the peak value will disappear.
     @ sql/rpl_slave.cc
        Adde code to make sure that the Timestamp of Format_Description_Log_Event
        will be smaller than the last executed event on slave. It is not reasonable
        and then "rpl_seconds_behind_master" test will cause abort by the added
        DEBUG_ASSERT. The test will run OK if we do not assign the Timestamp of
        Format_Description_Log_Event to the last_master_timestamp on slave.
[20 Aug 2010 7:39] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/116338

3192 Dao-Gang.Qu@sun.com	2010-08-20
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the relay log's
      Format_Description_Log_Event. This can be a very big number if the relay
      log was created long ago.
      
      The Timestamp recorded in Format_Description_Log_Event should not be used
      when executing the Format_Description_Log_Event on slave. So do not assign
      the Timestamp of the Format_Description_Log_Event to last_master_timestamp.
      The the peak value will disappear.
     @ sql/rpl_slave.cc
        Adde code to make sure that the Timestamp of Format_Description_Log_Event
        will be smaller than the last executed event on slave. It is not reasonable
        and then "rpl_seconds_behind_master" test will cause abort by the added
        DEBUG_ASSERT. The test will run OK if we do not assign the Timestamp of
        Format_Description_Log_Event to the last_master_timestamp on slave.
[26 Aug 2010 7:14] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/116825

3192 Dao-Gang.Qu@sun.com	2010-08-26
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the Format_Description_Log_Event
      from master. This can be a very big number if the relay log was created
      long ago.
      
      The Timestamp recorded in Format_Description_Log_Event should not be used
      when executing the Format_Description_Log_Event on slave. So do not assign
      the Timestamp of the Format_Description_Log_Event to last_master_timestamp.
      Then the peak value will disappear. And we just update last_master_timestamp
      at the end of a transaction (to non-transation, treat every statement as a
      transaction as it is enclosed with 'BEGIN' and 'COMMIT' in binary log) for
      making the value of Seconds_Behind_Master more reasonable.
     @ mysql-test/suite/rpl/r/rpl_seconds_behind_master.result
        Updated for the patch of Bug #53167.
     @ mysql-test/suite/rpl/t/rpl_delayed_slave.test
        Updated for the patch of Bug #53167.
     @ mysql-test/suite/rpl/t/rpl_seconds_behind_master.test
        Updated for the patch of Bug #53167.
     @ sql/binlog.cc
        Added code to set LOG_EVENT_RELAY_LOG_F flag for relay log's FD
     @ sql/rpl_slave.cc
        Added code to update the last_master_timestamp at the end of a
        transaction(to non-transation, treat every statement as a transaction
        as it is enclosed with 'BEGIN' and 'COMMIT' in binary log) for
        making the value of Seconds_Behind_Master more reasonable.
[26 Aug 2010 7:22] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/116826

3192 Dao-Gang.Qu@sun.com	2010-08-26
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the Format_Description_Log_Event
      from master. This can be a very big number if the relay log was created
      long ago.
      
      The Timestamp recorded in Format_Description_Log_Event should not be used
      when executing the Format_Description_Log_Event on slave. So do not assign
      the Timestamp of the Format_Description_Log_Event to last_master_timestamp.
      Then the peak value will disappear. And we just update last_master_timestamp
      at the end of a transaction (to non-transation, treat every statement as a
      transaction as it is enclosed with 'BEGIN' and 'COMMIT' in binary log) for
      making the value of Seconds_Behind_Master more reasonable.
     @ mysql-test/suite/rpl/r/rpl_seconds_behind_master.result
        Updated for the patch of Bug #53167.
     @ mysql-test/suite/rpl/t/rpl_delayed_slave.test
        Updated for the patch of Bug #53167.
     @ mysql-test/suite/rpl/t/rpl_seconds_behind_master.test
        Updated for the patch of Bug #53167.
     @ sql/binlog.cc
        Added code to set LOG_EVENT_RELAY_LOG_F flag for relay log's FD
     @ sql/rpl_slave.cc
        Added code to update the last_master_timestamp at the end of a
        transaction(to non-transation, treat every statement as a transaction
        as it is enclosed with 'BEGIN' and 'COMMIT' in binary log) for
        making the value of Seconds_Behind_Master more reasonable.
[30 Aug 2010 11:02] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/117131

3192 Dao-Gang.Qu@sun.com	2010-08-30
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the Format_Description_Log_Event
      from master. This can be a very big number if the relay log was created
      long ago.
      
      The Timestamp recorded in Format_Description_Log_Event should not be used
      when executing the Format_Description_Log_Event on slave. So do not assign
      the Timestamp of the Format_Description_Log_Event to last_master_timestamp.
      Then the peak value will disappear.
     @ mysql-test/suite/rpl/t/rpl_delayed_slave.test
        Upadted to test the patch of Bug #53167.
     @ sql/binlog.cc
        Added code to set LOG_EVENT_RELAY_LOG_F flag for relay log's FD
     @ sql/rpl_slave.cc
        Added code to update the last_master_timestamp at the end of a
        transaction(to non-transation, treat every statement as a transaction
        as it is enclosed with 'BEGIN' and 'COMMIT' in binary log) for
        making the value of Seconds_Behind_Master more reasonable.
[31 Aug 2010 10:06] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/117192

3263 Dao-Gang.Qu@sun.com	2010-08-31
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the Format_Description_Log_Event
      from master. This can be a very big number if the relay log was created
      long ago.
      
      The Timestamp recorded in Format_Description_Log_Event should not be used
      when executing the Format_Description_Log_Event on slave. So do not assign
      the Timestamp of the Format_Description_Log_Event to last_master_timestamp.
      Then the peak value will disappear.
     @ mysql-test/suite/rpl/t/rpl_delayed_slave.test
        Updated to test the patch of Bug #53167.
     @ sql/binlog.cc
        Added code to set LOG_EVENT_RELAY_LOG_F flag for relay log's FD
     @ sql/rpl_slave.cc
        Added code to not update the last_master_timestamp by the Timestamp
        recorded in FD from master.
[31 Aug 2010 10:50] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/117195

3263 Dao-Gang.Qu@sun.com	2010-08-31
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the Format_Description_Log_Event
      from master. This can be a very big number if the previous relay log was
      created long ago. The first FD generated by slave, which refers to
      incomparable time taken on slave.
      
      The Timestamp recorded in Format_Description_Log_Event should not be used
      when executing the Format_Description_Log_Event on slave. So do not assign
      the Timestamp of the Format_Description_Log_Event to last_master_timestamp.
      Then the peak value will disappear.
     @ mysql-test/suite/rpl/t/rpl_delayed_slave.test
        Updated to test the patch of Bug #53167.
     @ sql/binlog.cc
        Added code to set LOG_EVENT_RELAY_LOG_F flag for relay log's FD
     @ sql/rpl_slave.cc
        Added code to not update the last_master_timestamp by the Timestamp
        recorded in FD from master.
[31 Aug 2010 11:33] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/117210

3263 Dao-Gang.Qu@sun.com	2010-08-31
      Bug #53167  	Seconds_Behind_Master is wrong after start slave
      
      When a slave server has an existing relay log and the user issues
      START SLAVE, the output from "SHOW SLAVE STATUS" shows a wrong
      value for Seconds_Behind_Master until the first event from the relay
      log has finished executing. The displayed value for Seconds_Behind_Master
      is calculated based on the timestamp of the Format_Description_Log_Event,
      which is reinserted into stream of events in RL when RL rotates. This can
      be a very big number if the previous relay log was created long ago. And
      the first FD generated by slave, which refers to incomparable time generated
      on slave.
      
      Do not assign the Timestamp of the Format_Description_Log_Event to
      last_master_timestamp when executing the Format_Description_Log_Event
      on slave. Then the peak value will disappear.
     @ mysql-test/suite/rpl/t/rpl_delayed_slave.test
        Updated to test the patch of Bug #53167.
     @ sql/binlog.cc
        Added code to set LOG_EVENT_RELAY_LOG_F flag for relay log's FD
     @ sql/rpl_slave.cc
        Added code to not update the last_master_timestamp by the Timestamp
        recorded in FD from master.
[2 Sep 2010 11:27] Luis Soares
See also: BUG#56363.
[6 Sep 2010 2:56] Daogang Qu
Pushed into mysql-next-mr-bugfixing
[2 Oct 2010 18:13] Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101002181053-6iotvl26uurcoryp) (version source revid:alexander.nozdrin@oracle.com-20101002180917-h0n62akupm3z20nt) (pib:21)
[13 Nov 2010 16:16] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (merge vers: 5.6.99-m4) (pib:21)
[29 Nov 2010 22:04] Jon Stephens
Issue doesn't appear in a release version. Closed without further action.
[19 Sep 2012 11:24] Valerii Kravchuk
IMHO issue does appear in 5.1+ (as it was reported initially), like in 5.5:

[openxs@chief mysql-test]$ ./mtr bug53167
Logging: ./mtr  bug53167
120919 14:18:21 [Note] Plugin 'FEDERATED' is disabled.
MySQL Version 5.5.29
Checking supported features...
 - skipping ndbcluster
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
vardir: /home/openxs/dbs/5.5/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/openxs/dbs/5.5/mysql-test/var'...
Installing system database...
Using server port 41463

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.bug53167                            [ fail ]
        Test ended at 2012-09-19 14:18:44

CURRENT_TEST: main.bug53167
--- /home/openxs/dbs/5.5/mysql-test/r/bug53167.result   2012-09-19 14:18:13.441426251 +0300
+++ /home/openxs/dbs/5.5/mysql-test/r/bug53167.reject   2012-09-19 14:18:44.033616514 +0300
@@ -0,0 +1,43 @@
+include/master-slave.inc
+[connection master]
+CREATE TABLE t1 (a VARCHAR(100));
+CREATE FUNCTION delay_on_slave(seconds INT) RETURNS INT BEGIN IF @@server_id = 2 THEN RETURN SLEEP(seconds); ELSE RETURN 0; END IF; END;
+Seconds_Behind_Master 1= 0
+INSERT INTO t1 VALUES ('let slave get synced');
+INSERT INTO t1 VALUES ('let slave get synced');
+Seconds_Behind_Master 2= 0
+include/stop_slave.inc
+include/start_slave.inc
+Seconds_Behind_Master 3= 0
+INSERT INTO t1 VALUES (delay_on_slave(4));
+Warnings:
+Note   1592    Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave.
+Note   1592    Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave.
+Seconds_Behind_Master 4= 7 pos=941 now=2012-09-19 14:18:39
+# at 4
+#120919 14:18:32 server id 1  end_log_pos 107  Start: binlog v 4, server v 5.5.29-debug-log created 120919 14:18:32 at startup
+# Warning: this binlog is either in use or was not closed properly.
+# at 107
+#120919 14:18:35 server id 1  end_log_pos 202  Query   thread_id=6     exec_time=0     error_code=0
+# at 202
+#120919 14:18:35 server id 1  end_log_pos 449  Query   thread_id=6     exec_time=0     error_code=0
+# at 449
+#120919 14:18:37 server id 1  end_log_pos 517  Query   thread_id=6     exec_time=0     error_code=0
+# at 517
+#120919 14:18:37 server id 1  end_log_pos 626  Query   thread_id=6     exec_time=0     error_code=0
+# at 626
+#120919 14:18:37 server id 1  end_log_pos 695  Query   thread_id=6     exec_time=0     error_code=0
+# at 695
+#120919 14:18:37 server id 1  end_log_pos 763  Query   thread_id=6     exec_time=0     error_code=0
+# at 763
+#120919 14:18:37 server id 1  end_log_pos 872  Query   thread_id=6     exec_time=0     error_code=0
+# at 872
+#120919 14:18:37 server id 1  end_log_pos 941  Query   thread_id=6     exec_time=0     error_code=0
+# at 941
+#120919 14:18:37 server id 1  end_log_pos 1009         Query   thread_id=6    exec_time=0      error_code=0
+# at 1009
+#120919 14:18:37 server id 1  end_log_pos 1113         Query   thread_id=6    exec_time=0      error_code=0
+# at 1113
+#120919 14:18:37 server id 1  end_log_pos 1182         Query   thread_id=6    exec_time=0      error_code=0
+# End of log file
+Seconds_Behind_Master 5= 0