原文： https://www.percona.com/blog/2014/05/02/how-to-identify-and-cure-mysql-replication-slave-lag/

Percona的MySQL支持团队经常会看到用户在抱怨数据库同步延迟，并且大多数都是由于MySQL复制slave端的落后引起的。这对于MySQL用户来说从来都不是什么新鲜事，这几年我们也在 MySQL Performance Blog 中关于这个话题发过几个帖子（Percona CEO的Peter Zaitsev写的“MySQL同步延迟的原因”和“处理MySQL的Slave端延迟”尤其值得一看）。

然而在今天这篇文章中，我将会分享一些定位同步延迟的方法（包括导致slave落后的一些可能性）以及如何解决这些问题。

如何定位同步延迟
MySQL 同步是通过两个线程完成的：IO_THREAD 和SQL_THREAD。IO_THREAD 与master端链接并且读取它的二进制日志事件，同时将读到的数据复制写入本地的中继日志。另一方面，SQL_THREAD从中继日志中的事件，并且在slave端尽快执行。如果发现同步延迟了，那第一步就是要确定是哪个线程引起的问题。

一般来说，I/O线程并不会造成很大的同步延迟，因为它只负责从master端读取二进制日志。然而这还是得看两个服务器之间的网络链接状况和延迟。slave端的I/O线程可能会因为带宽被占用的太多而运行缓慢。通常如果IO_THREAD可以较快地读取二进制日志并且写入中继文件，那么这表示IO_THREAD不是slave落后的罪魁祸首。

另一方面，如果是SQL_THREAD造成同步延迟的话，那很可能是因为获取的那些请求在slave端执行消耗了很长的时间。这种情况有时是因为主从两个机子的硬件性能差别导致的，也可能是由于不同的索引配置导致的，也有可能是负荷不同导致的。另外，slave的OLTP有时可能会因为加锁策略而导致同步延迟。举个例子，如果存在一个长时间运行的MyISAM读取操作，则可能会阻塞SQL线程，或者InnoDB上的数据交换会造成IX锁并锁住SQL县城的DDL。另外，如果把MySQL 5.6版本之前的单线程slave这种情况也算在里面的话，那也可能导致slave端的SQL_THREAD延迟。

让我来通过master和slave端的状态来展示一些例子，并分析是IO_THREAD还是SQL_THREAD导致的延迟。

mysql-master> SHOW MASTER STATUS;
+------------------+--------------+------------------+------------------------------------------------------------------+
| File | Position  | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                                                |
+------------------+--------------+------------------+------------------------------------------------------------------+
| mysql-bin.018196 | 15818564     |                  | bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:1-2331947                   |
+------------------+--------------+------------------+------------------------------------------------------------------+
mysql-slave> SHOW SLAVE STATUSG
*************************** 1. row ***************************
Slave_IO_State: Queueing master event to the relay log
Master_Host: master.example.com
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.018192
Read_Master_Log_Pos: 10050480
Relay_Log_File: mysql-relay-bin.001796
Relay_Log_Pos: 157090
Relay_Master_Log_File: mysql-bin.018192
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 5395871
Relay_Log_Space: 10056139
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 230775
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 2
Master_UUID: bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:2-973166
Master_Info_File: /var/lib/mysql/i1/data/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Reading event from the relay log
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set: bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:2-973166
Executed_Gtid_Set: bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:2-973166,
ea75c885-c2c5-11e3-b8ee-5cf3fcfc9640:1-1370
Auto_Position: 1

我们很容易可以看出slave端的IO_THREAD已经落后，并且因此SQL_THREAD也落后了。我们可以看到master端的日志文件是mysql-bin.018196（通过master状态的文件参数可以看到），而slave的IO_THREAD正在读取的是mysql-bin.018192（slave状态中的Master_Log_File），这意味着slave的IO_THREAD正在读取的是后者而master端在写的是前者，所以slave的IO_THREAD落后了4个binlogs文件。同时，slave的SQL_THREAD正在读取文件mysql-bin.018192（slave状态的Relay_Master_Log_File）。这意味着slave的SQL_THREAD处理时间的速度足够快，但是他也有所落后了，这从slave状态的Read_Master_Log_Pos 和 Exec_Master_Log_Pos可以看出。

你可以通过 Read_Master_Log_Pos – Exec_Master_Log_Pos 得到的差值来计算SQL_THREAD的落后，但前提是Master_Log_File和Relay_Master_Log_File是相同的。这可以让你大概知道slave的 SQL_THREAD 处理事件的速度。正如我前面所说的，在这个例子中slave的IO_THREAD也处于落后状态，所以SQL_THREAD 也落后了。关于slave的状态相关参数，可以参考这篇文章。

另外Seconds_Behind_Master参数显示slave端存在巨大的延迟。然而这可能会产生一些误导，因为这个参数是通过计算最新获取的中继日志和正在执行的中继日志的时间戳差值得到的。如果还有部分master端的日志没有获取，那么这样计算出来的就不是和master端真正的时间差值。你可以通过使用 Percona Toolkit. 的pt-heartbeat 来获取更加准确的延迟时间。所以到目前为止我们已经知道了如何判别是哪一个县城导致了slave端的同步落后，接下来我将介绍一些解决方案和建议。

