MySQL Bugs: #29309: Incorrect "Seconds_Behind_Master" value in SHOW SLAVE STATUS after FLUSH LOGS

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

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:
.

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.

s/flow/flaw/

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).

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).

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.

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.

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.

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.

Documented fix in mysql-5.1.22-ndb-6.3.4 changelog.

Left bug status as Patch Queued pending merge into mainline trees.

Pushed into 5.0.54

Pushed into 5.1.23-rc

Pushed into 6.0.4-alpha

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.