MySQL Seconds behind Master fluctuation

Question

I have two servers set up in Master-Master with one additional Slave connected to the first master. Lately I've started getting alerts from monyog that Master 1 has a seconds_behind_master value of 1109. Oddly enough, it's ALWAYS 1109. If I log into the server and just do show slave status\G over and over, every 10-15 seconds it'll show 1109 in seconds_behind_master and then immediately goes back to 0. Then 10-15 seconds later it'll go back to 1109, then back to 0.

I found this article about the issue I'm experiencing, Unfortunately the resolution was unrelated to what's happening on my server. I did show slave status until I got it to show 1109 again, then I looked at the relay log position, looked it up in the relay log and checked all events for several seconds before and after and all events came from master 2, as expected. All of the timestamps were in order, too.

Any ideas?

Answer 1

I have dealt with this pesky 0 to infinity and back to 0 issue with Seconds_Behind_Master. Here are my past posts where I have addressed this:

• Jun 17, 2011 : MySQL Replication Lag Behaving Erraticly
• Sep 24, 2012 : MySQL replication - slave is continuously lagging behind master
• May 04, 2014 : MySQL 5.6 showing wrong "second_behind_master"

Although there is a bug fix in place based on binlogs not being flushed properly and if you configure sync_binlog=1 on Master1 and Master2, it may exacerbate the problem.

Even in a perfect world for Binary Logs, sometimes there will be occasions when queries will bunch up on one Master and have the same timestamp. When those queries are completed in parallel on a Master, every Slave processes them in a serialized manner.

EXAMPLE

If 60 queries take one second to run on a Master and all of them complete at the same time...

• all 60 queries will be written to the Master's Binary Logs on-by-one
• all 60 queries will have the same timestamp
• each of the 60 one-second queries are executed one-by-one of the Slave
• The timestamp of each query won't move while NOW() on the Slave is moving (The difference between NOW() on the Slave and the timestamp of the query from the Master is Seconds_Behind_Master)
• When the first 59 queries are processed, Seconds_Behind_Master will be 59
• When the 60th query is processed, Seconds_Behind_Master drops to 0

Given this computation of Second_Behind_Master and Master1 records multiple queries in the same timeframe, Master2 will always experience this time warp.

SUGGESTION

You could try zapping all the relay logs on the Master2.

• On Master1, STOP SLAVE;
• On Master2, SHOW SLAVE STATUS\G
• On Master2, get LOGFIL from Relay_Master_Log_File
• On Master2, get LOGPOS from Exec_Master_Log_Pos
• On Master2, CHANGE MASTER TO master_log_file='LOGFIL',master_log_pos=LOGPOS;
• On Master2, START SLAVE;
• On Master1, STOP SLAVE;

Once you run these steps, you have a clean set of relay logs on Master2, but you still subject to Slave Lag emanating from Master1 due to multiple queries completing at the same time.

All the numbers I mentioned in the Example assumes that Master1 and Master2 have identical Storage Engine configs, identical OS, identical hardware, identical disks, and excellent network communication. If Master2 is inferior to Master1 in any of these aspects, perhaps the 60 seconds to process the queries on the Slave will be more like 70 or 80 seconds.

If the hardware, software, and Storage Engine configs are not identical, then make them identical and restart MySQL as needed.

These are the facts. There is no "Magic Bullet" for this phenomenon so long as your hammer multiple INSERT, UPDATEs, and DELETEs on Master1.

LOOKING OUTSIDE THE BOX

• What you need to look for in the Master1's Binary Logs is 15-second Windows of Time among the timestamps and see how many INSERT, UPDATEs, and DELETEs and being done.
• If your application performs these writes with the same rhythmic pattern, then you need to look at the application as to how it does writes in InnoDB and MyISAM.
• Look around for any cronjobs that perform any scheduled writes