pt-heartbeat工具监控MySQL复制延迟

pt-heartbeat工作原理：

1，在主库上的某个数据库A中创建一张heartbeat表，按照一定的时间频率更新该表的字段（把时间更新进去）。

2，从主库连接到从上的这个数据库A中检查复制的时间记录，和从库的当前系统时间进行比较，得出时间的差异。

使用方法：

在主库上执行：

[root@:Test: ~/tidb-bench/sysbench]#pt-heartbeat --database sbtest2 --create-table --update --daemonize -uroot -p123456

这里--database表示要指定是哪个数据库。 而--create-table表示在那个数据库下创建heartbeat表来进行检测。--update表示每秒更新一次heartbeat时间记录。--daemonize表示以守护进程的方式运行此命令。-u以及-p都填写主库的用户名和密码。

接下来继续在主库上执行：

[root@:Test: ~/tidb-bench/sysbench]#pt-heartbeat -uroot -p123456 -h 172.31.26.133  -D sbtest2 --master-server-id=1 --monitor

这里-u和-p都是连接主库的MySQL用户和密码。但是-h后接从库的IP。-D后接数据库。--master-server-id后接主库的server-id。--monitor表示监控主从延迟值（也可以指定为--check，表示只输出一次，可用于脚本处理）。

我下面这个是下午测试的主从延迟

1286.00s [ 1307.52s, 1398.31s, 992.58s ]
1285.00s [ 1306.78s, 1397.54s, 994.01s ]
1285.00s [ 1306.07s, 1396.78s, 995.43s ]

其中第一列表示此时此刻的延迟，后面的三列分别表示：1分钟、5分钟、15分钟内的平均延迟时间。

在发现主从延迟的情况下，我们就要开始定位主从延迟的原因是什么。

如何定位同步延迟
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会扫描全表并造成同步延迟。所以需要确保你的表有主键或者唯一键。

此外：要多参考MySQL官方文档：https://dev.mysql.com/doc/refman/5.5/en/show-slave-status.html

在定位线程上多关注这几个：

一般上而言I/O线程不会造成过大的延迟，主要的延迟还是在SQL线程上：

Master_Log_File：表示从库I/O线程当前读取Binlog的文件名，如果比主库当前的binlog日志还小的话说明从库I/O接受主库的日志慢了。

Read_Master_Log_File：表示SQL线程正在应用的Relay Log对应的Binlog，如果这个binlog文件比较老，说明SQL线程应用日志的速度过慢，因此基本可以判断出延迟的线程是SQL线程了。

上面两个多用于进行比较。

Read_Master_Log_Pos：表示从库I/O线程读取主库Binlog的位置。

Exec_Master_Log_Pos：表示SQL线程正在应用Relay Log的位置对应于主库Binlog的位置。

你可以通过 Read_Master_Log_Pos – Exec_Master_Log_Pos 得到的差值来计算SQL_THREAD的落后，但前提是Master_Log_File和Relay_Master_Log_File是相同的