MySQL 5.7复制配置不规范修改导致的坑(一)

发布时间:2020-08-15 16:09:44 作者:沃趣科技
来源:ITPUB博客 阅读:679
沃趣科技  罗小波

1、复现与简单分析
2、重新复现、详细分析与验证
2.1. 重新复现与详细分析
2.1.1. stop slave
2.1.2. change master to master_auto_position=0
2.1.3. start slave
2.2. 解决方法验证
3、总结
今天咱们同事说碰到一个古怪的问题,说MySQL 5.7.18上,主从复制结构中,从库在使用change master语句切换master_auto_position=1为0时,SQL线程报错了([ERROR] Slave SQL for channel '': Error '@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.' on query. Default database: 'sbtest'. Query: 'BEGIN', Error_code: 1782),然后,出于尝试修复,又改成了1,重新启动复制就恢复正常了,然后再改成0重新启动复制,这个时候发生数据丢失了,再反复切换几次之后,MySQL crash了。。,当时我听到这个问题的第一反应就是:一脸懵逼(因为1782错误通常是发生复制架构启用GTID复制之后,从库IO线程读取到主库的ANONYMOUS 事务时报错)。。然后,发了一阵呆之后,想到了一些可能导致这个问题的原因,下文我们通过"复现与简单分析"、"重新复现、详细分析与验证"、"总结"三个步骤来对这个问题的前因后果进行一次透析,大家请跟随我往下看。
先列出硬件配置、操作系统和数据库环境信息

环境信息

操作系统:CentOS Linux release 7.2.1511 (Core)
sysbench版本:sysbench-0.5-3.el6.x86_64
* 使用sysbench造数8张500W数据的表
percona-toolkit版本:percona-toolkit-3.0.3-1.el7.x86_64
percona-xtrabackup版本:percona-xtrabackup-24-2.4.4-1.el7.x86_64
数据库版本:MySQL 5.7.18
数据库配置关键参数: 主机配置硬件配置:
IP:
郑重声明:本文仅供学习交流,请勿在生产环境试车!!

1、复现与简单分析

首先,我们使用主库中造好数的备份,与从库搭建主从复制结构(sysbench造数和搭建主备复制步骤省略),从库初始搭建时使用master_auto_position=1启动复制
主库使用如下sysbench语句加压
    1. sysbench --test=oltp --db-driver=mysql --mysql-table-engine=innodb --mysql-socket=/home/mysql/data/mysqldata1/sock/mysql.sock --mysql-port=3306 --mysql-db=sbtest \
    2.     --mysql-user='qbench' --mysql-password='qbench' --test=/usr/share/doc/sysbench/tests/db/update_non_index.lua --oltp-table-size=5000000 --oltp-tables-count=4 --num-threads=8 --max-time=1800 \
    3.     --max-requests=0 --report-interval=1 run
现在,我们准备把从库切换master_auto_position=0
先在从库上执行一下show slave status\G;语句查看一下复制状态,从下面的结果中可以看到,一切正常
    1. admin@localhost : (none) 02:46:49> show slave status\G;
    2.     *************************** 1. row ***************************
    3.                    Slave_IO_State: Waiting for master to send event
    4.     ......
    5.                   Master_Log_File: mysql-bin.000036
    6.               Read_Master_Log_Pos: 119450512
    7.                    Relay_Log_File: mysql-relay-bin.000002
    8.                     Relay_Log_Pos: 9530766
    9.             Relay_Master_Log_File: mysql-bin.000036
    10.                  Slave_IO_Running: Yes
    11.                 Slave_SQL_Running: Yes
    12.     ......
    13.               Exec_Master_Log_Pos: 101635141
    14.     ......
    15.             Seconds_Behind_Master: 47
    16.     Master_SSL_Verify_Server_Cert: No
    17.                     Last_IO_Errno: 0
    18.                     Last_IO_Error:
    19.                    Last_SQL_Errno: 0
    20.                    Last_SQL_Error:
    21.     ......
    22.           Slave_SQL_Running_State: Waiting for slave workers to process their queues
    23.     ......
    24.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-731881
    25.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710502:710504
    26.                     Auto_Position: 1
    27.     ......
    28.     1 row in set (0.02 sec)
