{"id":6589,"date":"2014-01-24T15:41:18","date_gmt":"2014-01-24T13:41:18","guid":{"rendered":"http:\/\/code.openark.org\/blog\/?p=6589"},"modified":"2014-01-24T15:41:18","modified_gmt":"2014-01-24T13:41:18","slug":"seconds_behind_master-vs-absolute-slave-lag","status":"publish","type":"post","link":"https:\/\/code.openark.org\/blog\/mysql\/seconds_behind_master-vs-absolute-slave-lag","title":{"rendered":"Seconds_behind_master vs. Absolute slave lag"},"content":{"rendered":"

I am unable to bring myself to trust the Seconds_behind_master<\/strong> value on SHOW SLAVE STATUS<\/strong>. Even with MySQL 5.5<\/strong>‘s CHANGE MASTER TO … MASTER_HEARTBEAT_PERIOD<\/strong> (good thing, applied when no traffic goes from master to slave) it’s easy and common to find fluctuations in\u00a0Seconds_behind_master<\/strong> value.<\/p>\n

And, when sampled by your favourite monitoring tool, this often leads to many<\/em> false negatives.<\/p>\n

At Outbrain we use HAProxy as proxy to our slaves, on multiple clusters. More about that in a future post. What’s important here is that our decision whether a slave enters or leaves a certain pool (i.e. gets UP or DOWN status in HAProxy) is based on replication lag. Taking slaves out when they are actually replicating well is bad, since this reduces the amount of serving instances. Putting slaves in the pool when they are actually lagging too much is bad as they contain invalid, irrelevant data.<\/p>\n

To top it all, even when correct, the\u00a0Seconds_behind_master<\/strong> value is practically irrelevant on 2nd<\/strong> level slaves. In a Master -> Slave1 -> Slave2<\/em> setup, what does it mean that Slave2<\/em> has Seconds_behind_master = 0<\/strong>? Nothing much to the application: Slave1<\/em> might be lagging an hour behind the master, or may not be replicating at all. Slave2<\/em> might have an hour’s data missing even though it says its own replication is fine.<\/p>\n

None of the above is news, and yet many fall in this pitfall. The solution is quite old as well; it is also very simple: do your own heartbeat mechanism, at your favourite time resolution, and measure slave lag by timestamp you yourself updated on the master.<\/p>\n

Maatkit<\/strong>\/percona-toolkit<\/strong> did this long time ago with mk-heartbeat<\/strong>\/pt-heartbeat<\/a><\/strong>. We’re doing it in a very similar manner. The benefit is obvious. Consider the following two graphs; the first shows Seconds_behind_master<\/strong>, the seconds shows our own Absolute_slave_lag<\/strong> measurement.<\/p>\n

\n
\"seconds_behind_master\"<\/a>
seconds_behind_master<\/figcaption><\/figure><\/blockquote>\n
\n
\"absolute_slave_lag\"<\/a>
absolute_slave_lag<\/figcaption><\/figure><\/blockquote>\n

The two graphs were taken simultaneously on a set of servers. Excuse me for not having same colours for same slaves, I blame it on graphite. Some small gaps are seen here that are irrelevant to our discussion (yes, we had some graphite delivery issues).<\/p>\n

As you can see the Absolute_slave_lag<\/strong> does not (and cannot!) fluctuate. With our 10 second heartbeat resolution it always shows an accurate value. In fact, within the hearbeat resolution, it show the de facto replication lag. Let’s stress this one:<\/p>\n

When you implement your own heartbeat mechanism, your own measured slave lag makes for the de facto slave replication lag within your heartbeat interval.<\/p><\/blockquote>\n

As another example, consider what happens when a slave stop replicating (i.e. some issued STOP SLAVE<\/strong>, or replication fails). The\u00a0Seconds_behind_master<\/strong> value is NULL<\/strong>, which is a good indication to error, and easy to monitor. But how does it present visually? Not too well. It is usually just not rendered:<\/p>\n

\"\"<\/p><\/blockquote>\n

But, consider: a slave that STOP<\/strong>s for 1<\/strong> minute for whatever reason is still only 1<\/strong> minute behind master. That is, it is by 60<\/strong> seconds up to date with master’s data. If we decide a slave should be serving for up to 5<\/strong> minutes of lag, then our slave can still be used for serving for 4<\/strong> more minutes!\u00a0Seconds_behind_master<\/strong> does not provide us with helpful information. Absolute_slave_lag<\/strong> does. Consider the above system status when measured by Absolute_slave_lag<\/strong>:<\/p>\n

\"\"<\/p><\/blockquote>\n

We now get good insight on how far our slave is behind. Of course we monitor\u00a0Seconds_behind_master<\/strong> to find out replication is not working; by our HAProxy only cares about Absolute_slave_lag<\/strong>.<\/p>\n

How does it work?<\/h4>\n

Very similar to pt-heartbeat<\/strong>, there’s a dedicated table which we update with current timestamp. We read that timestamp on slave and compare with actual time on host.<\/p>\n

We have these DDL:<\/p>\n

\n
create table my_heartbeat (\r\n\u00a0 id int unsigned not null primary key,\r\n\u00a0 master_ts timestamp,\r\n\u00a0 update_by varchar(128) default NULL\r\n);\r\n\r\ncreate or replace view my_heartbeat_status_v as\r\n\u00a0 select \r\n\u00a0\u00a0\u00a0 master_ts,\r\n\u00a0\u00a0\u00a0 now() as time_now,\r\n\u00a0\u00a0\u00a0 timestampdiff(SECOND, master_ts, now()) as slave_lag_seconds,\r\n\u00a0\u00a0\u00a0 update_by\r\n\u00a0 from my_heartbeat\r\n;\r\n\r\ninsert into my_heartbeat (id, master_ts, update_by) values (1, NOW(), 'init') on duplicate key update master_ts=NOW(), update_by=VALUES(update_by);\r\n\r\ncreate event \r\n\u00a0 update_heartbeat_event\r\n\u00a0 on schedule every 10 second starts current_timestamp \r\n\u00a0 on completion preserve\r\n\u00a0 enable\r\n\u00a0 do \u00a0\r\n\u00a0\u00a0\u00a0 insert into my_heartbeat (id, master_ts, update_by) values (1, NOW(), 'event_scheduler') on duplicate key update master_ts=NOW(), update_by=VALUES(update_by);\r\n;<\/pre>\n<\/blockquote>\n
We use both event scheduler as well as external script to pump the heartbeat value.<\/p>\n
On slave, utilize the view to:<\/p>\n
\n
select slave_lag_seconds from my_heartbeat_status_v<\/pre>\n<\/blockquote>\n
The above query answers: “how long ago was did I (the slave) get a timestamp update from the master?”. The result is correct within 10 seconds resolution, in our example.<\/p>\n
Not new, but not well known. I hope the above provides you with better visibility into your replication lag.<\/p>\n","protected":false},"excerpt":{"rendered":"
I am unable to bring myself to trust the Seconds_behind_master value on SHOW SLAVE STATUS. Even with MySQL 5.5‘s CHANGE MASTER TO … MASTER_HEARTBEAT_PERIOD (good thing, applied when no traffic goes from master to slave) it’s easy and common to find fluctuations in\u00a0Seconds_behind_master value. And, when sampled by your favourite monitoring tool, this often leads […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"jetpack_post_was_ever_published":false,"_jetpack_newsletter_access":"","_jetpack_dont_email_post_to_subs":false,"_jetpack_newsletter_tier_id":0,"_jetpack_memberships_contains_paywalled_content":false,"_jetpack_memberships_contains_paid_content":false,"footnotes":"","jetpack_publicize_message":"","jetpack_publicize_feature_enabled":true,"jetpack_social_post_already_shared":true,"jetpack_social_options":{"image_generator_settings":{"template":"highway","default_image_id":0,"enabled":false},"version":2}},"categories":[5],"tags":[46,8],"class_list":["post-6589","post","type-post","status-publish","format-standard","hentry","category-mysql","tag-monitoring","tag-replication"],"jetpack_publicize_connections":[],"jetpack_featured_media_url":"","jetpack_sharing_enabled":true,"jetpack_shortlink":"https:\/\/wp.me\/p2bZZp-1Ih","_links":{"self":[{"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/posts\/6589","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/comments?post=6589"}],"version-history":[{"count":11,"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/posts\/6589\/revisions"}],"predecessor-version":[{"id":6711,"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/posts\/6589\/revisions\/6711"}],"wp:attachment":[{"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/media?parent=6589"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/categories?post=6589"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/code.openark.org\/blog\/wp-json\/wp\/v2\/tags?post=6589"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}