MySQL5.7复制配置不规范修改导致的坑(一)

沃趣科技  罗小波

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 事务时报错)。。然后,发了一阵呆之后,想到了一些可能导致这个问题的原因,下文我们通过"复现与简单分析"、"重新复现、详细分析与验证"、"总结"三个步骤来对这个问题的前因后果进行一次透析,大家请跟随我往下看。
先列出硬件配置、操作系统和数据库环境信息

环境信息

主要从事网页设计、PC网站建设(电脑版网站建设)、wap网站建设(手机版网站建设)、成都响应式网站建设、程序开发、微网站、小程序制作等,凭借多年来在互联网的打拼,我们在互联网网站建设行业积累了丰富的成都网站制作、成都网站建设、网络营销经验,集策划、开发、设计、营销、管理等多方位专业化运作于一体,具备承接不同规模与类型的建设项目的能力。

操作系统: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
数据库配置关键参数:
  • * 主库:双一,log_slave_updates,log-bin,binlog_rows_query_log_events=ON,server-id=330614,slave_parallel_type=LOGICAL_CLOCK,enforce_gtid_consistency=ON,gtid_mode=on,innodb_buffer_pool_size=2G 
  • * 从库:双一,双TABLE,log_slave_updates,log-bin,binlog_rows_query_log_events=ON,server-id=330615,slave_parallel_type=LOGICAL_CLOCK,enforce_gtid_consistency=ON,gtid_mode=on,innodb_buffer_pool_size=2G,slave_parallel_workers=4
主机配置硬件配置:
  • * CPU:4 vcpus 
  • * 内存:8G 
  • * 磁盘:50G SSD 
  • * 网卡:Speed: 100Mb/s
IP:
  • * 主库:10.10.20.14 
  • * 从库:10.10.20.15