执行master_auto_position=0
  1. admin@localhost : sbtest 09:02:42> stop slave;
  2.     Query OK, 0 rows affected (0.08 sec)
  3.     admin@localhost : sbtest 09:02:45> change master to master_auto_position=0;
  4.     Query OK, 0 rows affected (0.06 sec)
  5.     admin@localhost : sbtest 09:02:53> start slave;
  6.     Query OK, 0 rows affected (0.03 sec)
  7.     admin@localhost : sbtest 09:02:56> show slave status\G;
  8.     *************************** 1. row ***************************
  9.                    Slave_IO_State: Waiting for master to send event
  10.     ......
  11.                   Master_Log_File: mysql-bin.000036
  12.               Read_Master_Log_Pos: 125448945
  13.                    Relay_Log_File: mysql-relay-bin.000002
  14.                     Relay_Log_Pos: 320
  15.             Relay_Master_Log_File: mysql-bin.000036
  16.                  Slave_IO_Running: Yes
  17.                 Slave_SQL_Running: No
  18.     ......
  19.               Exec_Master_Log_Pos: 120336889
  20.     ......
  21.             Seconds_Behind_Master: NULL
  22.     Master_SSL_Verify_Server_Cert: No
  23.                     Last_IO_Errno: 0
  24.                     Last_IO_Error:
  25.                    Last_SQL_Errno: 1782
  26.                    Last_SQL_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction 'NOT_YET_DETERMINED' at master log\
  27.      mysql-bin.000036, end_log_pos 120336968. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
  28.     ......
  29.           Last_IO_Error_Timestamp:
  30.          Last_SQL_Error_Timestamp: 170708 21:02:56
  31.     ......
  32.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947-739082
  33.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875
  34.                     Auto_Position: 0
  35.     ......
  36.     1 row in set (0.00 sec)
从上面的结果中可以看到,SQL线程报错了,从Last_SQL_Error字段显示的信息中我们可以得知,是某个workers线程报错了,让查询错误日志或者performance_schema.replication_applier_status_by_worker table表(为了防止备库继续落后于主库,现在,我们把sysbench先停止)
现在,我们来查询performance_schema.replication_applier_status_by_worker table表吧
  1. admin@localhost : sbtest 09:02:59> select * from performance_schema.replication_applier_status_by_worker where LAST_ERROR_MESSAGE != ''\G;
  2.     *************************** 1. row ***************************
  3.              CHANNEL_NAME:
  4.                 WORKER_ID: 1
  5.                 THREAD_ID: NULL
  6.             SERVICE_STATE: OFF
  7.     LAST_SEEN_TRANSACTION:
  8.         LAST_ERROR_NUMBER: 1782
  9.        LAST_ERROR_MESSAGE: Worker 1 failed executing transaction 'NOT_YET_DETERMINED' at master log mysql-bin.000036, end_log_pos 120336968; Error '@@SESSION.GTID_NEXT\
  10.      cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.' on query. Default database: 'sbtest'. Query: 'BEGIN'
  11.      LAST_ERROR_TIMESTAMP: 2017-07-08 21:02:56
  12.     1 row in set (0.00 sec)
发生什么了?主库的gtid_mode参数只有在设置为OFF和OFF_PERMISSIVE的时候,才会产生ANONYMOUS 事务并写入binlog中,而此时主库的gtid_mode配置参数是绝对没有人动过的,而且在执行上述操作之前,从库以GTID复制模式一直都工作得很正常,另外,通常这个错误是发生在IO线程读取主库的binlog时发生,SQL线程报这个错误还是头一次见。。尴尬。保险起见,还是到主库查看一下gtid_mode的值
  1. admin@localhost : sbtest 08:59:15> show variables like 'gtid_mode';
  2.     +---------------+-------+
  3.     | Variable_name | Value |
  4.     +---------------+-------+
  5.     | gtid_mode | ON |
  6.     +---------------+-------+
  7.     1 row in set (0.01 sec)
