墨墨导读:本文是作者用MySQL数据库手动注册binlog文件造成主从同步异常后,详述整个分析与解决的过程。
云和恩墨大讲堂线上分享:《weblogic 优化》
时间:2019年7月30日(星期二)20:30-21:30 立即报名:https://cs./event/57
一、问题来源
因为某些需求,想将备份的binlog文件恢复到主库并且进行注册,在不关闭主从同步的情况下,他做了如下操作:将备份的一些binlog文件加入到了binlog日志目录文件中。 修改index文件,加入了这些binlog文件。 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: 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模式是否兼容的时候报出来的,如下图 这个错误在这里并不重要,我们只需要知道老的binlog mysql-binlog.000035居然再次发送了。
三、flush binary logs对binlog的操作
flush binary logs 至少包含如下操作:
具体可以参考函数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偏移指针如下,如下图: 3. 主库执行purge binary logs做之前拷贝原有binlog.000001为binlog.000001bak因为等会要拷贝回去 mysql> purge binary logs to 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线程的index file偏移指针,如下图: 这个时候我们已经看到这个偏移指针已经错乱了,接下来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自己维护的。
|