MySQL Replication performs weird calculations for Seconds_Behind_Master based on a few things.
- What NOW() returns for SQL run on the master as recorded in relay logs
- What NOW() returns on the slave
- The last position from the master that was executed
Here is a SHOW SLAVE STATUS\G and how to identify the Last Executed SQL from the Master
mysql> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
1 row in set (0.00 sec)
Notice the following fields in SHOW SLAVE STATUS\G
- Master_Log_File (Line 6) : Log File on the Master whose position was last read
- Read_Master_Log_Pos (Line 7) : Last position read on the Slave from the Master
- Relay_Master_Log_File (Line 10) : Log File on the Master whose position was last executed
- Exec_Master_Log_Pos (Line 22) : Last position executed on the Slave from the Master
- Relay_Log_Space (Line 23) : Sum of bytes from all relay logs
To calculate Seconds_Behind_Master, it would essentially figured out
NOW() as recorded in Master LogFile 'Master_Log_File' LogPos 'Read_Master_Log_Pos'
NOW() on the Slave
This number can intermittently grow because the I/O thread can collect more entries from the Master and loading it into the last relay log while processing the SQL statement located at Master LogFile 'Relay_Master_Log_File' and Master LogPos 'Exec_Master_Log_Pos'. This increasing number is also manifested by three(3) variables changing: Relay_Log_Space, Master_Log_File, Read_Master_Log_Pos. If Seconds_Behind_Master is 0, this is good indication that Read_Master_Log_Pos and Exec_Master_Log_Pos virtually the same. Also worth noting is the fact that long running SQL can fool you into thinking that replication is behind. Once that SQL statement is complete and no other statements have sufficiently backlogged, Seconds_Behind_Master can drop dramatically, even to 0.
So, why would Seconds_Behind_Master bounce back and forth between 0 and an increasing number. It is possible for network latency in transmitting SQL through the I/O thread to contribute to miscalculation because the needed
TIMESTAMP variable was not reached yet in the back of the last relay log (remember this is asynchronous replication). To verify this, run
mysqlbinlog against any binary log or relay log and see where the
TIMESTAMP variables are written between statements.
This behavior was first addressed June 22, 2007 and the bug was supposedly fixed then.
Here is one sure way to take MySQL Replication and screw its head on correctly (For this example, use the same SHOW SLAVE STATUS\G)
Using Relay_Master_Log_File mysql-bin.002814 and Exec_Master_Log_Pos 823078734 as the Log FilePosition to Restart From, run these commands
CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.002814',MASTER_LOG_POS=823078734;
These steps should 1) kill both I/O and SQL Threads, 2) wipe out All Collected Relay Logs, 3) start with a New Relay Log, and 4) establish New I/O and SQL Threads.
Replication should be good to go from here. As to whether or not this bug can truly be addressed, this now in Oracle's hands (That last statement does not inspire any confidence, does it ???)