从上面的结果中可以看到,主库的gtid_mode参数并被修改过,既然SQL线程报了1782错误,那么我们就解析一下relay log,找到Exec_Master_Log_Pos: 120336889(协调器线程停止的位置)和worker线程报错的位置120336968(报错的worker线程停止的位置),到底是不是ANONYMOUS 事务(注意,这个pos是主库的binlog pos,不是relay log的pos,不能使用--start-position选项)
  1. '# 我们先查看一下relay log目录'
  2.     [root@luoxiaobo-02 relaylog]# ll
  3.     总用量 7092
  4.     -rw-r-----. 1 mysql mysql 247 7月 8 21:02 mysql-relay-bin.000001
  5.     -rw-r-----. 1 mysql mysql 7253186 7月 8 21:03 mysql-relay-bin.000002
  6.     -rw-r-----. 1 mysql mysql 120 7月 8 21:02 mysql-relay-bin.index
  7.     '# 发现有两个,解析最后一个relay log(第一个可能并不包含数据)并重定向到一个文件a.sql'
  8.     [root@luoxiaobo-02 relaylog]# mysqlbinlog -vv mysql-relay-bin.000002 > a.sql
  9.     '# vim打开这个文件,搜索120336968(这里只截取我们需要的部分内容)'
  10.     # at 123
  11.     #170708 21:02:56 server id 330615 end_log_pos 154 CRC32 0x6a8ed689 Previous-GTIDs
  12.     '# 纳尼。。这里居然是empty。。。'
  13.     # [empty]
  14.     # at 154
  15.     '# 这里是协调器线程报错时的Exec_Master_Log_Pos位置,然而,由于使用多线程复制,这个报错位置并不一定是workers线程真正触发报错的位置,我们需要查找 performance_schema.replication_applier_status_by_worker表'\
  16.     '# 中查询到的worker线程发生错误的位置,因为一旦有一个worker线程报错,会触发所有worker线程终止,协调器线程也会被终止'
  17.     #700101 8:00:00 server id 330614 end_log_pos 0 CRC32 0x122c770b Rotate to mysql-bin.000036 pos: 120336889
  18.     # at 201
  19.     '# 紧接着协调器线程停止的位置的event是relay log的FDE,说明协调器线程停止的位置并不是事务数据的event'
  20.     #170708 11:42:56 server id 330614 end_log_pos 0 CRC32 0x9433d36a Start: binlog v 4, server v 5.7.18-log created 170708 11:42:56
  21.     ......
  22.     # at 320
  23.     '# 这里就是就触发所有worker线程和协调器线程报错停止的位置,这里有啥好报错的?仔细一看,这个Query event前面原本应该还有一个记录一个GTID号的GTID event(开启GTID复制时,'\
  24.     '# 对于DML语句,如果row格式复制,那么在BEGIN语句前面一般都有用于记录GTID的GTID event,EVENT中记录的内容类似SET @@SESSION.GTID_NEXT= 'ec123678-5e26-11e7-9d38-000c295e08a0:34'/*!*/;,'\
  25.     '# 在5.7中,就算是使用传统复制模式, 这个地方也会有一个GTID event,EVENT中记录的内容类似:SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;),现在却缺失了!!!'
  26.     #170708 21:02:45 server id 330614 end_log_pos 120336968 CRC32 0x5a50ec65 Query thread_id=49 exec_time=0 error_code=0
  27.     SET TIMESTAMP=1499518965/*!*/;SET @@session.pseudo_thread_id=49/*!*/;
  28.     SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
  29.     SET @@session.sql_mode=1436549152/*!*/;
  30.     SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;
  31.     /*!\C latin1 *//*!*/;
  32.     SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=83/*!*/;
  33.     SET @@session.lc_time_names=0/*!*/;
  34.     SET @@session.collation_database=DEFAULT/*!*/;
  35.     BEGIN
  36.     /*!*/;
  37.     # at 399
  38.     #170708 21:02:45 server id 330614 end_log_pos 120337151 CRC32 0xfebefb51 Rows_query
  39.     # UPDATE sbtest2 SET c='65170974949-02872074133-35491912643-76037682303-52924518173-58373441038-15151348493-46026501347-34340253549-84073419150' WHERE id=2476460
  40.     # at 582
  41.     #170708 21:02:45 server id 330614 end_log_pos 120337210 CRC32 0x6c83af43 Table_map: `sbtest`.`sbtest2` mapped to number 121
  42.     # at 641
  43.     #170708 21:02:45 server id 330614 end_log_pos 120337626 CRC32 0xde840c87 Update_rows: table id 121 flags: STMT_END_F
  44.     BINLOG
从上面的信息中可以看到,Previous-GTIDs的event中原本应该记录一个GTID SET的内容(类似:b57c75c2-6205-11e7-8d9f-525400a4b2e1:337711-412882),现在却变成了" [empty]",而后续紧接着的日志中,Query event之前原本应该有个GTID event用于记录GTID SET的,现在却缺失了!!!神马情况?
既然relay log中记录的一个事务的binlog event组发生了丢失,那么我们就去主库的binlog中解析一把看看(解析 Relay_Master_Log_File: mysql-bin.000036,),从下面的信息中我们可以看到主库的binlog中120336968这个位置对应的事务完整的events组,其中GTID是"b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946"
  1. ......
  2.     # at 120336824
  3.     '# 这里就是缺失的GTID EVENT'
  4.     #170708 21:02:45 server id 330614 end_log_pos 120336889 CRC32 0x5d86abf6 GTID last_committed=144511 sequence_number=144517
  5.     '# 缺失的GTID号'
  6.     SET @@SESSION.GTID_NEXT= 'b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946'/*!*/;
  7.     # at 120336889
  8.     #170708 21:02:45 server id 330614 end_log_pos 120336968 CRC32 0x5a50ec65 Query thread_id=49 exec_time=0 error_code=0
  9.     SET TIMESTAMP=1499518965/*!*/;
  10.     BEGIN
  11.     /*!*/;
  12.     # at 120336968
  13.     #170708 21:02:45 server id 330614 end_log_pos 120337151 CRC32 0xfebefb51 Rows_query
  14.     # UPDATE sbtest2 SET c='65170974949-02872074133-35491912643-76037682303-52924518173-58373441038-15151348493-46026501347-34340253549-84073419150' WHERE id=2476460
  15.     # at 120337151
  16.     #170708 21:02:45 server id 330614 end_log_pos 120337210 CRC32 0x6c83af43 Table_map: `sbtest`.`sbtest2` mapped to number 121
  17.     # at 120337210
  18.     #170708 21:02:45 server id 330614 end_log_pos 120337626 CRC32 0xde840c87 Update_rows: table id 121 flags: STMT_END_F
  19.     BINLOG