郑重声明:本文仅供学习交流,请勿在生产环境试车!!

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*/
  • 分析到这里,视乎也没辙了。等等,一定是遗漏了什么细节,我们先去官方翻一翻我们刚刚做的几个动作stop slave;change master to master_auto_postion=0;start slave;时,mysql server后台会做一些什么事情
  • 功夫不负有心人,翻到了如下关键说明,大意是说,在基于GTID复制模式下转换为基于文件复制协议时,可以使用change master to master_auto_position=0语句,并且要指定MASTER_LOG_FILE和MASTER_LOG_POS选项(经验证,如果不指定MASTER_LOG_FILE和MASTER_LOG_POS选项,则执行change master语句时,那么SQL线程位置以IO线程位置为准,如果指定了MASTER_LOG_FILE和MASTER_LOG_POS选项,则IO线程位置以SQL线程位置为准),在5.7.4版本之后,使用change master to …语句时,如果IO和SQL线程都处于停止状态,那么将会删除所有的relay log文件,除非你同时指定了RELAY_LOG_FILE和RELAY_LOG_POS选项(经验证,只要不指定RELAY_LOG_FILE和RELAY_LOG_POS选项就会删除当前所有的relay log,无论其他选项如何指定):
    MySQL 5.7复制配置不规范修改导致的坑(一)
  • 也就是说,我们使用change master 语句的时候,只使用master_auto_position选项而不指定MASTER_LOG_FILE和MASTER_LOG_POS选项本身就是一种不规范的行为,再加上没有指定RELAY_LOG_FILE和RELAY_LOG_POS选项,导致relay log被清理了,我们知道,在前面执行stop slave;语句时,我们可以看到还有复制延迟的(Seconds_Behind_Master: 47),也就是说,这部分复制延迟的relay log被清理可能就是导致worker线程发生错误的原因(缺失的GTID EVENT就记录在被清理的relay log中)

  • 现在,原因我们应该找到了,但是还需要进一步确认,但根据目前的犯罪现场,已经调查不下去了,我们需要把复制先恢复之后,重新复现并在每一个步骤查看尽可能全面的信息以进行诊断。

  • 要恢复复制环境,我们可以把master_auto_position设置为1,根据GTID复制协议,设置为1启动复制时,会根据公式"UNION(@@global.gtid_executed, Retrieved_gtid_set - last_received_GTID)"自动计算IO线程重新向主库请求binlog的GTID SET,告诉主库自己当前已经执行了哪些事务,主库会把从库缺失的事务发送给从库。所以理论上只需要把master_auto_position设置为1启动的复制就可以恢复正常。

    1. admin@localhost : sbtest 09:52:41> stop slave;
    2.     Query OK, 0 rows affected (0.00 sec)
    3.     admin@localhost : sbtest 09:52:47> change master to master_auto_position=1;
    4.     Query OK, 0 rows affected (0.02 sec)
    5.     admin@localhost : sbtest 09:53:01> start slave;
    6.     Query OK, 0 rows affected (0.02 sec)
    7.     admin@localhost : sbtest 09:53:11> 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: 127589755
    13.                    Relay_Log_File: mysql-relay-bin.000002
    14.                     Relay_Log_Pos: 849241
    15.             Relay_Master_Log_File: mysql-bin.000036
    16.                  Slave_IO_Running: Yes
    17.                 Slave_SQL_Running: Yes
    18.     ......
    19.               Exec_Master_Log_Pos: 102801341
    20.     ......
    21.             Seconds_Behind_Master: 3075
    22.     Master_SSL_Verify_Server_Cert: No
    23.                     Last_IO_Errno: 0
    24.                     Last_IO_Error:
    25.                    Last_SQL_Errno: 0
    26.                    Last_SQL_Error:
    27.     ......
    28.           Last_IO_Error_Timestamp:
    29.          Last_SQL_Error_Timestamp:
    30.     ......
    31.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:710876-741652
    32.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-711894
    33.                     Auto_Position: 1
    34.     ...
    35.     1 row in set (0.01 sec)


  • 从上面的结果中,我们可以看到,从库的复制恢复正常,现在,我们需要做的就是等待从库的SQL线程追上IO线程,然后使用pt工具做一次主从数据校验,从下面的结果中可以看到,测试库sbtest在主从库中数据一致,没有差异
    1. [root@luoxiaobo-01 ~]# pt-table-checksum --nocheck-replication-filters --no-check-binlog-format --replicate=xiaoboluo.checksums --databases sbtest h=localhost,u=admin,p=letsg0,P=3306
    2.     Checksumming sbtest.sbtest1: 57% 00:24 remain
    3.                 TS ERRORS DIFFS ROWS CHUNKS SKIPPED TIME TABLE
    4.     07-08T22:19:10 0 0 5007738 28 0 59.849 sbtest.sbtest1
    5.     Checksumming sbtest.sbtest2: 49% 00:30 remain
    6.     Checksumming sbtest.sbtest2: 97% 00:01 remain
    7.     07-08T22:20:17 0 0 5007905 27 0 67.127 sbtest.sbtest2
    8.     Checksumming sbtest.sbtest3: 52% 00:27 remain
    9.     07-08T22:21:23 0 0 5007858 28 0 65.440 sbtest.sbtest3
    10.     Checksumming sbtest.sbtest4: 48% 00:32 remain
    11.     Checksumming sbtest.sbtest4: 92% 00:04 remain
    12.     07-08T22:22:35 0 0 5007914 29 0 71.766 sbtest.sbtest4
    13.     Checksumming sbtest.sbtest5: 61% 00:19 remain
    14.     07-08T22:23:38 0 0 5007412 29 0 63.463 sbtest.sbtest5
    15.     Checksumming sbtest.sbtest6: 58% 00:21 remain
    16.     07-08T22:24:38 0 0 5007473 29 0 59.838 sbtest.sbtest6
    17.     Checksumming sbtest.sbtest7: 53% 00:27 remain
    18.     07-08T22:25:44 0 0 5007216 29 0 66.526 sbtest.sbtest7
    19.     Checksumming sbtest.sbtest8: 50% 00:29 remain
    20.     07-08T22:26:47 0 0 5007273 28 0 62.753 sbtest.sbtest8
    21.     '# 如果DIFFS列出现有不为0值时,就表示主备数据不一致,可以执行如下语句执行同步,同步之后再次执行pt-table-checksum校验直到DIFFS列不会出现0值为止'
    22.     pt-table-sync --replicate=xiaoboluo.checksums --databases sbtest h=localhost,u=admin,p=letsg0,P=3306 --execute
    • 为什么计算公式中会有一个减去last_received_GTID呢?根据官方文档描述,在5.7.5版本之前是不会减去last_received_GTID的,但在5.7.5之后会减去last_received_GTID,因为。。IO线程正在持续不断地读取主库binlog时,是以event为单位进行读取的,而一个事务包含了一个event组,所以突然执行stop slave或者其他异常行为时,可能导致一个事务只读取了部分event,如果不减去这个binlog读取不完整的GTID,有可能导致SQL线程复制报错终止。下图是官方对于这个计算公式的解释:
      MySQL 5.7复制配置不规范修改导致的坑(一)
  • 现在,我们来重现复现步骤吧


网页标题:MySQL5.7复制配置不规范修改导致的坑(一)
文章来源:http://scyanting.com/article/gpdjhj.html