MySQL 手动注册binlog文件造成主从同步异常

雨点打透心脏的1/2处 2024-04-17 05:27 25阅读 0赞

**导读**

> 作者：**高鹏（重庆八怪）**
> 
> 对MySQL源码有一定的研究
> 
> 著有《深入理解MySQL主从原理》知识专栏

**想阅读更多内容请点击订阅专栏**

![640?wx\_fmt=png][640_wx_fmt_png]

**提示：****本文建议横屏观看，效果更佳**

--------------------

### 一、问题来源    ###

我的一个朋友因为某些需求，想将备份的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。

##### 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模式，这个报错在我**《深入MySQL主从原理 32节》**的第17节会看到这个错误是主库DUMP线程在检测主库的GTID Event和从库的GTID模式是否兼容的时候报出来的，如下，图1：![640?wx\_fmt=png][640_wx_fmt_png 1]

这个错误在这里并不重要，我们要弄明白老的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
    #1  0x000000000187d208 in generate_new_log_name
    #2  0x0000000001884fdb in MYSQL_BIN_LOG::new_file_impl
    #3  0x0000000001884cbb in MYSQL_BIN_LOG::new_file_without_locking
    #4  0x0000000001886b6b in MYSQL_BIN_LOG::rotate
    #5  0x0000000001886d53 in MYSQL_BIN_LOG::rotate_and_purge

### 四、主从问题的产生 ###

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线程并没有实际扫描binlog目录下的binlog文件，而是通过一个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进行过滤，延迟可能出现很大的情况。

关于各种模式对DUMP、IO、SQL线程的影响和延迟的计算方法我已经在我的**《深入MySQL主从原理 32节》**系列中进行了详细的描述，可以关注一下。

另外我们需要考虑一下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偏移指针如下，图2：![640?wx\_fmt=png][640_wx_fmt_png 2]

##### 3、主库执行purge binary logs #####

做之前拷贝原有binlog.000001为binlog.000001bak因为等会要拷贝回去

因为purge binary logs命令会维护偏移指针，这个时候DUMP线程的index file偏移指针如下，图3：![640?wx\_fmt=png][640_wx_fmt_png 3]

##### 4、将备份binlog拷贝回去并且修改index file #####

将binlog.000001bak拷贝为binlog.000001，修改index file将binlog.000001加入回去，然后flush binary logs如下：

手动完成这个工作并不会维护DUMP线程的index file偏移指针，因此如下，图4：![640?wx\_fmt=png][640_wx_fmt_png 4]

**这个时候我们已经看到这个偏移指针已经错乱了，接下来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自己维护的。

**识别下方二维码添加作者为好友**

![640?wx\_fmt=png][640_wx_fmt_png 5]

END

--------------------

**点击下图小程序订阅**

**《深入理解MySQL主从原理32讲》专栏**

**可了解更多八怪技术文章**

![640?wx\_fmt=png][640_wx_fmt_png]

***![640?wx\_fmt=png][640_wx_fmt_png 6]***

![640?wx\_fmt=gif][640_wx_fmt_gif]

扫码加入MySQL技术Q群

**（群号：****650149401）**

![640?wx\_fmt=jpeg][640_wx_fmt_jpeg]

[640_wx_fmt_png]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/9ad553af1ea54552a63b57670d830eb6.png
[640_wx_fmt_png 1]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/155fb675b66349a7984de6dda032ec9f.png
[640_wx_fmt_png 2]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/d473b42f4e084814bda2967c0862d89d.png
[640_wx_fmt_png 3]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/6e57ae373e214affa0aa552610b75e1d.png
[640_wx_fmt_png 4]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/f52ea0473a2249f5a1ef7d4a8c771abb.png
[640_wx_fmt_png 5]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/af06a881dac6456d95b415e31f6f2a33.png
[640_wx_fmt_png 6]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/32b517e44d6d43a6936bf314a21f72a3.png
[640_wx_fmt_gif]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/a4aab839419f4f68a44ea7219dfabbc4.gif
[640_wx_fmt_jpeg]: https://image.dandelioncloud.cn/pgy_files/images/2024/04/11/ebeb5b5002064ff89b23e52dcc92ee22.png