| 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: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.1+ | OS: | Any |
| Assigned to: | Daogang Qu | CPU Architecture: | Any |
| Tags: | Seconds_Behind_Master, start slave | ||
[26 Apr 2010 15:34]
Sven Sandberg
[26 Apr 2010 15:51]
Valeriy 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]
Valeriy 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
