MySQL 複製夯住一例排查以及原理探討
目錄
文/溫國兵
一 引子
研發反應，有臺從庫和主庫不同步。由於業務讀操作是針對從庫的，資料不同步必定會帶來資料的不一致，業務獲取的結果會受影響，所以這個問題必須儘快解決。
登上伺服器，檢視 MySQL 的從庫狀態，並沒有任何報錯資訊。重新整理從庫狀態，發現狀態沒有任何變化，Exec_Master_Log_Pos 卡住不動。
二 故障分析
為了安全起見，此文略去 MySQL 版本以及其他可能會帶來安全問題的資訊。
接下來逐步分析問題。
首先檢視從庫狀態：
mysql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
Slave_IO_State: Queueing master event to the relay log
Master_Host: masterIP
Master_User: replUser
Master_Port: masterPort
Connect_Retry: 60
Master_Log_File: binlog.000296
Read_Master_Log_Pos: 364027786
Relay_Log_File: relaylog.000002
Relay_Log_Pos: 250
Relay_Master_Log_File: binlog.000283
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
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: 594374863
Relay_Log_Space: 13803486573
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: 256219
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: masterID
1 row in set (0.00 sec) 此時的 Slave_IO_State 為 Queueing master event to the relay log，而不是正常狀態下的 Waiting for master to send event。重新整理多次，狀態沒有任何變化，Exec_Master_Log_Pos 不變，從而導致 Seconds_Behind_Master 一直不變。
接下來檢視 PROCESSLIST 狀態：
mysql> SHOW FULL PROCESSLIST;
+--------+-------------+------------------+--------------------+---------+---------+---------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+-------------+------------------+--------------------+---------+---------+---------------+------------------+
| 51378 | system user | | NULL | Connect | 1121183 | Waiting for master to send event | NULL |
| 88917 | system user | | NULL | Connect | 245327 | Reading event from the relay log | NULL |
| 106029 | userA | xxx.xxx.xxx.xxx:14057 | NULL | Sleep | 14504 | | NULL |
| 106109 | userA | xxx.xxx.xxx.xxx:15077 | databaseA | Sleep | 79 | | NULL |
| 106110 | userA | xxx.xxx.xxx.xxx:15081 | databaseA | Sleep | 13000 | | NULL |
| 106116 | userB | xxx.xxx.xxx.xxx:15096 | databaseA | Sleep | 357 | | NULL |
| 106117 | userB | xxx.xxx.xxx.xxx:15097 | NULL | Sleep | 12964 | | NULL |
| 106119 | root | localhost | NULL | Query | 0 | NULL | SHOW FULL PROCESSLIST |
| 106126 | userB | xxx.xxx.xxx.xxx:15173 | NULL | Sleep | 12856 | | NULL |
| 106127 | userB | xxx.xxx.xxx.xxx:15180 | databaseA | Sleep | 12849 | | NULL |
| 106766 | userA | xxx.xxx.xxx.xxx:17960 | databaseA | Sleep | 64 | | NULL |
+--------+-------------+------------------+--------------------+---------+---------+---------------+------------------+
11 rows in set (0.00 sec) 從以上的結果來看，沒有任何異常。
既然從上述資訊中得不到任何對排查問題有幫助的資訊，那麼我們可以試著分析 MySQL 的 binlog，看 Pos 為 594374863 的點發生了什麼操作。
分析日誌我們可以使用 mysqlbinlog 命令，指定 start-position 為夯住的那個點，並重定向到檔案。
/usr/local/mysql/bin/mysqlbinlog --no-defaults -v --start-position="594374863" \ binlog.000283 > /XXX/binlog.sql 檢視輸出結果，發現端倪了，以下是摘抄的部分結果：
/*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE[email protected]@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #150814 17:43:15 server id 21 end_log_pos 107 Start: binlog v 4, server v x.x.xx-log created 150814 17:43:15 BINLOG ' M7jNVQ8VAAAAZwAAAGsAAAAAAAQANS41LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA== '/*!*/; # at 594374863 #150814 18:09:36 server id 21 end_log_pos 594374945 Query thread_id=210702841 exec_time=43 error_code=0 SET TIMESTAMP=1439546976/*!*/; SET @@session.pseudo_thread_id=210702841/*!*/; 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 utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 594374945 # at 594375036 # at 594376047 # at 594377085 # at 594378123 # at 594379152 # at 594380187 # at 594381165 # at 594382194 # at 594383223 # at 594384252 # at 594385269 # at 594386307 # at 594387282 # at 594388299 # at 594389265 # at 594390270 # at 594391299 # at 594392310 # at 594393327 # at 594394344 # at 594395340 # at 594396336 # at 594397332 從以上輸出中，我們可以知道，從夯住的那個點開始，binlog 記錄的資訊就出現了異常，可以推測在主庫有大操作。另外，針對出現問題庫，檢視主庫和從庫的表數量，發現從庫的表數量多於主庫，有幾個臨時表出現。可以推測的，主庫有刪表的操作，從庫同步夯住，導致同步異常，主庫刪表的操作還沒來得及同步到從庫。
經過和研發溝通，確認了兩點。第一，確實有大操作，程式有大量的批量插入，而且是用的 LOAD DATA LOCAL INFILE；第二，主庫確實有刪表的操作，這幾張表都是臨時表。
三 故障解決
既然問題找到了，那解決辦法自然就有了。既然從庫的表多於主庫，而且這幾張表是臨時資料，我們可以過濾掉對這幾張表的同步操作。具體思路如下：在主庫備份臨時表（雖然研發說資料不重要，但還是以防萬一，DBA 還是謹慎為好），然後通知研發臨時切走從庫的流量，修改配置檔案，指定 replicate-ignore-table 引數，重啟 MySQL。
接下來就是具體的解決步驟，首先備份資料。備份時不加 –master-data 引數和 –single-transaction。究其原因，–master-data 禁用 –lock-tables 引數，在和 –single-transaction 一起使用時會禁用 –lock-all-tables。在備份開始時，會獲取全域性 read lock。 –single-transaction 引數設定預設級別為 REPEATABLE READ，
並且在開始備份時執行 START TRANSACTION。在備份期間， 其他連線不能執行如下語句：ALTER TABLE、CREATE TABLE、DROP TABLE、RENAME TABLE、TRUNCATE TABLE。MySQL 同步夯住，如果加了上述引數，mysqldump 也會夯住。mysqldump 會 FLUSH TABLES、LOCK TABLES，如果有 –master-data 引數，會導致 Waiting for table flush。同樣，有 –single-transaction 引數，仍然會導致 Waiting for table flush。另外，還可以看到 Waiting for table metadata lock，此時做了 DROP TABLE 的操作。此時可以停掉 MySQL 同步來避免這個問題。
為了保險起見，我們在主庫加大 expire_logs_days 引數，避免 binlog 丟失。
mysql> SHOW VARIABLES LIKE '%expire%';
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| expire_logs_days | 3 |
+------------------+-------+
1 row in set (0.00 sec) mysql> SET GLOBAL expire_logs_days=5; Query OK, 0 rows affected (0.00 sec) mysql> SHOW VARIABLES LIKE '%expire%'; +------------------+-------+ | Variable_name | Value | +------------------+-------+ | expire_logs_days | 5 | +------------------+-------+ 1 row in set (0.00 sec) 接著修改從庫的配置檔案：
vim /xxx/xxxx/xxx/my.cnf
在 mysqld 後，加入如下配置：
replicate-ignore-table=databaseA.tableA
replicate-ignore-table=databaseA.tableB
replicate-ignore-table=databaseA.tableC
replicate-ignore-table=databaseA.tableD
然後重啟 MySQL：
/xxx/xxx/xxx/xxx/mysqld restart
登入 MySQL 從庫，檢視從庫狀態，並定時重新整理狀態，我們可以看到的是，Exec_Master_Log_Pos 在遞增，Seconds_Behind_Master 在遞減，證明問題已經解決了。
mysql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: masterIP
Master_User: replUser
Master_Port: masterPort
Connect_Retry: 60
Master_Log_File: binlog.000319
Read_Master_Log_Pos: 985656691
Relay_Log_File: relaylog.000004
Relay_Log_Pos: 709043542
Relay_Master_Log_File: binlog.000284
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table: databaseA.tableA,databaseA.tableB,databaseA.tableC,databaseA.tableD
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 709043399
Relay_Log_Space: 38579192969
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: 258490
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: masterID
1 row in set (0.00 sec) 需要注意的是，待同步完成後，需要把從庫配置檔案中增加的 replicate-ignore-table引數註釋，並重啟 MySQL。
四 原理探討
在主庫執行 LOAD DATA LOCAL INFILE，主庫和從庫時這樣同步的：
- 在主節點：
- 執行 LOAD DATA LOCAL INFILE；
- 拷貝使用的整個文字檔案內容到二進位制日誌；
- 新增 LOAD DATA LOCAL INFILE 到最新的二進位制日誌。
- 複製所有主庫的二進位制日誌到從庫的中繼日誌；
- 在從節點：
- 檢查中繼日誌中的文字檔案；
- 從多箇中繼日誌檔案中讀取所有的塊；
- 文字檔案存放在 /tmp 資料夾中；
- 從中繼日誌中讀取 LOAD DATA LOCAL INFILE；
- 在 SQL 執行緒中執行 LOAD DATA LOCAL INFILE。
在從節點執行的 1-4 步驟中，IO 執行緒會呈現 Reading event from the relay log 狀態，持續地為下一個 LOAD DATA LOCAL INFILE 命令提取 CSV 行。此時從庫會持續落後，一旦從庫落後時間較長，會導致 SQL 執行緒阻塞，呈現 Queueing master event to the relay log 狀態，從而複製夯住。
五 小結
這樣的故障，歸根結底還是研發寫的程式還有優化的餘地。大批量的資料插入，這在 MySQL 中是不推薦使用的。我們可以這樣：第一，一條 SQL 語句插入多條資料；第二，在事務中進行插入處理；第三，分批插入，在程式中設定 auto_commit 為 0，分批插入完成後，手動 COMMIT；第四，需要使用 LOAD DATA LOCAL INFILE 時，設定 sync_binlog 為 1。
–EOF–