實(shí)戰(zhàn)演練：MySQL手動(dòng)注冊(cè)binlog文件造成主從同步異常

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

公司主營(yíng)業(yè)務(wù)：成都做網(wǎng)站、成都網(wǎng)站建設(shè)、移動(dòng)網(wǎng)站開(kāi)發(fā)等業(yè)務(wù)。幫助企業(yè)客戶真正實(shí)現(xiàn)互聯(lián)網(wǎng)宣傳，提高企業(yè)的競(jìng)爭(zhēng)能力。成都創(chuàng)新互聯(lián)是一支青春激揚(yáng)、勤奮敬業(yè)、活力青春激揚(yáng)、勤奮敬業(yè)、活力澎湃、和諧高效的團(tuán)隊(duì)。公司秉承以“開(kāi)放、自由、嚴(yán)謹(jǐn)、自律”為核心的企業(yè)文化，感謝他們對(duì)我們的高要求，感謝他們從不同領(lǐng)域給我們帶來(lái)的挑戰(zhàn)，讓我們激情的團(tuán)隊(duì)有機(jī)會(huì)用頭腦與智慧不斷的給客戶帶來(lái)驚喜。成都創(chuàng)新互聯(lián)推出武陵免費(fèi)做網(wǎng)站回饋大家。

導(dǎo)讀：本文是作者用MySQL數(shù)據(jù)庫(kù)手動(dòng)注冊(cè)binlog文件造成主從同步異常后，詳述整個(gè)分析與解決的過(guò)程。

一、問(wèn)題來(lái)源

因?yàn)槟承┬枨螅雽浞莸腷inlog文件恢復(fù)到主庫(kù)并且進(jìn)行注冊(cè)，在不關(guān)閉主從同步的情況下，他做了如下操作：

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

做完這些操作后，主庫(kù)確實(shí)binlog注冊(cè)回來(lái)了， 但是整個(gè)主從環(huán)境大量延遲。

二、初次測(cè)試

測(cè)試操作如下：

1. 主庫(kù)操作，拷貝并且清理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. 主庫(kù)操作，將備份的binlog拷貝回原先的目錄并修改index文件進(jìn)行注冊(cè)

[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. 主庫(kù)操作，主庫(kù)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)

報(bào)錯(cuò)如下：

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.

從這個(gè)錯(cuò)誤的位點(diǎn)來(lái)看，在主庫(kù)flush binary logs后，視乎主庫(kù)的DUMP線程又在重新發(fā)送老的mysql-binlog.000035這個(gè)binlog。報(bào)錯(cuò)是因?yàn)橐郧笆荊TID模式，但是測(cè)試的時(shí)候已經(jīng)改為了POSITION模式，是主庫(kù)DUMP線程在檢測(cè)主庫(kù)的GTID Event和從庫(kù)的GTID模式是否兼容的時(shí)候報(bào)出來(lái)的，如下圖

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

三、flush binary logs對(duì)binlog的操作

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

• 獲取新的binlog文件名字
  

• 關(guān)閉舊的binlog
  

• 關(guān)閉index file
  

• 打開(kāi)index file
  

• 打開(kāi)新的binlog
  

• 將新的binlog加入到indexfile

• 根據(jù)參數(shù)expire_logs_days判斷是否需要進(jìn)行binlog刪除

具體可以參考函數(shù)MYSQL_BIN_LOG::new_file_impl。其中要說(shuō)明一下獲取新的binlog文件名字是通過(guò)函數(shù)find_uniq_filename實(shí)現(xiàn)的，其中包含如下代碼：

  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文件，獲取其序號(hào)最高的一個(gè)，然后加1。因此即便我們手動(dòng)修改了index file，flush binary logs不會(huì)有問(wèn)題，因?yàn)樗鼘?shí)際掃描了binlog文件。同時(shí)我們也看到flush binary logs重新加載了index file，這個(gè)時(shí)候手動(dòng)修改的index file就生效了，使用show binary logs就能查看到你手動(dòng)加入的文件了。

棧幀如下：

#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

四、主從問(wèn)題的產(chǎn)生

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

mysql_bin_log.find_next_log 包含的代碼：

  my_b_seek(&index_file, linfo->index_file_offset);//進(jìn)行偏移量偏移

  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線程并沒(méi)有實(shí)際掃描整個(gè)index文件，而是通過(guò)一個(gè)index文件的偏移量進(jìn)行讀取。如果手動(dòng)修改index文件那么這個(gè)偏移量就不會(huì)維護(hù)，DUMP發(fā)送的下一個(gè)文件將是不確定的，因此出現(xiàn)了發(fā)送手動(dòng)注冊(cè)的binlog文件給從庫(kù)的現(xiàn)象，根據(jù)主從設(shè)置的不同將會(huì)出現(xiàn)下面的情況：

