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 status\G命令輸出的Seconds_Behind_Master參數的值來判斷，是否有發生主從延時。

mysql> show slave status\G;
*************************** 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 status\G的輸出結果，須要監控下面三個參數：
   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 status\G;
*************************** 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 processlist\G;
*************************** 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';

這是沒有活躍SQL的狀況，Time值是idle time，而且 Seconds_Behind_Master 爲 0
mysql> show processlist; show slave status\G;
| 6 | system user | | NULL | Connect | 22004245 | Waiting for master to send event | NULL |
| 7 | system user | | NULL | Connect | 13 | Has read all relay log;**
Read_Master_Log_Pos: 445167889
Exec_Master_Log_Pos: 445167889
Seconds_Behind_Master: 0

多執行幾回，看下是否有活躍的SQL
mysql> show processlist; show slave status\G;
| 6 | system user | | NULL | Connect | 22004248 | Waiting for master to send event | NULL |
| 7 | system user | | NULL | Connect | 16 | Has read all relay log;**
Read_Master_Log_Pos: 445167889
Exec_Master_Log_Pos: 445167889
Seconds_Behind_Master: 0

發現有活躍SQL了，Time值是和 Seconds_Behind_Master 同樣，即SQL線程比IO線程「慢」了1秒
mysql> show processlist; show slave status\G;
| 6 | system user | | NULL | Connect | 22004252 | Waiting for master to send event | NULL |
| 7 | system user | | floweradmin | Connect | 1 | Updating | update **
Read_Master_Log_Pos: 445182239
Exec_Master_Log_Pos: 445175263
Seconds_Behind_Master: 1

再次查看下狀態
mysql> show processlist; show slave status\G;
| 6 | system user | | NULL | Connect | 22004254 | Waiting for master to send event | NULL |
| 7 | system user | | floweradmin | Connect | 1 | Updating | update **
Read_Master_Log_Pos: 445207174
Exec_Master_Log_Pos: 445196837
Seconds_Behind_Master: 1
檢查到此，能夠說下如何正確判斷slave的延遲狀況：
1）首先看 Relay_Master_Log_File 和 Master_Log_File 是否有差別；
2）若是Relay_Master_Log_File 和 Master_Log_File 是同樣的話，再來看Exec_Master_Log_Pos 和 Read_Master_Log_Pos 的差別，對比SQL線程比IO線程慢了多少個binlog事件；
3）若是Relay_Master_Log_File 和 Master_Log_File 不同，那說明延遲可能較大，須要從MASTER上取得binlog status，判斷當前的binlog和MASTER上的差距；

所以，相對更加嚴謹的作法是：
在第三方監控節點上，對MASTER和slave同時發起SHOW BINARY LOGS和SHOW slave STATUS\G的請求，最後判斷兩者binlog的差別，以及 Exec_Master_Log_Pos 和Read_Master_Log_Pos 的差別。

例如：
在MASTER上執行SHOW BINARY LOGS 的結果是：
+------------------+--------------+
| Log_name | File_size |
+------------------+--------------+
| mysql-bin.000009 | 1073742063 |
| mysql-bin.000010 | 107374193 |
+------------------+--------------+
而在slave上執行SHOW slave STATUS\G 的結果是：

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