瀟湘隱者

生產環境有一套3個節點的MySQL InnoDB Cluster，MySQL的版本為Server version: 8.0.35 MySQL Community Server - GPL， 早上突然收到Zabbix的告警，其中一個節點出現空間告警："/data: Disk space is low (used > 80%)"

檢查分析后發現是因為MySQL的binlog沒有清理導致空間報警，如下所示(binlog太多，省略了部分內容)

$ du -sh *
78G     bin_logs
12K     conf
7.3G    data
132K    logs
4.0K    mysql.pid
0       mysql_temp
4.0K    slow_logs
$ cd bin_logs
$ ls -lrt
total 81783492
-rw-r----- 1 mysql mysql  909802606 Jan  9 00:10 mysql_binlog.000011
-rw-r----- 1 mysql mysql  984228474 Jan 10 00:10 mysql_binlog.000012
-rw-r----- 1 mysql mysql  980302993 Jan 11 00:10 mysql_binlog.000013
-rw-r----- 1 mysql mysql  985147519 Jan 12 00:10 mysql_binlog.000014
-rw-r----- 1 mysql mysql  962232624 Jan 13 00:10 mysql_binlog.000015
....................................................
....................................................
-rw-r----- 1 mysql mysql  891703862 Apr  7 00:10 mysql_binlog.000101
-rw-r----- 1 mysql mysql  920700543 Apr  8 00:10 mysql_binlog.000102
-rw-r----- 1 mysql mysql  921675101 Apr  9 00:10 mysql_binlog.000103
-rw-r----- 1 mysql mysql       3854 Apr  9 00:10 mysql_binlog.index
-rw-r----- 1 mysql mysql  330341220 Apr  9 09:30 mysql_binlog.000104

檢查三個節點(姑且用node1, node2, node3表示)，發現其它兩個節點(node1,node2)的binlog都正常清理了，而唯獨節點node3的binlog一直沒有被清理。三個節點的MySQL系統變量是一致的，如下所示，

mysql> show variables like 'binlog_expire_logs_seconds';
+----------------------------+---------+
| Variable_name              | Value   |
+----------------------------+---------+
| binlog_expire_logs_seconds | 1209600 |
+----------------------------+---------+
1 row in set (0.00 sec)

mysql> show variables like 'expire_logs_days';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| expire_logs_days | 0     |
+------------------+-------+
1 row in set (0.00 sec)

mysql> 

binlog_expire_logs_seconds設置為1209600，也就是14天，超過14天的binlog應該被清理掉，但是檢查發現node3上超過14天的binlog并沒有被清理。那么為什么節點node3上的過期的binlog沒有被清理呢？

首先，這三個節點的MySQL數據庫版本是一致的，出現問題的節點node3是MySQL InnoDB集群的備庫，我們在這個節點上做Xtrabackup備份。

其次，我們檢查MySQL錯誤日志，其實每天作業做Xtrabackup備份時，都會收到類似下面告警郵件

2024-04-09T00:10:03.078285+08:00 357726 [Warning] [MY-013712] [Server] No suitable 'keyring_component_metadata_query' service implementation found to fulfill the request.
2024-04-09T00:10:12.066464+08:00 357726 [Warning] [MY-014054] [Server] Could not purge binary logs since another session is executing LOCK INSTANCE FOR BACKUP. Wait for that session to release the lock.

出現這個告警信息，之前也查過，官方文檔提示，當對MySQL實例發出LOCK INSTANCE FOR BACKUP語句期間，PURGE BINARY LOGS是不允許的，因為它會從服務器中刪除文件(刪除binlog文件)，違反了備份鎖(backup lock)的規則。從MySQL 8.0.28開始，這個是不允許的。具體的官方文檔^[1]信息如下所示：

PURGE BINARY LOGS should not be issued while a LOCK INSTANCE FOR BACKUP statement is in effect for the instance, because it contravenes the rules of the backup lock by removing files from the server. From MySQL 8.0.28, this is disallowed.

因為Xtrabackup備份時，它會執行FLUSH NO_WRITE_TO_BINLOG BINARY LOGS命令，它會輪換二進制日志(rotate the binlog)，這實質上將創建一個新的二進制日志，而在 輪換二進制日志時，就會觸發PURGE BINARY LOGS,而由于當前MySQL版本為MySQL 8.0.35，在MySQL進行Xtrabackup時，由于LOCK INSTANCE FOR BACKUP鎖，導致PURGE BINARY LOGS是不允許的。所以Xtrabackup期間，我們會收到這個告警，即使binlog出現了輪換，但是也不會觸發清理過期的binlog。之前分析過這個告警，但是覺得它沒有產生什么異常或問題，就忽略了這個告警。

另外，我們要弄清楚清理過期binlog的原理機制，即使我們設置了系統變量binlog_expire_logs_seconds，不是說一旦binlog的創建時間超過了系統變的binlog_expire_logs_seconds的閾值，就會立即觸發MySQL的相關線程去清理過期的binlog。清理過期的binlog，一般發生在MySQL啟動時或刷新二進制日志時進行。官方文檔^[2]的描述如下：

Binary log files are automatically removed after the server's binary log expiration period. Removal of the files can take place at startup and when the binary log is flushed.

我檢查系統變量max_binlog_size的大小，如下所示，也就是1G，

mysql> show variables like 'max_binlog_size';
+-----------------+------------+
| Variable_name   | Value      |
+-----------------+------------+
| max_binlog_size | 1073741824 |
+-----------------+------------+
1 row in set (0.01 sec)

mysql>

由于這個系統一天產生的binlog小于1G(可以從上面的binlog的輸出信息看出，例如，binlog的大小，binlog的創建時間)，也就是說，一天24小時內，MySQL的binlog不會由于binlog過大而觸發binlog的切換，也就是說只有Xtrabackup時才觸發了binlog的切換，而又由于限制問題，導致過期的binlog不能被清理，久而久之，過期的binlog一直不能清理，直到觸發空間告警，問題才被暴露出來。

而其它幾套MySQL InnoDB Cluster也有這個問題，但是它們的過期的binlog為什么被清理了呢？ 因為它們一天產生的binlog的大小，超過了系統變量max_binlog_size的大小，在其它時間點會輪換/切換binlog,從而觸發了PURGE BINARY LOGS。所以就沒有遇到這樣的問題。

參考資料