墨墨导读：本文是作者用MySQL数据库手动注册binlog文件造成主从同步异常后，详述整个分析与解决的过程。
云和恩墨大讲堂线上分享：《weblogic 优化》
时间：7月30日（星期二）20:30-21:30
立即报名：/event/57
一、问题来源
因为某些需求，想将备份的binlog文件恢复到主库并且进行注册，在不关闭主从同步的情况下，他做了如下操作：
将备份的一些binlog文件加入到了binlog日志目录文件中。
修改index文件，加入了这些binlog文件。
flush binary logs注册文件。
做完这些操作后，主库确实binlog注册回来了， 但是整个主从环境大量延迟。
二、初次测试
测试操作如下：
1. 主库操作，拷贝并且清理binlog
(root:db1@xucl:10:30:22)[(none)]>showbinarylogs;
+---------------------+-----------+
|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|
+---------------------+-----------+
12rowsinset(0.00sec)
拷贝需要清理的binlog到备份目录，即binlog 35、36、37、38。
(root:db1@xucl:10:30:34)[(none)]>purgebinarylogsto"mysql-binlog.000039";
QueryOK,0rowsaffected(0.00sec)
(root:db1@xucl:10:30:49)[(none)]>showbinarylogs;
+---------------------+-----------+
|Log_name|File_size|
+---------------------+-----------+
|mysql-binlog.000039|284|
|mysql-binlog.000040|284|
|mysql-binlog.000041|284|
|mysql-binlog.000042|234|
+---------------------+-----------+
4rowsinset(0.00sec)
2. 主库操作，将备份的binlog拷贝回原先的目录并修改index文件进行注册
[root@izbp12nspj47ypto9t6vyezlogs]#ll
-rw-r-----1mysqlmysql21345月:03mysql-binlog.000035
-rw-r-----1mysqlmysql8459155月:03mysql-binlog.000036
-rw-r-----1mysqlmysql117355月:05mysql-binlog.000037
-rw-r-----1mysqlmysql2845月:06mysql-binlog.000038
-rw-r-----1mysqlmysql2845月2110:28mysql-binlog.000039
-rw-r-----1mysqlmysql2845月2110:28mysql-binlog.000040
-rw-r-----1mysqlmysql2845月2110:28mysql-binlog.000041
-rw-r-----1mysqlmysql4915月2110:31mysql-binlog.000042
-rw-r-----1mysqlmysql2045月2110:30mysql-binlog.index
3. 主库操作，主库flush binary logs
(root:db1@xucl:10:32:51)[(none)]>flushbinarylogs;
QueryOK,0rowsaffected(0.01sec)
(root:db1@xucl:10:32:57)[(none)]>showbinarylogs;
+---------------------+-----------+
|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|
+---------------------+-----------+
13rowsinset(0.00sec)
4. 此时，从库操作，show slave status
报错如下：
Last_IO_Error:Gotfatalerror1236frommasterwhenreadingdatafrombinarylog:"CannotreplicateGTID-
transactionwhen@@GLOBAL.GTID_MODE=OFF,atfile/storage/single/mysql3306/logs/mysql-binlog.000035,position194.
5. 错误观察
从这个错误的位点来看，在主库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就能查看到你手动加入的文件了。
栈帧如下：
#0find_uniq_filename(name=0x7fffec5ec6d0"/mysqldata/mysql3340/log/binlog",next=0x7fffec5ec678,need_next=true)
at/mysqldata/percona-server-locks-detail-5.7.22/sql/:3679
#10x000000000187d208ingenerate_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/:3767
#20x0000000001884fdbinMYSQL_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/:7175
#30x0000000001884cbbinMYSQL_BIN_LOG::new_file_without_locking(this=0x2e83640,extra_description_event=0x0)
at/mysqldata/percona-server-locks-detail-5.7.22/sql/:7099
#40x0000000001886b6binMYSQL_BIN_LOG::rotate(this=0x2e83640,force_rotate=true,check_purge=0x7fffec5ecbfb)
at/mysqldata/percona-server-locks-detail-5.7.22/sql/:7775
#50x0000000001886d53inMYSQL_BIN_LOG::rotate_and_purge(this=0x2e83640,thd=0x7ffedc000b90,force_rotate=true)
at/mysqldata/percona-server-locks-detail-5.7.22/sql/:7846
四、主从问题的产生
binlog切换后，DUMP线程也需要读取下一个binlog文件，但是它获取的过程和flush binary logs完全不同。在函数Binlog_sender::run中可以找到循环每个binlog文件的代码。下面一句是寻找下一个binlog文件：
interror=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>showbinarylogs;
+---------------+-----------+
|Log_name|File_size|
+---------------+-----------+
|binlog.000001|198|
|binlog.000002|154|
+---------------+-----------+
2rowsinset(0.00sec)
mysql>showcreatetabletestcp\G;
***************************1.row***************************
Table:testcp
CreateTable:CREATETABLE`testcp`(
`id`int(11)NOTNULL,
PRIMARYKEY(`id`)
)ENGINE=InnoDBDEFAULTCHARSET=utf8
1rowinset(0.00sec)
ERROR:
Noqueryspecified
2. 执行一个语句
主库：
mysql>insertintotestcpvalues(20);
QueryOK,1rowaffected(0.43sec)
mysql>select*fromtestcp;
+----+
|id|
+----+
|10|
|20|
+----+
2rowsinset(0.01sec)
从库：
mysql>showslavestatus\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*fromtestcp;
+----+
|id|
+----+
|10|
|20|
+----+
这个时候DUMP线程index file偏移指针如下，如下图：
3.主库执行purge binary logs
做之前拷贝原有binlog.000001为binlog.000001bak因为等会要拷贝回去
mysql>purgebinarylogsto"binlog.000002";
QueryOK,0rowsaffected(3.14sec)
mysql>showbinarylogs;
+---------------+-----------+
|Log_name|File_size|
+---------------+-----------+
|binlog.000002|417|
+---------------+-----------+
1rowinset(0.00sec)
因为purge binary logs命令会维护偏移指针，这个时候DUMP线程的index file偏移指针如下，如下图：
4. 将备份binlog拷贝回去并且修改index file
将binlog.000001bak拷贝为binlog.000001，修改index file将binlog.000001加入回去，然后flush binary logs如下：
mysql>flushbinarylogs;
QueryOK,0rowsaffected(0.15sec)
mysql>showbinarylogs;
+---------------+-----------+
|Log_name|File_size|
+---------------+-----------+
|binlog.000001|198|
|binlog.000002|461|
+---------------+-----------+
2rowsinset(0.00sec)
手动完成这个工作并不会维护DUMP线程的index file偏移指针，如下图：
这个时候我们已经看到这个偏移指针已经错乱了，接下来DUMP线程将再次发送binlog.000002。
5. 报错观察
就这样DUMP线程重新发送了一次binlog.000002的内容，POSITION 模式的从库只能报错了如下，我们可以看到重复的行出现了，错误1062如下：
LAST_ERROR_MESSAGE:Worker1failedexecutingtransaction"ANONYMOUS"atmasterlogbinlog.000002,
end_log_pos386;CouldnotexecuteWrite_rowseventontabletestmts.testcp;Duplicateentry"20"forkey
"PRIMARY",Error_code:1062;handlererrorHA_ERR_FOUND_DUPP_KEY;theevent"smasterlog
binlog.000002,end_log_pos386
六、总结
我们可以看到这种操作非常不规范，如果实在要这么做考虑如下步骤：
关闭全部的从库
手动注册binlog文件，修改index 文件
flush binary logs
启动从库
这样重新启动从库将重新初始化DUMP的index file偏移指针，应该是没有问题的。但是应该还是要尽量避免此类操作，因为index file和binlog都是MySQL自己维护的。
