mysql主從同步(4)-Slave延遲狀態監控

散盡浮華發表於2016-07-19

 

之前部署了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

相關文章