實戰演練：MySQL手動注冊binlog文件造成主從同步異常

原文： https://www.enmotech.com/web/detail/1/789/1.html

公司主營業務：成都做網站、成都網站建設、移動網站開發等業務。幫助企業客戶真正實現互聯網宣傳，提高企業的競爭能力。成都創新互聯是一支青春激揚、勤奮敬業、活力青春激揚、勤奮敬業、活力澎湃、和諧高效的團隊。公司秉承以“開放、自由、嚴謹、自律”為核心的企業文化，感謝他們對我們的高要求，感謝他們從不同領域給我們帶來的挑戰，讓我們激情的團隊有機會用頭腦與智慧不斷的給客戶帶來驚喜。成都創新互聯推出武陵免費做網站回饋大家。

導讀：本文是作者用MySQL數據庫手動注冊binlog文件造成主從同步異常后，詳述整個分析與解決的過程。

一、問題來源

因為某些需求，想將備份的binlog文件恢復到主庫并且進行注冊，在不關閉主從同步的情況下，他做了如下操作：

1. 將備份的一些binlog文件加入到了binlog日志目錄文件中。
2. 修改index文件，加入了這些binlog文件。

3. flush binary logs注冊文件。

做完這些操作后，主庫確實binlog注冊回來了，但是整個主從環境大量延遲。

二、初次測試

測試操作如下：

1. 主庫操作，拷貝并且清理binlog

(root:db1@xucl:10:30:22)[(none)]> show binary logs;
+---------------------+-----------+
| Log_name            | File_size |
+---------------------+-----------+
| mysql-binlog.000035 |      2134 |
| mysql-binlog.000036 |    845915 |
| mysql-binlog.000037 |     11735 |
| mysql-binlog.000038 |       284 |
| mysql-binlog.000039 |       284 |
| mysql-binlog.000040 |       284 |
| mysql-binlog.000041 |       284 |
| mysql-binlog.000042 |       234 |
+---------------------+-----------+
12 rows in set (0.00 sec)

拷貝需要清理的binlog到備份目錄，即binlog 35、36、37、38。

(root:db1@xucl:10:30:34)[(none)]> purge binary logs to 'mysql-binlog.000039';
Query OK, 0 rows affected (0.00 sec)
(root:db1@xucl:10:30:49)[(none)]> show binary logs;
+---------------------+-----------+
| Log_name            | File_size |
+---------------------+-----------+
| mysql-binlog.000039 |       284 |
| mysql-binlog.000040 |       284 |
| mysql-binlog.000041 |       284 |
| mysql-binlog.000042 |       234 |
+---------------------+-----------+
4 rows in set (0.00 sec)

2. 主庫操作，將備份的binlog拷貝回原先的目錄并修改index文件進行注冊

[root@izbp12nspj47ypto9t6vyez logs]# ll
-rw-r----- 1 mysql mysql   2134 5月 20 22:03 mysql-binlog.000035
-rw-r----- 1 mysql mysql 845915 5月 20 22:03 mysql-binlog.000036
-rw-r----- 1 mysql mysql 11735 5月 20 22:05 mysql-binlog.000037
-rw-r----- 1 mysql mysql    284 5月 20 22:06 mysql-binlog.000038
-rw-r----- 1 mysql mysql    284 5月 21 10:28 mysql-binlog.000039
-rw-r----- 1 mysql mysql    284 5月 21 10:28 mysql-binlog.000040
-rw-r----- 1 mysql mysql    284 5月 21 10:28 mysql-binlog.000041
-rw-r----- 1 mysql mysql    491 5月 21 10:31 mysql-binlog.000042
-rw-r----- 1 mysql mysql    204 5月 21 10:30 mysql-binlog.index

3. 主庫操作，主庫flush binary logs

(root:db1@xucl:10:32:51)[(none)]> flush binary logs;
Query OK, 0 rows affected (0.01 sec)
(root:db1@xucl:10:32:57)[(none)]> show binary logs;
+---------------------+-----------+
| Log_name            | File_size |
+---------------------+-----------+
| mysql-binlog.000035 |      2134 |
| mysql-binlog.000036 |    845915 |
| mysql-binlog.000037 |     11735 |
| mysql-binlog.000038 |       284 |
| mysql-binlog.000039 |       284 |
| mysql-binlog.000040 |       284 |
| mysql-binlog.000041 |       284 |
| mysql-binlog.000042 |       541 |
| mysql-binlog.000043 |       234 |
+---------------------+-----------+
13 rows in set (0.00 sec)

4. 此時，從庫操作，show slave status

報錯如下：

Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Cannot replicate GTID-
transaction when @@GLOBAL.GTID_MODE = OFF, at file /storage/single/mysql3306/logs/mysql-binlog.000035, position 194.

