問題描述

收到SLAVE延遲時間一直很大的報警，於是檢查一下SLAVE狀態（無關狀態我給隱去了）：

Slave_IO_State: Waiting for master to send event Master_Log_File: mysql-bin.000605 ---當前master的binlog
Read_Master_Log_Pos: 305864 ---master binlog位置
Relay_Log_File: mysql-relay-bin.003224 Relay_Log_Pos: 295105 Relay_Master_Log_File: mysql-bin.000604 ----當前salve同步到的master的binlog日誌
Slave_IO_Running: Yes Slave_SQL_Running: Yes Last_Errno: 0 Last_Error: Exec_Master_Log_Pos: 294959 -----當前slave執行到的master的binlog 的pos
Relay_Log_Space: 4139172581 Seconds_Behind_Master: 10905 ---延遲一般是Read_Master_Log_Pos-Exec_Master_Log_Pos

可以看到，延遲確實很大，而且從多次show slave status的結果來看，發現binlog的position一直不動。

點選(此處)摺疊或開啟

檢查processlist 也沒發現異常sql語句

在master上檢視相應binlog，確認都在幹神馬事：

[yejr@imysql.com]# mysqlbinlog -vvv --base64-output=decode-rows -j 294959 mysql-bin.000604 | more
--base64-output=decode-rows --去除一些不必要的二進位制日誌展示 /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; **# at 294959** #160204 6:16:30 server id 1 end_log_pos 295029 **Query thread_id=461151** **exec_time=2144** error_code=0 SET TIMESTAMP=1454537790/*!*/; SET @@session.pseudo_thread_id=461151/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=0/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; /*!\C latin1 *//*!*/; SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 295029 # at 295085 # at 296040 # at 297047 # at 298056 # at 299068 # at 300104

上面這段內容的幾個關鍵資訊：
# at 294959 — binlog起點
thread_id=461151 — master上執行的執行緒ID
exec_time=2144 — 該事務執行總耗時

再往下看都是一堆的binlog position資訊，透過這種方式可讀性不強，我們換一種姿勢看看

[yejr@imysql.com (test)]> show binlog events in 'mysql-bin.000604' from 294959 limit 10; +------------------+--------+-------------+-----------+-------------+----------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | +------------------+--------+-------------+-----------+-------------+----------------------------+ | mysql-bin.000604 | 294959 | Query | 1 | 295029 | BEGIN | | mysql-bin.000604 | 295029 | Table_map | 1 | 295085 | table_id: 84 (bacula.File) | | mysql-bin.000604 | 295085 | Delete_rows | 1 | 296040 | table_id: 84 | | mysql-bin.000604 | 296040 | Delete_rows | 1 | 297047 | table_id: 84 | | mysql-bin.000604 | 297047 | Delete_rows | 1 | 298056 | table_id: 84 | | mysql-bin.000604 | 298056 | Delete_rows | 1 | 299068 | table_id: 84 | | mysql-bin.000604 | 299068 | Delete_rows | 1 | 300104 | table_id: 84 | | mysql-bin.000604 | 300104 | Delete_rows | 1 | 301116 | table_id: 84 | | mysql-bin.000604 | 301116 | Delete_rows | 1 | 302147 | table_id: 84 | | mysql-bin.000604 | 302147 | Delete_rows | 1 | 303138 | table_id: 84 |

可以看到，這個事務不幹別的，一直在刪除資料。
這是一個Bacula備份系統，會每天自動刪除一個月前的過期資料。
事實上，這個事務確實非常大，從binlog的294959開始，一直到這個binlog結束4139169218，一直都是在幹這事，總共大概有3.85G的binlog要等著apply。

怎麼解決

由於這是Bacula備份系統內建生成的大事務，除非去修改它的原始碼，否則沒有太好的辦法。

對於我們一般的應用而言，最好是攢夠一定操作後，就先提交一下事務，比如刪除幾千條記錄後提交一次，而不是像本例這樣，一個刪除事務消耗了將近3.9G的binlog日質量，這種就非常可怕了。

除了會導致SLAVE看起來一直不動以外，還可能會導致某些資料行（data rows）被長時間鎖定不釋放，而導致大量行鎖等待發生。

參考文件

【Mysql】Slave 延遲很大並且不動了