mysql主从同步(4)-Slave延迟状态监控

之前部署了mysql主从同步环境（Mysql主从同步(1)-主从/主主环境部署梳理），针对主从同步过程中slave延迟状态的监控梳理如下：

在mysql日常维护工作中，对于主从复制的监控主要体现在： 1）检查数据是否一致；主从数据不同步时，参考下面两篇文档记录进行数据修复： mysql主从同步(3)-percona-toolkit工具（数据一致性监测、延迟监控）使用梳理利用mk-table-checksum监测Mysql主从数据一致性操作记录

2）监控主从同步延迟，同步延迟的检查工作主要从下面两方面着手： 1.一般的做法就是根据Seconds_Behind_Master的值来判断slave的延迟状态。可以通过监控show slave statusG命令输出的Seconds_Behind_Master参数的值来判断，是否有发生主从延时。

mysql> show slave statusG;
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.168.1.101
Master_User: slave
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000004
Read_Master_Log_Pos: 761249
Relay_Log_File: mysql-relay-bin.000008
Relay_Log_Pos: 761408
Relay_Master_Log_File: mysql-bin.000004
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB: huanqiu,huanpc
Replicate_Ignore_DB: mysql
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: 761249
Relay_Log_Space: 761620
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: 0
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: 101
Master_UUID: b667a58f-d6e0-11e6-8c0a-fa163e2d66ac
Master_Info_File: /data/mysql/data/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it
Master_Retry_Count: 86400
Master_Bind: 
Last_IO_Error_Timestamp: 
Last_SQL_Error_Timestamp: 
Master_SSL_Crl: 
Master_SSL_Crlpath: 
Retrieved_Gtid_Set: 
Executed_Gtid_Set: 
Auto_Position: 0
1 row in set (0.00 sec)

ERROR: 
No query specified

以上是show slave statusG的输出结果，需要监控下面三个参数： 1）Slave_IO_Running：该参数可作为io_thread的监控项，Yes表示io_thread的和主库连接正常并能实施复制工作，No则说明与主库通讯异常，多数情况是由主从间网络引起的问题； 2）Slave_SQL_Running：该参数代表sql_thread是否正常，YES表示正常，NO表示执行失败，具体就是语句是否执行通过，常会遇到主键重复或是某个表不存在。 3）Seconds_Behind_Master：是通过比较sql_thread执行的event的timestamp和io_thread复制好的event的timestamp(简写为ts)进行比较，而得到的这么一个差值； NULL—表示io_thread或是sql_thread有任何一个发生故障，也就是该线程的Running状态是No，而非Yes。 0 — 该值为零，是我们极为渴望看到的情况，表示主从复制良好，可以认为lag不存在。正值 — 表示主从已经出现延时，数字越大表示从库落后主库越多。负值 — 几乎很少见，我只是听一些资深的DBA说见过，其实，这是一个BUG值，该参数是不支持负值的，也就是不应该出现。 ----------------------------------------------------------------------------------------------------------------------------- Seconds_Behind_Master的计算方式可能带来的问题： relay-log和主库的bin-log里面的内容完全一样，在记录sql语句的同时会被记录上当时的ts，所以比较参考的值来自于binlog，其实主从没有必要与NTP进行同步，也就是说无需保证主从时钟的一致。其实比较动作真正是发生在io_thread与sql_thread之间，而io_thread才真正与主库有关联，于是，问题就出来了，当主库I/O负载很大或是网络阻塞，io_thread不能及时复制binlog（没有中断，也在复制），而sql_thread一直都能跟上io_thread的脚本，这时Seconds_Behind_Master的值是0，也就是我们认为的无延时，但是，实际上不是，你懂得。这也就是为什么大家要批判用这个参数来监控数据库是否发生延时不准的原因，但是这个值并不是总是不准，如果当io_thread与master网络很好的情况下，那么该值也是很有价值的。之前，提到Seconds_Behind_Master这个参数会有负值出现，我们已经知道该值是io_thread的最近跟新的ts与sql_thread执行到的ts差值，前者始终是大于后者的，唯一的肯能就是某个event的ts发生了错误，比之前的小了，那么当这种情况发生时，负值出现就成为可能。 -----------------------------------------------------------------------------------------------------------------------------

