MySQL 復(fù)制中slave延遲監(jiān)控

原文地址：http://imysql.com/2014/08/30/mysql-faq-howto-monitor-slave-lag.shtml

在MySQL復(fù)制環(huán)境中，我們通常只根據(jù) Seconds_Behind_Master 的值來判斷SLAVE的延遲。這么做大部分情況下尚可接受，但并不夠準(zhǔn)確，而應(yīng)該考慮更多因素。

首先，我們先看下SLAVE的狀態(tài)：

yejr@imysql.com [(none)]> 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 秒。

我們?cè)賮砜聪耂LAVE上的2個(gè)REPLICATION進(jìn)程狀態(tài)：

yejr@imysql.com [(none)]> 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線程一直在執(zhí)行UPDATE操作，注意到 Time 的值是 3293，看起來像是這個(gè)UPDATE操作執(zhí)行了3293秒，一個(gè)普通的SQL而已，肯定不至于需要這么久。
實(shí)際上，在REPLICATION進(jìn)程中，Time 這列的值可能有幾種情況：
1、SQL線程當(dāng)前執(zhí)行的binlog（實(shí)際上是relay log）中的timestamp和IO線程最新的timestamp的差值，這就是通常大家認(rèn)為的 Seconds_Behind_Master 值，并不是某個(gè)SQL的實(shí)際執(zhí)行耗時(shí)；
2、SQL線程當(dāng)前如果沒有活躍SQL在執(zhí)行的話，Time值就是SQL線程的idle time；

而IO線程的Time值則是該線程自從啟動(dòng)以來的總時(shí)長(zhǎng)（多少秒），如果系統(tǒng)時(shí)間在IO線程啟動(dòng)后發(fā)生修改的話，可能會(huì)導(dǎo)致該Time值異常，比如變成負(fù)數(shù)，或者非常大。

來看下面幾個(gè)狀態(tài)：

#設(shè)置pager，只查看關(guān)注的幾個(gè)status值
yejr@imysql.com [(none)]> 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
yejr@imysql.com [(none)]> 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 
#和上面一樣
yejr@imysql.com [(none)]> 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 
#這時(shí)有活躍SQL了，Time值是和 Seconds_Behind_Master 一樣，即SQL線程比IO線程“慢”了1秒
yejr@imysql.com [(none)]> 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 
#和上面一樣
yejr@imysql.com [(none)]> 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 的差異，對(duì)比SQL線程比IO線程慢了多少個(gè)binlog事件；
3、如果Relay_Master_Log_File 和 Master_Log_File 不一樣，那說明延遲可能較大，需要從MASTER上取得binlog status，判斷當(dāng)前的binlog和MASTER上的差距；

因此，相對(duì)更加嚴(yán)謹(jǐn)?shù)淖龇ㄊ牵?br> 在第三方監(jiān)控節(jié)點(diǎn)上，對(duì)MASTER和SLAVE同時(shí)發(fā)起SHOW BINARY LOGS和SHOW SLAVE STATUS\G的請(qǐng)求，最后判斷二者binlog的差異，以及 Exec_Master_Log_Pos 和 Read_Master_Log_Pos 的差異。

例如：
在MASTER上執(zhí)行SHOW BINARY LOGS 的結(jié)果是：

+------------------+--------------+
| Log_name | File_size |
+------------------+--------------+
| mysql-bin.000009 | 1073742063 |
| mysql-bin.000010 | 107374193 |
+------------------+--------------+

而在SLAVE上執(zhí)行SHOW SLAVE STATUS\G 的結(jié)果是：

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
***

這時(shí)候，SLAVE實(shí)際的延遲應(yīng)該是：
mysql-bin.000009 這個(gè)binlog中的binlog position 1073742063 和 SLAVE上讀取到的binlog position之間的差異延遲，即：

1073742063 - 654409041 = 419333022 個(gè)binlog event

并且還要加上 mysql-bin.000010這個(gè)binlog已經(jīng)產(chǎn)生的107374193個(gè)binlog event，共

107374193 + 419333022 = 526707215 個(gè)binlog event

后記更新：

1、可以在MASTER上維護(hù)一個(gè)監(jiān)控表，它只有一個(gè)字段，存儲(chǔ)這最新最新時(shí)間戳（高版本可以采用event_scheduler來更新，低版本可以用cron結(jié)合自動(dòng)循環(huán)腳本來更新），在SLAVE上讀取該字段的時(shí)間，只要MASTER和SLAVE的系統(tǒng)時(shí)間一致，即可快速知道SLAVE和MASTER延遲差了多少。不過，在高并發(fā)的系統(tǒng)下，這個(gè)時(shí)間戳可以細(xì)化到毫秒，否則哪怕時(shí)間一致，也是有可能會(huì)延遲數(shù)千個(gè)binlog event的。
2、網(wǎng)友（李大玉，QQ：407361231）細(xì)心支出上面的計(jì)算延遲有誤，應(yīng)該是mysql-bin.000009的最大事件數(shù)減去已經(jīng)被執(zhí)行完的事件數(shù)，即1073742063 – 654409041= 419333022個(gè)binlog event，再加上mysql-bin.000010這個(gè)binlog已經(jīng)產(chǎn)生的107374193個(gè)binlog event，共526707215 個(gè)binlog event。