冷静分析一下,从库中的relay log为什么缺失了?等等,在回头看看执行操作前后的show slave status信息,发现stop slave;change master to master_auto_position=0;start slave;之后的GTID相关信息的差异如下:
  1. '# 执行切换之前:'
  2.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-731881
  3.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710502:710504
  4.     '# 执行切换之后:'
  5.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947-739082
  6.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875
  7.     '# 再看一下从库的show master status信息'
  8.     admin@localhost : sbtest 09:05:36> show master status;
  9.     +------------------+----------+--------------+------------------+-----------------------------------------------+
  10.     | File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
  11.     +------------------+----------+--------------+------------------+-----------------------------------------------+
  12.     | mysql-bin.000001 | 9717837 | | | b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875 |
  13.     +------------------+----------+--------------+------------------+-----------------------------------------------+
  14.     1 row in set (0.00 sec)
有问题!!我只是操作stop slave;change master to master_auto_position=0;start slave; 然而现在从我们能够看到的信息中有如下蹊跷的地方:两次show slave status输出信息中Retrieved_Gtid_Set的值完全没有交集,前者GTID事务号是699054-731881,后者是732947-739082
Retrieved_Gtid_Set中最小的GTID比Executed_Gtid_Set最大的GTID还大22072个事务号
通过前面查看从库的relay log中,报错的位置事务GTID事务号是b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946,正好+1之后正好是报错时show slave status的Retrieved_Gtid_Set起始值,也就是说:就是由于这个事务(732946)的GTID EVENT缺失,同时由于relay log切换时,记录GTID SET的Previous-GTIDs event记录是[empty],所以Retrieved_Gtid_Set最终计算起始值就从下一个事务,也就是 b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947开始计算了,那缺失的日志去哪里了?
我们解析一下mysql-relay-bin.000001,从下面的结果中可以看到,这个relay log中没有任何数据相关的内容。那丢失的日志去哪里了?
  1. [root@luoxiaobo-02 relaylog]# mysqlbinlog -vv mysql-relay-bin.000001
  2.     mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'
  3.     /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
  4.     /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
  5.     DELIMITER /*!*/;
  6.     # at 4
  7.     #170708 21:02:53 server id 330615 end_log_pos 123 CRC32 0xc16fd9be Start: binlog v 4, server v 5.7.18-log created 170708 21:02:53 at startup
  8.     # This Format_description_event appears in a relay log and was generated by the slave thread.
  9.     # at 123
  10.     #170708 21:02:53 server id 330615 end_log_pos 194 CRC32 0xd425b7a8 Previous-GTIDs
  11.     # b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-732945
  12.     # at 194
  13.     #170708 21:02:56 server id 330615 end_log_pos 247 CRC32 0x43311780 Rotate to mysql-relay-bin.000002 pos: 4
  14.     SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
  15.     DELIMITER ;
  16.     # End of log file
  17.     /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
  18.     /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/
推荐阅读:
  1. linux安装mysql 5.7
  2. MySQL5.7中sql_mode默认值会带来什么问题

免责声明:本站发布的内容(图片、视频和文字)以原创、转载和分享为主,文章观点不代表本网站立场,如果涉及侵权请联系站长邮箱:is@yisu.com进行举报,并提供相关证据,一经查实,将立刻删除涉嫌侵权内容。

mysql 修改 规范

上一篇:帝国CMS实现提交评论后自动重新生成内容页

下一篇:帝国CMS整合Discuz的方法

相关阅读

您好,登录后才能下订单哦!

密码登录
登录注册
其他方式登录
点击 登录注册 即表示同意《亿速云用户服务条款》