FAQ系列 | SLAVE為什麼停滞一直不動了

導讀

遇到SLAVE延遲很大，binlog apply position一直不動的情況如何排查？

問題描述

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

Slave_IO_State: Waiting for master to send event
         Master_Log_File: mysql-bin.000605
     Read_Master_Log_Pos: 1194
          Relay_Log_File: mysql-relay-bin.003224
           Relay_Log_Pos: 295105
   Relay_Master_Log_File: mysql-bin.000604
        Slave_IO_Running: Yes
       Slave_SQL_Running: Yes
              Last_Errno: 0
              Last_Error: 
     Exec_Master_Log_Pos: 294959
         Relay_Log_Space: 4139172581
   Seconds_Behind_Master: 10905      

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

Read_Master_Log_Pos: 1194
          Relay_Log_File: mysql-relay-bin.003224
           Relay_Log_Pos: 295105
   Relay_Master_Log_File: mysql-bin.000604
     Exec_Master_Log_Pos: 294959
         Relay_Log_Space: 4139172581      

從processlist的中也看不出來有什麼不對勁的SQL在跑：

******************** 1. row ******************
     Id: 16273070
   User: system user
   Host:
     db: NULL
Command: Connect
   Time: 4828912
  State: Waiting for master to send event
   Info: NULL
********************* 2. row *****************
     Id: 16273071
   User: system user
   Host:
     db: NULL
Command: Connect
   Time: 9798
  State: Reading event from the relay log
   Info: NULL      

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

[[email protected]]# mysqlbinlog -vvv --base64-output=decode-rows -j 294959 mysql-bin.000604 | more

/*!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資訊，通過這種方式可讀性不強，我們換一種姿勢看看：

[[email protected] (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。

-rw-rw---- 1 mysql mysql 1.1G Feb  3 03:07 mysql-bin.000597
-rw-rw---- 1 mysql mysql 1.1G Feb  3 03:19 mysql-bin.000598
-rw-rw---- 1 mysql mysql 2.1G Feb  3 03:33 mysql-bin.000599
-rw-rw---- 1 mysql mysql 1.4G Feb  3 03:45 mysql-bin.000600
-rw-rw---- 1 mysql mysql 1.8G Feb  3 04:15 mysql-bin.000601
-rw-rw---- 1 mysql mysql 1.3G Feb  3 04:53 mysql-bin.000602
-rw-rw---- 1 mysql mysql 4.5G Feb  4 06:16 mysql-bin.000603
-rw-rw---- 1 mysql mysql 3.9G Feb  4 06:52 mysql-bin.000604
-rw-rw---- 1 mysql mysql 1.2K Feb  4 06:52 mysql-bin.000605      

可以看到上面的曆史binlog，個别情況下，一個事務裡一次性要删除資料量太大了，導緻binlog檔案遠超預設的1G，最大的達到4.5G之多。

怎麼解決

由于這是Bacula備份系統内置生成的大事務，除非去修改它的源碼，否則沒有太好的辦法。

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

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

其他導緻SLAVE複制進度看起來停滞了的可能原因：設定了Replicate Ignore/Do DB/Table規則，不符合規則的binlog event都會被忽略，進而看起來像是複制停滞不前。