欢迎您访问程序员文章站本站旨在为大家提供分享程序员计算机编程知识!
您现在的位置是: 首页  >  IT编程

MySQL手动注册binlog文件造成主从异常的原因

程序员文章站 2022-03-07 19:05:42
一、问题来源有一个朋友@水米田 问我,基于position的主从。他做了如下的操作将备份的一些binlog文件加入到了目录中修改index文件,加入了这些binlog文件flush binary lo...

一、问题来源

有一个朋友@水米田 问我,基于position的主从。他做了如下的操作

将备份的一些binlog文件加入到了目录中
修改index文件,加入了这些binlog文件
flush binary logs
然后整个主从环境大量延迟。

二、朋友的测试

下面是另外一个朋友@徐晨亮的测试:

master上:
(root:db1@xucl:10:30:22)[(none)]> show binary logs;
+---------------------+-----------+
| log_name      | file_size |
+---------------------+-----------+
| mysql-binlog.000031 |   1019 |
| mysql-binlog.000032 |    424 |
| mysql-binlog.000033 |    244 |
| mysql-binlog.000034 |   2332 |
| 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)
(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)
执行插入数据
(root:db1@xucl:10:31:23)[xucl]> insert into t values(9,9);
将备份的binlog拷贝回原先的目录并修改index文件进行注册
[root@izbp12nspj47ypto9t6vyez logs]# ll
总用量 884
-rw-r----- 1 mysql mysql  1019 5月 20 22:03 mysql-binlog.000031
-rw-r----- 1 mysql mysql  424 5月 20 22:03 mysql-binlog.000032
-rw-r----- 1 mysql mysql  244 5月 20 22:03 mysql-binlog.000033
-rw-r----- 1 mysql mysql  2332 5月 20 22:03 mysql-binlog.000034
-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
主库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.000031 |   1019 |
| mysql-binlog.000032 |    424 |
| mysql-binlog.000033 |    244 |
| mysql-binlog.000034 |   2332 |
| 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)
此时,slave报错如下:
(root:db1@xucl:10:31:05)[(none)]> show slave status\g
*************************** 1. row ***************************
        slave_io_state:
         master_host: 127.0.0.1
         master_user: repl
         master_port: 3306
        connect_retry: 60
       master_log_file: mysql-binlog.000035
     read_master_log_pos: 194
        relay_log_file: izbp12nspj47ypto9t6vyez-relay-bin.000011
        relay_log_pos: 373
    relay_master_log_file: mysql-binlog.000035
       slave_io_running: no
      slave_sql_running: yes
       replicate_do_db:
     replicate_ignore_db:
      replicate_do_table:
    replicate_ignore_table:
   replicate_wild_do_table:
 replicate_wild_ignore_table:
          last_errno: 0
          last_error:
         skip_counter: 0
     exec_master_log_pos: 194
       relay_log_space: 648
       until_condition: none
        until_log_file:
        until_log_pos: 0
      master_ssl_allowed: no
      master_ssl_ca_file:
      master_ssl_ca_path:
       master_ssl_cert:
      master_ssl_cipher:
        master_ssl_key:
    seconds_behind_master: null
master_ssl_verify_server_cert: no
        last_io_errno: 1236
        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.; the first event 'mysql-binlog.000039' at 234, the last event read from '/storage/single/mysql3306/logs/mysql-binlog.000035' at 259, the last byte read from '/storage/single/mysql33'
        last_sql_errno: 0
        last_sql_error:
 replicate_ignore_server_ids:
       master_server_id: 3306
         master_uuid: e8bdf01a-c79b-11e8-82b3-00163e088352
       master_info_file: mysql.slave_master_info
          sql_delay: 0
     sql_remaining_delay: null
   slave_sql_running_state: slave has read all relay log; waiting for more updates
      master_retry_count: 86400
         master_bind:
   last_io_error_timestamp: 190521 10:32:57
   last_sql_error_timestamp:
        master_ssl_crl:
      master_ssl_crlpath:
      retrieved_gtid_set:
      executed_gtid_set: 4c423515-6661-11e9-b767-00163e088352:1-7,
e8bdf01a-c79b-11e8-82b3-00163e088352:1-57192
        auto_position: 0
     replicate_rewrite_db:
         channel_name:
      master_tls_version:
1 row in set (0.00 sec)
从slave上的报错来看,在主库flush binary logs后,从库又读取注册的binlog并且又apply了

三、现象说明

从整个测试来看,mysql视乎将手动注册的文件进行了传输和应用。报错是因为这个库以前是gitd_mode=on的,但是测试的时候已经关闭了gtid_mode,改为了position的模式,这个报错是因为dump线程会进行检测:

MySQL手动注册binlog文件造成主从异常的原因

这个图来自我新写的一个系列(暂时还没发布,大概年底才能写好)。不管怎么说,dump线程已经在开始传输老的binlog文件了。那么原因是什么呢?下面我们将进行解释。

四、flush binary logs对binlog的操作