5. 錯誤觀察

從這個錯誤的位點來看，在主庫flush binary logs后，視乎主庫的DUMP線程又在重新發送老的mysql-binlog.000035這個binlog。報錯是因為以前是GTID模式，但是測試的時候已經改為了POSITION模式，是主庫DUMP線程在檢測主庫的GTID Event和從庫的GTID模式是否兼容的時候報出來的，如下圖

實戰演練：MySQL手動注冊binlog文件造成主從同步異常

這個錯誤在這里并不重要，我們只需要知道老的binlog mysql-binlog.000035居然再次發送了。

三、flush binary logs對binlog的操作

flush binary logs 至少包含如下操作：

獲取新的binlog文件名字
關閉舊的binlog
關閉index file
打開index file
打開新的binlog
將新的binlog加入到indexfile
根據參數expire_logs_days判斷是否需要進行binlog刪除

具體可以參考函數MYSQL_BIN_LOG::new_file_impl。其中要說明一下獲取新的binlog文件名字是通過函數find_uniq_filename實現的，其中包含如下代碼：

file_info= dir_info->dir_entry;
for (i= dir_info->number_off_files ; i-- ; file_info++)
{
    if (strncmp(file_info->name, start, length) == 0 &&
    is_number(file_info->name+length, &number,0))
    {
      set_if_bigger(max_found, number);
    }
}
...
*next= (need_next || max_found == 0) ? max_found + 1 : max_found;

大概意思就是掃描binlog目錄下的binlog文件，獲取其序號最高的一個，然后加1。因此即便我們手動修改了index file，flush binary logs不會有問題，因為它實際掃描了binlog文件。同時我們也看到flush binary logs重新加載了index file，這個時候手動修改的index file就生效了，使用show binary logs就能查看到你手動加入的文件了。

棧幀如下：

#0 find_uniq_filename (name=0x7fffec5ec6d0 "/mysqldata/mysql3340/log/binlog", next=0x7fffec5ec678, need_next=true)
    at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3679
#1 0x000000000187d208 in generate_new_log_name (new_name=0x7fffec5ec6d0 "/mysqldata/mysql3340/log/binlog", new_ext=0x0,
    log_name=0x7ffedc011520 "/mysqldata/mysql3340/log/binlog", is_binlog=true) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3767
#2 0x0000000001884fdb in MYSQL_BIN_LOG::new_file_impl (this=0x2e83640, need_lock_log=false, extra_description_event=0x0)
    at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7175
#3 0x0000000001884cbb in MYSQL_BIN_LOG::new_file_without_locking (this=0x2e83640, extra_description_event=0x0)
    at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7099
#4 0x0000000001886b6b in MYSQL_BIN_LOG::rotate (this=0x2e83640, force_rotate=true, check_purge=0x7fffec5ecbfb)
    at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7775
#5 0x0000000001886d53 in MYSQL_BIN_LOG::rotate_and_purge (this=0x2e83640, thd=0x7ffedc000b90, force_rotate=true)
    at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7846

四、主從問題的產生

binlog切換后，DUMP線程也需要讀取下一個binlog文件，但是它獲取的過程和flush binary logs完全不同。在函數Binlog_sender::run中可以找到循環每個binlog文件的代碼。下面一句是尋找下一個binlog文件：

int error= mysql_bin_log.find_next_log(&m_linfo, 0);

mysql_bin_log.find_next_log 包含的代碼：

my_b_seek(&index_file, linfo->index_file_offset);//進行偏移量偏移
linfo->index_file_start_offset= linfo->index_file_offset;
length=my_b_gets(&index_file, fname, FN_REFLEN));//讀取文件名字
...
if(normalize_binlog_name(full_fname, fname, is_relay_log))
...
linfo->index_file_offset= my_b_tell(&index_file);//偏移量從新記錄以備下一次使用

我們能夠看到DUMP線程并沒有實際掃描整個index文件，而是通過一個index文件的偏移量進行讀取。如果手動修改index文件那么這個偏移量就不會維護，DUMP發送的下一個文件將是不確定的，因此出現了發送手動注冊的binlog文件給從庫的現象，根據主從設置的不同將會出現下面的情況：

如果是GTID_MODE 關閉，使用POSITION那么這種情況一定報錯，比如重復的行，下面我們會測試這種情況。
如果是GTID_MODE 和AUTO_POSITION=1，那么DUMP線程會進行GTID的過濾不發送，因為Event不發送所以延遲會持續一段時間為0。
如果是GTID_MODE 和AUTO_POSITION=0，那么DUMP線程會實際的發送這些Event，但是SQL線程應用時候會根據GTID進行過濾，延遲可能出現很大的情況。

