189 8069 5689

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复制配置不规范修改导致的坑（一）
URL分享：http://cdxtjz.cn/article/gpdjhj.html

其他资讯