flush binary logs 将包含如下操作:

  • 获取新的binlog文件名字
  • 关闭旧的binlog
  • 关闭index file
  • 打开index file
  • 打开新的binlog
  • 将新的binlog加入到indexfile

具体可以参考函数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;

大概意思就是扫描index file文件里面的binlog文件,获取其序号最高的一个,然后加1。栈帧如下:

#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

因此即便我们手动修改了index file,flush binary logs却不会有问题,因为它实际扫描了index file文件。
同时我们也看到flush binary logs重新加载了index file,这个时候手动修改的index file就生效了,使用show binary logs就能查看到你加入的文件了。

五、主从问题的产生

binlog切换后,dump线程也需要读取下一个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文件给从库的现象,这种情况下可能出现下面情况:

  1. 如果是gtid_mode 关闭,使用position那么这种情况一定报错,比如重复的行。
  2. 如果是gtid_mode 和auto_position=1,那么dump线程会进行gtid的过滤不发送,因为event不发送所以延迟会持续一段时间为0。
  3. 如果是gtid_mode 和auto_position=0,那么sql线程应用gitd_event的时候会进行过滤,延迟可能出现很大的情况。

尽管gtid可能可以屏蔽这种问题,但是dump线程已经在考虑发送老的binlog文件了,这是不合适的。

六、purge binary logs能够维护这个偏移量

为什么purge binary logs不会出现问题呢,因为在purge binary logs的语句下,会维护这个偏移量如下:

 virtual void operator()(thd *thd)
 {
  log_info* linfo;
  mysql_mutex_lock(&thd->lock_thd_data);
  if ((linfo= thd->current_linfo))//b binlog.cc:2829
  {
   /*
    index file offset can be less that purge offset only if
    we just started reading the index file. in that case
    we have nothing to adjust.
   */
   if (linfo->index_file_offset < m_purge_offset)
    linfo->fatal = (linfo->index_file_offset != 0);
   else
    linfo->index_file_offset -= m_purge_offset;
  }
  mysql_mutex_unlock(&thd->lock_thd_data);

我们可以看到linfo->index_file_offset -= m_purge_offset;这样一个语句。下面是栈帧:

#0 adjust_offset::operator() (this=0x7fffec5ec720, thd=0x7ffedc000be0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:2831
#1 0x0000000000eef320 in do_thd::operator() (this=0x7fffec5ec6a0, thd=0x7ffedc000be0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/mysqld_thd_manager.cc:46
#2 0x0000000000eefa0f in std::for_each<thd**, do_thd> (__first=0x3003358, __last=0x3003368, __f=...)
  at /usr/lib/gcc/x86_64-redhat-linux/4.4.7/../../../../include/c++/4.4.7/bits/stl_algo.h:4200
#3 0x0000000000eeefc0 in global_thd_manager::do_for_all_thd (this=0x3003340, func=0x7fffec5ec720)
  at /mysqldata/percona-server-locks-detail-5.7.22/sql/mysqld_thd_manager.cc:273
#4 0x000000000187ae0a in adjust_linfo_offsets (purge_offset=0) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:2873
#5 0x0000000001883239 in mysql_bin_log::remove_logs_from_index (this=0x2e83640, log_info=0x7fffec5ec7d0, need_update_threads=true)
  at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:6352
#6 0x0000000001883676 in mysql_bin_log::purge_logs (this=0x2e83640, to_log=0x7fffec5eca80 "/mysqldata/mysql3340/log/binlog.000001", included=false, 
  need_lock_index=true, need_update_threads=true, decrease_log_space=0x0, auto_purge=false) at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:6469
#7 0x000000000187b4b5 in purge_master_logs (thd=0x7ffee0000c00, to_log=0x7ffee0006600 "binlog.000001")
  at /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3127

七、测试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 ***************************
        slave_io_state: waiting for master to send event
         master_host: 192.168.99.41
         master_user: repl
         master_port: 3340
        connect_retry: 60
       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偏移指针如下:

MySQL手动注册binlog文件造成主从异常的原因

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偏移指针如下:

MySQL手动注册binlog文件造成主从异常的原因

4、手动更改

将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偏移指针,因此如下:

MySQL手动注册binlog文件造成主从异常的原因

就这样dump线程重新发送了一次binlog.000002的内容,position的从库只能报错了如下:

mysql> select * from replication_applier_status_by_worker \g
*************************** 1. row ***************************
     channel_name: 
      worker_id: 1
      thread_id: null
    service_state: off
last_seen_transaction: anonymous
  last_error_number: 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
 last_error_timestamp: 2019-05-21 14:46:26

八、总结

这种操作非常不规范,如果实在要这么做考虑如下步骤:

  • 关闭全部的从库
  • 手动注册binlog文件,修改index 文件
  • flush binary logs
  • 启动从库

这种情况下将会重新初始化dump的偏移量指针,应该是没有问题的。还是尽量不要考虑这么做。

以上就是mysql手动注册binlog文件造成主从异常的原因的详细内容,更多关于mysql 主从异常的资料请关注其它相关文章!