另外我們需要考慮一下purge binary logs會刪除binlog，為什么不會出現偏移量錯亂的問題呢，因為purge binary logs會實際的維護這個偏移量在函數adjust_linfo_offsets中調用Adjust_offset::operator()進行維護，代碼如下：

linfo->index_file_offset -= m_purge_offset;

五、實際測試

我們來測試 GTID_MODE 關閉，使用POSITION，主鍵沖突的情況。

1. 測試表和相關環境

mysql> show binary logs;
+---------------+-----------+
| Log_name      | File_size |
+---------------+-----------+
| binlog.000001 |       198 |
| binlog.000002 |       154 |
+---------------+-----------+
2 rows in set (0.00 sec)
mysql> show create table testcp \G;
*************************** 1. row ***************************
       Table: testcp
Create Table: CREATE TABLE `testcp` (
`id` int(11) NOT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)
ERROR:
No query specified

2. 執行一個語句

主庫：

mysql> insert into testcp values(20);
Query OK, 1 row affected (0.43 sec)
mysql> select * from testcp;
+----+
| id |
+----+
| 10 |
| 20 |
+----+
2 rows in set (0.01 sec)

從庫：

mysql> show slave status \G;
*************************** 1. row ***************************
...
              Master_Log_File: binlog.000002
          Read_Master_Log_Pos: 417
               Relay_Log_File: relay.000004
                Relay_Log_Pos: 624
        Relay_Master_Log_File: binlog.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
...
mysql> select * from testcp;
+----+
| id |
+----+
| 10 |
| 20 |
+----+

這個時候DUMP線程index file偏移指針如下，如下圖：

實戰演練：MySQL手動注冊binlog文件造成主從同步異常

3. 主庫執行purge binary logs

做之前拷貝原有binlog.000001為binlog.000001bak因為等會要拷貝回去

mysql> purge binary logs to 'binlog.000002';
Query OK, 0 rows affected (3.14 sec)
mysql> show binary logs;
+---------------+-----------+
| Log_name | File_size |
+---------------+-----------+
| binlog.000002 | 417 |
+---------------+-----------+
1 row in set (0.00 sec)

因為purge binary logs命令會維護偏移指針，這個時候DUMP線程的index file偏移指針如下，如下圖：

實戰演練：MySQL手動注冊binlog文件造成主從同步異常

4. 將備份binlog拷貝回去并且修改index file

將binlog.000001bak拷貝為binlog.000001，修改index file將binlog.000001加入回去，然后flush binary logs如下：

mysql> flush binary logs;
Query OK, 0 rows affected (0.15 sec)
mysql> show binary logs;
+---------------+-----------+
| Log_name      | File_size |
+---------------+-----------+
| binlog.000001 |         198 |
| binlog.000002 |       461 |
+---------------+-----------+
2 rows in set (0.00 sec)

手動完成這個工作并不會維護DUMP線程的index file偏移指針，如下圖：

實戰演練：MySQL手動注冊binlog文件造成主從同步異常

這個時候我們已經看到這個偏移指針已經錯亂了，接下來DUMP線程將再次發送binlog.000002。

5. 報錯觀察

就這樣DUMP線程重新發送了一次binlog.000002的內容，POSITION 模式的從庫只能報錯了如下，我們可以看到重復的行出現了，錯誤1062如下：

LAST_ERROR_MESSAGE: Worker 1 failed executing transaction 'ANONYMOUS' at master log binlog.000002,
end_log_pos 386; Could not execute Write_rows event on table testmts.testcp; Duplicate entry '20' for key
'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log
binlog.000002, end_log_pos 386

六、總結

我們可以看到這種操作非常不規范，如果實在要這么做考慮如下步驟：

關閉全部的從庫
手動注冊binlog文件，修改index 文件
flush binary logs
啟動從庫

這樣重新啟動從庫將重新初始化DUMP的index file偏移指針，應該是沒有問題的。但是應該還是要盡量避免此類操作，因為index file和binlog都是MySQL自己維護的。

原創：高鵬（八怪），現任易極付高級DBA，從事Oracle/MySQL相關工作10余年Oracle OCM 有豐富的數據庫性能調優故障診斷經驗，對MySQL源碼有一定研究。《深入理解MySQL主從原理》作者。請關注《深入MySQL主從原理32節》，地址：http://j.youzan.com/yEY_Xi 。

想了解更多關于數據庫、云技術的內容嗎？

快來關注“數據和云”公眾號、“云和恩墨”官方網站，我們期待與大家一同學習和進步！

實戰演練：MySQL手動注冊binlog文件造成主從同步異常