实战演练：MySQL手动注册binlog文件造成主从同步异常

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

公司主营业务：成都做网站、成都网站建设、移动网站开发等业务。帮助企业客户真正实现互联网宣传，提高企业的竞争能力。成都创新互联是一支青春激扬、勤奋敬业、活力青春激扬、勤奋敬业、活力澎湃、和谐高效的团队。公司秉承以“开放、自由、严谨、自律”为核心的企业文化，感谢他们对我们的高要求，感谢他们从不同领域给我们带来的挑战，让我们激情的团队有机会用头脑与智慧不断的给客户带来惊喜。成都创新互联推出武陵免费做网站回馈大家。

导读：本文是作者用MySQL数据库手动注册binlog文件造成主从同步异常后，详述整个分析与解决的过程。

一、问题来源

因为某些需求，想将备份的binlog文件恢复到主库并且进行注册，在不关闭主从同步的情况下，他做了如下操作：

1. 将备份的一些binlog文件加入到了binlog日志目录文件中。
2. 修改index文件，加入了这些binlog文件。

做完这些操作后，主库确实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)

报错如下：

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.

从这个错误的位点来看，在主库flush binary logs后，视乎主库的DUMP线程又在重新发送老的mysql-binlog.000035这个binlog。报错是因为以前是GTID模式，但是测试的时候已经改为了POSITION模式，是主库DUMP线程在检测主库的GTID Event和从库的GTID模式是否兼容的时候报出来的，如下图

这个错误在这里并不重要，我们只需要知道老的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文件：

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进行过滤，延迟可能出现很大的情况。

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

主库：

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偏移指针如下，如下图：

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偏移指针如下，如下图：

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线程将再次发送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 。

想了解更多关于数据库、云技术的内容吗？

快来关注“数据和云”公众号、“云和恩墨”官方网站，我们期待与大家一同学习和进步！

（扫描上方二维码，关注“数据和云”公众号，即可查看更多科技文章）