• 如果是GTID_MODE 關(guān)閉，使用POSITION那么這種情況一定報(bào)錯(cuò)，比如重復(fù)的行，下面我們會(huì)測(cè)試這種情況。
  

• 如果是GTID_MODE 和AUTO_POSITION=1，那么DUMP線程會(huì)進(jìn)行GTID的過(guò)濾不發(fā)送，因?yàn)镋vent不發(fā)送所以延遲會(huì)持續(xù)一段時(shí)間為0。

• 如果是GTID_MODE 和AUTO_POSITION=0，那么DUMP線程會(huì)實(shí)際的發(fā)送這些Event，但是SQL線程應(yīng)用時(shí)候會(huì)根據(jù)GTID進(jìn)行過(guò)濾，延遲可能出現(xiàn)很大的情況。

linfo->index_file_offset -= m_purge_offset;

五、實(shí)際測(cè)試

我們來(lái)測(cè)試 GTID_MODE 關(guān)閉，使用POSITION，主鍵沖突的情況。

1. 測(cè)試表和相關(guān)環(huán)境

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

主庫(kù)：

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)

從庫(kù)：

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 |
+----+  

這個(gè)時(shí)候DUMP線程index file偏移指針如下，如下圖：

3. 主庫(kù)執(zhí)行purge binary logs

做之前拷貝原有binlog.000001為binlog.000001bak因?yàn)榈葧?huì)要拷貝回去

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)

因?yàn)閜urge binary logs命令會(huì)維護(hù)偏移指針，這個(gè)時(shí)候DUMP線程的index file偏移指針如下，如下圖：

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)

這個(gè)時(shí)候我們已經(jīng)看到這個(gè)偏移指針已經(jīng)錯(cuò)亂了，接下來(lái)DUMP線程將再次發(fā)送binlog.000002。

5. 報(bào)錯(cuò)觀察

就這樣DUMP線程重新發(fā)送了一次binlog.000002的內(nèi)容，POSITION 模式的從庫(kù)只能報(bào)錯(cuò)了如下，我們可以看到重復(fù)的行出現(xiàn)了，錯(cuò)誤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

六、總結(jié)

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

• 關(guān)閉全部的從庫(kù)
  

• 手動(dòng)注冊(cè)binlog文件，修改index 文件
  

• flush binary logs
  

• 啟動(dòng)從庫(kù)

這樣重新啟動(dòng)從庫(kù)將重新初始化DUMP的index file偏移指針，應(yīng)該是沒(méi)有問(wèn)題的。但是應(yīng)該還是要盡量避免此類操作，因?yàn)閕ndex file和binlog都是MySQL自己維護(hù)的。

原創(chuàng)：高鵬（八怪），現(xiàn)任易極付高級(jí)DBA，從事Oracle/MySQL相關(guān)工作10余年Oracle OCM 有豐富的數(shù)據(jù)庫(kù)性能調(diào)優(yōu)故障診斷經(jīng)驗(yàn)，對(duì)MySQL源碼有一定研究?！渡钊肜斫釳ySQL主從原理》作者。請(qǐng)關(guān)注《深入MySQL主從原理32節(jié)》，地址：http://j.youzan.com/yEY_Xi 。

想了解更多關(guān)于數(shù)據(jù)庫(kù)、云技術(shù)的內(nèi)容嗎？

快來(lái)關(guān)注“數(shù)據(jù)和云”公眾號(hào)、“云和恩墨”官方網(wǎng)站，我們期待與大家一同學(xué)習(xí)和進(jìn)步！

（掃描上方二維碼，關(guān)注“數(shù)據(jù)和云”公眾號(hào)，即可查看更多科技文章）

網(wǎng)站題目：實(shí)戰(zhàn)演練：MySQL手動(dòng)注冊(cè)binlog文件造成主從同步異常
網(wǎng)頁(yè)URL：http://bm7419.com/article24/gegjje.html

成都網(wǎng)站建設(shè)公司_創(chuàng)新互聯(lián)，為您提供Google、動(dòng)態(tài)網(wǎng)站、電子商務(wù)、App開(kāi)發(fā)、響應(yīng)式網(wǎng)站、定制網(wǎng)站

廣告

聲明：本網(wǎng)站發(fā)布的內(nèi)容（圖片、視頻和文字）以用戶投稿、用戶轉(zhuǎn)載內(nèi)容為主，如果涉及侵權(quán)請(qǐng)盡快告知，我們將會(huì)在第一時(shí)間刪除。文章觀點(diǎn)不代表本網(wǎng)站立場(chǎng)，如需處理請(qǐng)聯(lián)系客服。電話：028-86922220；郵箱：631063699@qq.com。內(nèi)容未經(jīng)允許不得轉(zhuǎn)載，或轉(zhuǎn)載時(shí)需注明來(lái)源： 創(chuàng)新互聯(lián)