简单来说，就是监控slave同步状态中的： 1）Slave_IO_Running、Slave_SQL_Running状态值，如果都为YES，则表示主从同步；反之，主从不同步。 2）Seconds_Behind_Master的值，如果为0，则表示主从同步不延时，反之同步延时。

2.上面根据Seconds_Behind_Master的值来判断slave的延迟状态，这么做在大部分情况下尚可接受，但其实是并不够准确的。对于Slave延迟状态的监控，还应该做到下面的考虑：首先，我们先看下slave的状态： mysql> show slave statusG; *************************** 1. row *************************** slave_IO_State: Waiting for master to send event *** Master_Log_File: mysql-bin.000327 Read_Master_Log_Pos: 668711237 Relay_Log_File: mysql-relay-bin.002999 Relay_Log_Pos: 214736858 Relay_Master_Log_File: mysql-bin.000327 slave_IO_Running: Yes slave_SQL_Running: Yes *** Skip_Counter: 0 Exec_Master_Log_Pos: 654409041 Relay_Log_Space: 229039311 *** Seconds_Behind_Master: 3296 *** 可以看到 Seconds_Behind_Master 的值是 3296，也就是slave至少延迟了 3296 秒。

我们再来看下slave上的2个REPLICATION进程状态： mysql> show full processlistG; *************************** 1. row *************************** Id: 6 User: system user Host: db: NULL Command: Connect Time: 22005006 State: Waiting for master to send event Info: NULL *************************** 2. row *************************** Id: 7 User: system user Host: db: NULL Command: Connect Time: 3293 State: Updating Info: UPDATE ** SET ** WHERE **

可以看到SQL线程一直在执行UPDATE操作，注意到 Time 的值是 3293，看起来像是这个UPDATE操作执行了3293秒，一个普通的SQL而已，肯定不至于需要这么久。实际上，在REPLICATION进程中，Time 这列的值可能有几种情况： 1）SQL线程当前执行的binlog（实际上是relay log）中的timestamp和IO线程最新的timestamp的差值，这就是通常大家认为的 Seconds_Behind_Master 值，并不是某个SQL的实际执行耗时； 2）SQL线程当前如果没有活跃SQL在执行的话，Time值就是SQL线程的idle time；而IO线程的Time值则是该线程自从启动以来的总时长（多少秒），如果系统时间在IO线程启动后发生修改的话，可能会导致该Time值异常，比如变成负数，或者非常大。来看下面几个状态：设置pager，只查看关注的几个status值 mysql> pager cat | egrep -i 'system user|Exec_Master_Log_Pos|Seconds_Behind_Master|Read_Master_Log_Pos';

因此，相对更加严谨的做法是：在第三方监控节点上，对MASTER和slave同时发起SHOW BINARY LOGS和SHOW slave STATUSG的请求，最后判断二者binlog的差异，以及 Exec_Master_Log_Pos 和Read_Master_Log_Pos 的差异。

Master_Log_File: mysql-bin.000009 Read_Master_Log_Pos: 668711237 Relay_Master_Log_File: mysql-bin.000009 slave_IO_Running: Yes slave_SQL_Running: Yes *** Exec_Master_Log_Pos: 654409041

*** Seconds_Behind_Master: 3296 *** 这时候，slave实际的延迟应该是： mysql-bin.000009 这个binlog中的binlog position 1073742063 和 slave上读取到的binlog position之间的差异延迟，即： 1073742063 - 654409041 = 419333022 个binlog event 并且还要加上 mysql-bin.000010这个binlog已经产生的107374193个binlog event，共 107374193 + 419333022 = 526707215 个binlog event