DB-유

Monitoring MySQL Replication Lag with SHOW SLAVE STATUS

· mysql, replication, monitoring

The slave is always a little behind the master. Usually it's milliseconds and nobody cares. When it's minutes, a user who just placed an order hits a read replica and sees nothing, and I get the phone call. I would much rather find out from a check than from a user.

The built-in view is SHOW SLAVE STATUS: about fifty fields, of which only a handful matter for lag. Below are those fields, the situations where Seconds_Behind_Master lies, and a cron check. It assumes MySQL 5.6/5.7 or MariaDB 10.x with a slave, and an account on the slave with REPLICATION CLIENT (or SUPER).

The fields that matter

On the slave:

SHOW SLAVE STATUS\G

The fields to look at, in order:

  • Slave_IO_Running and Slave_SQL_Running: both must be Yes. If either is No, lag is irrelevant; the slave is broken.
  • Seconds_Behind_Master: the headline number. NULL means the SQL thread is not running.
  • Master_Log_File / Read_Master_Log_Pos: what the IO thread has downloaded from the master.
  • Relay_Master_Log_File / Exec_Master_Log_Pos: what the SQL thread has applied.
  • Last_IO_Error, Last_SQL_Errno, Last_SQL_Error: why a thread stopped.

If Read_Master_Log_Pos is far ahead of Exec_Master_Log_Pos in the same file, the network is fine and the slave is simply slow at applying. If both are close together but the master is much further along (compare with SHOW MASTER STATUS on the master), the IO thread is the bottleneck, usually because of network bandwidth.

What Seconds_Behind_Master actually measures

The value is the difference between the slave's clock and the timestamp in the event the SQL thread is currently executing. Consequences:

  • When the SQL thread has caught up with the relay log it reports 0, even if the IO thread has not fetched the latest events yet. A slave with a saturated network link can show 0 lag while missing ten minutes of data.
  • A single long-running statement (a big ALTER TABLE or a huge DELETE without row-based replication) makes the value jump from 0 to hundreds and then back to 0 in one step.
  • Clock skew between master and slave shifts the number. Keep both on NTP.

For a truthful measurement, use a heartbeat: a row on the master updated every second, compared with the slave's clock. Percona Toolkit ships pt-heartbeat for exactly this:

# on the master
pt-heartbeat --daemonize --update --database percona --create-table \
  --user=heartbeat --password=Hb-P@ss
# on the slave
pt-heartbeat --check --database percona --user=heartbeat --password=Hb-P@ss

The --check output is the real lag in seconds regardless of what the IO thread is doing. I trust this number more than the built-in one.

A cron-friendly check

This exits non-zero when lag exceeds a threshold or a thread stopped:

#!/bin/bash
THRESHOLD=60
STATUS=$(mysql --defaults-extra-file=/root/.my.cnf -e 'SHOW SLAVE STATUS\G')
IO=$(echo "$STATUS" | awk '/Slave_IO_Running:/ {print $2}')
SQL=$(echo "$STATUS" | awk '/Slave_SQL_Running:/ {print $2}')
LAG=$(echo "$STATUS" | awk '/Seconds_Behind_Master:/ {print $2}')
if [ "$IO" != "Yes" ] || [ "$SQL" != "Yes" ]; then
  echo "CRITICAL: replication threads IO=$IO SQL=$SQL"; exit 2
fi
if [ "$LAG" = "NULL" ] || [ "$LAG" -gt "$THRESHOLD" ]; then
  echo "WARNING: replication lag ${LAG}s"; exit 1
fi
echo "OK: lag ${LAG}s"

Nagios/Icinga users can drop this in as a plugin. Zabbix's MySQL template and the Percona Monitoring Plugins already include a Seconds_Behind_Master item, so use those if you have them.

When lag becomes chronic

If the SQL thread is constantly behind, these are the fixes I try, in order of effort:

  1. Switch to row-based replication (binlog_format=ROW) so expensive statements are not re-executed on the slave.
  2. Enable multi-threaded replication on MySQL 5.7:
[mysqld]
slave_parallel_type = LOGICAL_CLOCK
slave_parallel_workers = 4
slave_preserve_commit_order = 1
  1. Relax durability on the slave only: sync_binlog=0 and innodb_flush_log_at_trx_commit=2. If the slave crashes you rebuild it from the master anyway.
  2. Make sure the slave hardware is not weaker than the master; a replica on spinning disks behind an SSD master will never keep up under write load.

After enabling parallel workers, check that they are actually being used:

SELECT * FROM performance_schema.replication_applier_status_by_worker;

Each worker row should show a recent LAST_APPLIED_TRANSACTION. Watch Seconds_Behind_Master over a few minutes with:

watch -n 5 "mysql -e 'SHOW SLAVE STATUS\G' | grep -E 'Seconds_Behind|Running:'"

Error messages I keep seeing

  • Seconds_Behind_Master: NULL with Slave_SQL_Running: No and Last_SQL_Errno: 1062: a duplicate key error stopped the SQL thread. Find the offending statement in Last_SQL_Error, decide whether to fix data or skip it with SET GLOBAL sql_slave_skip_counter = 1; START SLAVE; (never on GTID slaves; inject an empty transaction there instead).
  • Last_IO_Error: error connecting to master 'repl@10.0.0.1:3306' - retry-time: 60 retries: 3: network or credentials. Test with mysql -h 10.0.0.1 -u repl -p from the slave.
  • Got fatal error 1236 from master when reading data from binary log: 'Could not find first log file name in binary log index file': the master purged the binlog the slave needs. Increase expire_logs_days on the master and rebuild the slave from a fresh backup.
  • Lag oscillates between 0 and a large number every few minutes: usually a periodic batch job on the master. Check Relay_Master_Log_File and mysqlbinlog the events around that time to identify it.

SHOW SLAVE STATUS catches a broken slave. For a number you'd let wake you up at night, use a heartbeat table.