Bug #29309 Incorrect "Seconds_Behind_Master" value in SHOW SLAVE STATUS after FLUSH LOGS
Submitted: 22 Jun 2007 21:33 Modified: 28 Nov 2007 20:23
Reporter: Matthew Montgomery Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.0.38 OS:Any
Assigned to: Andrei Elkin CPU Architecture:Any
Tags: bfsm_2007_06_28, bfsm_2007_10_18, relay log, replication

[22 Jun 2007 21:33] Matthew Montgomery
Description:
When flush tables is executed there is a brief moment when "Seconds_Behind_Master"  is calculated incorrectly.

This jump in "Seconds_Behind_Master" can cause false positive alerts for monitoring services.  

How to repeat:
1) Configure replication.

2) Make some change on the master which propagates to the slave.

mysqlM> CREATE TABLE replTest (f1 INT, f2 INT) ENGINE=MyISAM;
mysqlM> INSERT INTO replTest values(1, 2),(3,4); 

3) watch for differences in Seconds_Behind_Master value

shellS1> watch --differences=cumulative -n 0  "mysql -e 'SHOW SLAVE STATUS\G' | grep Seconds_Behind_Master"

4) with step 3 still running issue "FLUSH LOGS" on slave.

You should see the time behind master jump for a split second to the difference in time between the last executed command and now.  You might need issue FLUSH LOGS several times before you see the time change.

mysqlS> FLUSH LOGS;
-or-
shellS2> watch -n 0 "mysql -e 'flush logs'"

Suggested fix:
.
[13 Sep 2007 10:46] Andrei Elkin
There is an evident flow in the code which treats FormatDescription event wrong so 
that after FLUSH LOGS on slave the Seconds_behind_master's calculation slips and incorrect value can be caught. Even worse is that the gap between the correct and incorrect deltas grows with time.
The patch to fix this kind of problem is ready for committing.
[13 Sep 2007 10:47] Andrei Elkin
s/flow/flaw/
[13 Sep 2007 12:18] 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/34172

ChangeSet@1.2501, 2007-09-13 15:18:05+03:00, aelkin@koti.dsl.inet.fi +5 -0
  Bug #29309 Incorrect "Seconds_Behind_Master" value in SHOW SLAVE STATUS after FLUSH LOGS
  
  Report claims that Seconds_behind_master behaves unexpectedly. 
  
  Code analysis shows that there is an evident flaw in that treating of FormatDescription event is wrong
  so  that after FLUSH LOGS on slave the Seconds_behind_master's calculation slips and incorrect
  value can be reported to SHOW SLAVE STATUS. 
  Even worse is that the gap between the correct and incorrect deltas grows with time.
  
  Fixed with prohibiting changes to rpl->last_master_timestamp by artifical events (any kind of).
[13 Sep 2007 13: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/34180

ChangeSet@1.2501, 2007-09-13 16:50:09+03:00, aelkin@koti.dsl.inet.fi +5 -0
  Bug #29309 Incorrect "Seconds_Behind_Master" value in SHOW SLAVE STATUS after FLUSH LOGS
  
  Report claims that Seconds_behind_master behaves unexpectedly. 
  
  Code analysis shows that there is an evident flaw in that treating of FormatDescription event is wrong
  so  that after FLUSH LOGS on slave the Seconds_behind_master's calculation slips and incorrect
  value can be reported to SHOW SLAVE STATUS. 
  Even worse is that the gap between the correct and incorrect deltas grows with time.
  
  Fixed with prohibiting changes to rpl->last_master_timestamp by artifical events (any kind of).
[4 Oct 2007 15:46] 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/34907

ChangeSet@1.2501, 2007-10-04 18:46:31+03:00, aelkin@koti.dsl.inet.fi +5 -0
  Bug #29309 Incorrect "Seconds_Behind_Master" value in SHOW SLAVE STATUS after FLUSH LOGS
  
  Report claims that Seconds_behind_master behaves unexpectedly. 
  
  Code analysis shows that there is an evident flaw in that treating of FormatDescription event is wrong
  so  that after FLUSH LOGS on slave the Seconds_behind_master's calculation slips and incorrect
  value can be reported to SHOW SLAVE STATUS. 
  Even worse is that the gap between the correct and incorrect deltas grows with time.
  
  Fixed with prohibiting changes to rpl->last_master_timestamp by artifical events (any kind of).
  suggestion as comments is added how to fight with lack of info on the slave side by means of
  new heartbeat feature coming.
  
  The test can not be done ealily fully determistic.
[13 Oct 2007 18:58] 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/35513

ChangeSet@1.2575, 2007-10-13 21:57:59+03:00, aelkin@koti.dsl.inet.fi +10 -0
  manual merge for bug_29136, bug#29309.
[13 Oct 2007 20:13] 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/35514

ChangeSet@1.2575, 2007-10-13 23:12:50+03:00, aelkin@koti.dsl.inet.fi +11 -0
  manual merge for bug_29136, bug#29309.
[22 Oct 2007 7:15] Andrei Elkin
The pushed patch addresses one of the issues must have been hit by the reporter.
That is FLUSH logs handling installed an ancient timestamp into rli->last_master_timestamp.
Another issues remains which is "Seconds_behind_master is not 100% reliable" see the Guilhem's notes and comments in the code.
That can be fixed by means of using heartbeat (not pushed yet into main trees) and
doing some simple changes in the code to replace read-eof from relay-log as the proof of successful synchornization semantics with a more accurate approach.
[24 Oct 2007 9:35] Jon Stephens
Documented fix in mysql-5.1.22-ndb-6.3.4 changelog.

Left bug status as Patch Queued pending merge into mainline trees.
[27 Nov 2007 10:49] Bugs System
Pushed into 5.0.54
[27 Nov 2007 10:51] Bugs System
Pushed into 5.1.23-rc
[27 Nov 2007 10:53] Bugs System
Pushed into 6.0.4-alpha
[28 Nov 2007 20:23] Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Documented for 6.0.4, no other mainline releases, per comment from Lars.