关于造成同步延迟的原因和一些解决方案的建议
一般如果slave的 IO_THREAD落后是因为网络速度慢导致的。大部分情况下打开 slave_compressed_protocol 可以缓解这个症状。另外，如果不需要紧急备份还原的话就关掉slave的二进制文件记录功能，以此来环节IO上的压力。

为了最小化slave的SQL_THREAD 延迟，则需要优化各个请求。我的建议是打开 log_slow_slave_statements 配置来找到slave端执行时间超过long_query_time 的请求语句。如果要获取更多关于请求的性能，可以将log_slow_verbosity 配置为“full”。

这样我们就可以观察到slave的SQL_THREAD 的那些查询请求消耗了多少时间。读者可以很据我之前的那篇文章来了解如何通过上述提到的配置选项来记录执行较慢的请求日志。log_slow_slave_statements作为提醒功能的日志第一次出现在Percona Server 5.1中，而现在已经是MySQL 5.6.11版本后的普通功能。在更早版本的MySQL Server中log_slow_slave_statements是作为命令行选项存在的。更多的细节可以参考 这篇文章 关于Percona Server特有的log_slow_verbosity功能。

另外还有一个造成slave的SQL_THREAD延迟的可能：如果你使用基于行的binlog格式，并且某些表缺少主键或者唯一键则所有的SQL_THREAD会扫描全表并造成同步延迟。所以需要确保你的表有主键或者唯一键。这个bug的详情可以参考http://bugs.mysql.com/bug.php?id=53375。你可以通过下列语句来确定slave上的数据v库表是否有主键缺失。

mysql> SELECT t.table_schema,t.table_name,engine
FROM information_schema.tables t INNER JOIN information_schema .columns c
on t.table_schema=c.table_schema and t.table_name=c.table_name
GROUP BY t.table_schema,t.table_name
HAVING sum(if(column_key in ('PRI','UNI'), 1,0)) =0;

MySQL 5.6在这个场景上作出了优化，即在内存散列中使用slave_rows_search_algorithms。

Seconds_Behind_Master在我们读取一个巨大的RBR事件时并不会更新，所以“落后”只和我们未读取的事件有关。举个例子，在一个基于行的同步中，巨大的数据修改会造成slave端的延迟，比如你有1亿行数据的表中你执行了“DELETE FROM table WHERE id < 5000000” ，5000万行的数据会发送到slave端，并且每行处理的都非常慢。所以如果你需要删除一个巨大表的多行老数据，使用分表也许是个不错的代替方案：用DROP旧部分的数据来代替DELETE在同步中会表现得更好。

为了更好地介绍这个方法，我们假设你有partition1 拥有ID是 1 到 1000000的行，partition2拥有ID是 1000001 到 **2000000 **的行。然后取代“DELETE FROM table WHERE ID<=1000000;”的方法就可以是“ALTER TABLE DROP partition1;”了解更多分表相关的信息可以参照对应的 手册，以及另外一篇由我的同时Roman写的关于同步延迟的文章。

pt-stalk是Percona Toolkit 中最好用的工具之一，它可以问题发生时候相关的诊断数据。你可以通过下面介绍的方法来搭建pt-stalk，之后不管什么时候slave延迟发生了，它都能将诊断信息存入日志，从而我们就可以更轻松得发现罪魁祸首。

通过下列脚本就可以搭建好pt-stalk来找出同步延迟的原因：

------- pt-plug.sh contents
#!/bin/bash
trg_plugin() {
mysqladmin $EXT_ARGV ping &> /dev/null
mysqld_alive=$?
if [[ $mysqld_alive == 0 ]]
then
seconds_behind_master=$(mysql $EXT_ARGV -e "show slave status" --vertical | grep Seconds_Behind_Master | awk '{print $2}')
echo $seconds_behind_master
else
echo 1
fi
}
# Uncomment below to test that trg_plugin function works as expected
#trg_plugin
-------
-- That's the pt-plug.sh file you would need to create and then use it as below with pt-stalk:
$ /usr/bin/pt-stalk --function=/root/pt-plug.sh --variable=seconds_behind_master --threshold=300 --cycles=60 --notify-by-email=muhammad@example.com --log=/root/pt-stalk.log --pid=/root/pt-stalk.pid --daemonize

You can adjust the threshold, currently its 300 seconds, combining that with –cycles, it means that if seconds_behind_master value is >= 300 for 60 seconds or more then pt-stalk will start capturing data. Adding –notify-by-email option will notify via email when pt-stalk captures data. You can adjust the pt-stalk thresholds accordingly so that’s how it triggers to collect diagnostic data during problem.
你可以调整延迟阈值，当前是 300 秒，这意味着如果seconds_behind_master值大于300的时间超过60 秒， pt-stalk 将会开始记录数据。添加–notify-by-email 选项就可以在pt-stalk 记录数据的同时发送电子邮件到你的邮箱。你可以调整根据实际情况来调整pt-stalk的阈值在问题发生时决定何时出发相关的数据收集。

结论
slave端的延迟虽然不是什么大问题，但是却在MySQL同步的使用中非常常见。我试着在这篇文章中覆盖同步延迟的方方面面。如果你知道任何其他导致同步延迟的可能，请务必在留言区分享给大家，谢谢！