故障分析 | MySQL 從機故障重啟後主從同步報錯案例分析

愛可生雲資料庫發表於2022-02-28
MySql主從同步

作者：付祥

現居珠海，主要負責 Oracle、MySQL、mongoDB 和 Redis 維護工作。

本文來源：原創投稿

*愛可生開源社群出品，原創內容未經授權不得隨意使用，轉載請聯絡小編並註明來源。

1. 環境說明

1.1. MySQL版本

root@3306 (none)> SELECT @@VERSION;
+------------+
| @@VERSION |
+------------+
| 5.7.34-log |
+------------+
1 row in set (0.01 sec)

1.2. binlog 相關引數

root@3306 (none)> select @@log_bin,@@log_slave_updates;
+-----------+---------------------+
| @@log_bin | @@log_slave_updates |
+-----------+---------------------+
| 1 | 1 |
+-----------+---------------------+
1 row in set (0.00 sec)
root@3306 (none)>

1.3. GTID 相關引數

root@3306 (none)> select
@@binlog_gtid_simple_recovery,@@enforce_gtid_consistency,@@gtid_mode;
+-------------------------------+----------------------------+-------------+
| @@binlog_gtid_simple_recovery | @@enforce_gtid_consistency | @@gtid_mode |
+-------------------------------+----------------------------+-------------+
| 1 | ON | ON |
+-------------------------------+----------------------------+-------------+
1 row in set (0.01 sec)
root@3306 (none)>

1.4. 半同步相關引數

root@3306 (none)> show global variables like '%semi%';
+-------------------------------------------+------------+
| Variable_name | Value |
+-------------------------------------------+------------+
| rpl_semi_sync_master_enabled | ON |
| rpl_semi_sync_master_timeout | 1000 |
| rpl_semi_sync_master_trace_level | 32 |
| rpl_semi_sync_master_wait_for_slave_count | 1 |
| rpl_semi_sync_master_wait_no_slave | ON |
| rpl_semi_sync_master_wait_point | AFTER_SYNC |
| rpl_semi_sync_slave_enabled | ON |
| rpl_semi_sync_slave_trace_level | 32 |
+-------------------------------------------+------------+
8 rows in set (0.00 sec)
root@3306 (none)>

1.5. 多執行緒同步相關引數

root@3306 (none)> select
@@binlog_transaction_dependency_tracking,@@slave_parallel_type,@@slave_parallel_
workers;
+------------------------------------------+-----------------------+---------
-----------------+
| @@binlog_transaction_dependency_tracking | @@slave_parallel_type |
@@slave_parallel_workers |
+------------------------------------------+-----------------------+---------
-----------------+
| COMMIT_ORDER | LOGICAL_CLOCK |
2 |
+------------------------------------------+-----------------------+---------
-----------------+
1 row in set (0.00 sec)
root@3306 (none)>

2.故障現象

MySQL 從庫所在主機故障重啟後，sql_thread 執行緒報錯：

root@3306 (none)> show slave status\G
-- 摘取有用資訊如下：
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1062
Last_Error: Coordinator stopped because there were
error(s) in the worker(s). The most recent failure being: Worker 1 failed
executing transaction '471c2974-f9bb-11eb-afb1-52540010fb89:88313207' at master
log MySql-bin.000685, end_log_pos 1004756557. See error log and/or
performance_schema.replication_applier_status_by_worker table for more details
about this failure or others, if any.
......省略..................
Retrieved_Gtid_Set: 471c2974-f9bb-11eb-afb1-
52540010fb89:88313207-88341912
Executed_Gtid_Set: 471c2974-f9bb-11eb-afb1-52540010fb89:1-
88313206,
d4c228df-f9c6-11eb-a2d8-5254006f63b6:1-5
Auto_Position: 1
root@3306 (none)> select * from
performance_schema.replication_applier_status_by_worker\G
*************************** 1. row ***************************
CHANNEL_NAME:
WORKER_ID: 1
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 471c2974-f9bb-11eb-afb1-52540010fb89:88313207
LAST_ERROR_NUMBER: 1062
LAST_ERROR_MESSAGE: Worker 1 failed executing transaction '471c2974-f9bb-
11eb-afb1-52540010fb89:88313207' at master log MySql-bin.000685, end_log_pos
1004756557; Could not execute Write_rows event on table kefumobile.i_sms_proxy;
Duplicate entry '14765130' for key 'PRIMARY', Error_code: 1062; handler error
HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 1004756557
LAST_ERROR_TIMESTAMP: 2022-01-24 23:05:02
*************************** 2. row ***************************
CHANNEL_NAME:
WORKER_ID: 2
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION:
LAST_ERROR_NUMBER: 0
LAST_ERROR_MESSAGE:
LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
2 rows in set (0.00 sec)

通過報錯資訊可知，worker 執行緒在回放事務 '471c2974-f9bb-11eb-afb1-52540010fb89:88313207' 時，由於要插入的記錄主鍵衝突報錯。

3.故障分析

主機重啟前，主從同步正常，主機重啟後，主從同步由於主鍵衝突報錯，對比了衝突主鍵所在行記
錄在主從庫是一致的，初步分析事務 '471c2974-f9bb-11eb-afb1-52540010fb89:88313207' 在主機故
障前已經在從庫進行了回放，那為何事務會重複回放呢？

在開啟gtid模式下，如果指定 master_auto_position=1，start slave 時，從庫會把
Retrieved_Gtid_Set 和 Executed_Gtid_Set 的並集傳送給主庫，主庫將收到的並集和自己的
gtid_executed 比較，把從庫 gtid 集合裡缺失的事務全都傳送給從庫。

主機重啟後，事務重複回放，表明 Retrieved_Gtid_Set 和 Executed_Gtid_Set 的並集中有 GTID 事務
丟失，導致重複獲取事務執行引發主鍵衝突錯誤。Retrieved_Gtid_Set 和 Executed_Gtid_Set 均為記憶體變
量，MySQL 重啟後，Retrieved_Gtid_Set 初始化為空值，從而推斷出 Executed_Gtid_Set 有 GTID 事務丟
失。

Executed_Gtid_Set 來源於 gtid_executed 變數，gtid_executed 變數持久化介質有
mysql.gtid_executed 表和 binlog ，其中 mysql.gtid_executed 表是 MySQL 5.7 後引入的，在 MySQL 5.6 中，從庫要使用 GTID ，必須要先設定 log_bin=on,log_slave_updates=on ，因為從庫執行過的 GTID 只保留在 binlog 中。

  1. 當 log_bin=on ，log_slave_updates=off 時，gtid_executed 變數的更新實時持久化到 mysql.gtid_executed 表中，MySQL 重啟後 gtid_executed 變數值從 mysql.gtid_executed 表讀取。
  2. 當 log_bin=on ，log_slave_updates=on 時，只有在 binlog 切換時侯才會更新 mysql.gtid_executed 表，儲存直到上一個 binlog 執行過的 GTID 集合。mysql 重啟後，在預設引數 binlog_gtid_simple_recovery=1 時，gtid_executed 變數值從最後一個 binlog 檔案計算獲得。

gtid_executed 變數值陳舊，推斷出 binlog 未實時持久化，我們看一下引數 sync_binlog :

root@3306 (none)> show variables like 'sync_binlog';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| sync_binlog | 600 |
+---------------+-------+
1 row in set (0.00 sec)

通過以上分析，此次故障來龍去脈就清楚了：

Worker 執行緒報 1062 主鍵衝突錯誤 --> gtid_executed 資訊陳舊 --> binlog 未實時持久化

4.測試驗證

搭建一主一從測試環境，通過 sysbench 模擬主庫併發插入，從庫主機暴力關機後，故障復現：

root@mysql.sock][(none)]> select * from
performance_schema.replication_applier_status_by_worker\G
*************************** 1. row ***************************
CHANNEL_NAME:
WORKER_ID: 1
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 4a0ad3da-b89e-11eb-9d0b-000c299b4d6c:452362
LAST_ERROR_NUMBER: 1062
LAST_ERROR_MESSAGE: Worker 1 failed executing transaction '4a0ad3da-b89e-
11eb-9d0b-000c299b4d6c:452362' at master log MySql-bin.000012, end_log_pos
1011339749; Could not execute Write_rows event on table sbtest.sbtest5;
Duplicate entry '111305' for key 'PRIMARY', Error_code: 1062; handler error
HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 1011339749
LAST_ERROR_TIMESTAMP: 2022-01-26 09:56:38
*************************** 2. row ***************************
CHANNEL_NAME:
WORKER_ID: 2
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION:
LAST_ERROR_NUMBER: 0
LAST_ERROR_MESSAGE:
LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
2 rows in set (0.00 sec)
[root@mysql.sock][(none)]>

5.故障處理

既然錯誤原因是事務重複執行，那跳過錯誤就好了，有如下兩種方式，根據需要選取其中一種方式執行：

5.1.通過空事務替代報錯事務執行

set gtid_next='xxxxxx';
begin;
commit;
set gtid_next=AUTOMATIC;
start slave sql_thread

如果最新 binglog 丟失的 GTID 較多，手工執行比較繁瑣，需要不斷試錯。可寫一個儲存過程批量執行：

set sql_log_bin=0;
DELIMITER $$
create procedure p_fx_gtid_next(i_master_Executed_Gtid_max varchar(100))
begin
declare v_gtid_next varchar(100);
declare master_Executed_Gtid_max varchar(100);
declare slave_Executed_Gtid_max varchar(100);
-- 主庫當前執行了的gtid最大值，做為退出迴圈條件 show master status
set master_Executed_Gtid_max=i_master_Executed_Gtid_max;
loop_name:loop
SELECT ifnull(min(LAST_SEEN_TRANSACTION),'empty') FROM
performance_schema.replication_applier_status_by_worker WHERE
LAST_ERROR_NUMBER=1062
into v_gtid_next;
if v_gtid_next <> 'empty' then
set gtid_next = v_gtid_next;
start transaction;
commit;
set gtid_next =AUTOMATIC;
start slave sql_thread;
end if;
select max(LAST_SEEN_TRANSACTION) from
performance_schema.replication_applier_status_by_worker into
slave_Executed_Gtid_max;
if slave_Executed_Gtid_max = master_Executed_Gtid_max then
leave loop_name;
end if;
select SLEEP(1);
end loop;
end $$
DELIMITER ;
set sql_log_bin=1;
call p_fx_gtid_next('XXXXX:XXX');

5.2.帶引數 slave_skip_errors=1062 重啟 MySQL

待主從同步正常後，再取消引數 slave_skip_errors 設定重啟 MySQL 。

相關文章