复制作为 MySQL 原生的数据同步功能，在 MySQL 高可用架构中起着至关重要的作用。本文梳理了在运维本公司 MySQL 高可用产品 UDB 的过程中遇到的复制问题，并总结了当复制发生异常时，排查复制异常的方法。
查看主库 binlog 日志
查看主库的 binlog 日志文件列表，可能会发现主库的 binlog 变成重新开始记录：
-rw-r----- 1 songlei.wang songlei.wang 449 Apr 18 17:01 binlog001.000001-rw-r----- 1 songlei.wang songlei.wang 19 Apr 18 17:01 binlog_index001.index
复制代码
或者需要复制的 binlog 已经被删除:
-rw-r----- 1 songlei.wang songlei.wang 241 Apr 18 17:12 binlog001.000006-rw-r----- 1 songlei.wang songlei.wang 1716 Apr 18 17:12 binlog001.000007-rw-r----- 1 songlei.wang songlei.wang 194 Apr 18 17:12 binlog001.000008-rw-r----- 1 songlei.wang songlei.wang 57 Apr 18 17:12 binlog_index001.index
复制代码
如果 binlog 重新开始记录，通常是由于主库执行了 resetmaster 命令，导致所有的 binlog 被删除;如果 binlog 任然在继续记录，只是从库需要的 binlog 被删除，通常是由于主库手动执行了 purge binary logs 命令，或者日志的保留时间超过了 expire_logs_days 设置的时间。
03 从库没有执行主库复制的语句(mysql-5.6)
由于 GTID 的特性，SQL 线程不会去执行相同的 GTID 对应的事务，即如果 SQL 线程发现从 relay log 中读取到的事务对应的 GTID 已经存在于从库的 GTID_EXECUTED 中，那么 SQL 线程便不会存在。
1. 错误原因
复制过程中，用于主库执行的事务对应的 GTID 已经存在于从库的 GTID_EXECUTED 中，那么从库便不会执行这些事务，从而导致主库和从库的数据不一致。通常有如下情况：
主机执行了 reset master（从库当前读取主机的第一个 binlog，并不会因为 reset master 而导致找不到文件）;重做主从，从库没有清除从库的 binlog。
2.错误信息
在从库忽略主机执行的事务的过程中，从库复制不会报出任何错误，所以这种复制的异常容易被忽略，没有办法及时的发现。
由于主库和从库的数据库不一致，后续的 DML 和 DDL 操作可能会发生执行失败的错误。
3.原因分析过程
这里我们以插入语句找不到对应的表为例。
查看 error log
Error log 中记录错误信息:
2017-04-18 20:39:01 682 [ERROR] Slave SQL: Error 'Table 'mydb.mytbl2' doesn't exist' on query. Default database: 'mydb'. Query: 'insert into mydb.mytbl4 values (1)', Error_code: 1146
复制代码
查看 show slave status
show slave status 显示的信息全部正常，无从库执行事务的 binlog 产生。这里不排除从库关闭 binlog 执行 drop table 操作的可能。
查看表
分别在主机和从库执行命令 show create table mydb.mytbl4，发现从库上并未不存在 mydb.mytbl4。
解析 binlog 日志
解析主机 binlog 日志，查看建表的事务日志：
#170418 20:50:47 server id 30061 end_log_pos 199 CRC32 0xaaa00818 GTID [commit=yes]SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;# at 199#170418 20:50:47 server id 30061 end_log_pos 319 CRC32 0x06f5789f Query thread_id=3 exec_time=0 error_code=0……create table if not exists mydb.mytbl4 (A int)
复制代码
解析从库的 binlog 日志，查找是否存在建表的事务日志:
#170418 20:49:49 server id 30061 end_log_pos 199 CRC32 0x3051fade GTID [commit=yes]SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;# at 199#170418 20:49:49 server id 30061 end_log_pos 278 CRC32 0x7156a1c9 Query thread_id=3 exec_time=40 error_code=0……BEGIN/*!*/;# at 278#170418 20:49:49 server id 30061 end_log_pos 385 CRC32 0x25560e04 Query thread_id=3 exec_time=40 error_code=0use `mydb`/*!*/;SET TIMESTAMP=1492519789/*!*/;insert into mydb.mytbl values (1)/*!*/;……
复制代码
这时我们发现对于相同的 GTID，从库和主机执行的语句是不相同的。通过上述分析，我们推断是从库并没有执行建表语句，从而导致主库数据不一致。
4.说明
Got fatal error 1236 from master when reading data from binary log: 'Slave has more GTIDs than the master has, using the master's SERVER_UUID. This may indicate that the end of the binary log was truncated or that the last binary log file was lost, e.g., after a power or disk failure when sync_binlog != 1. The master may or may not have rolled back transactions that were already replica', Error_code: 1236
复制代码
这种情况的复制错误只会发生在 MySQL-5.6 版本，在 MySQL-5.7 版本会在复制时有更严格的校验，如果主机发送 GTID 要少于从库的 GTID，那么会报告出如下的错误：
Got fatal error 1236 from master when reading data from binary log: 'Slave has more GTIDs than the master has, using the master's SERVER_UUID. This may indicate that the end of the binary log was truncated or that the last binary log file was lost, e.g., after a power or disk failure when sync_binlog != 1. The master may or may not have rolled back transactions that were already replica', Error_code: 1236
复制代码
04 主库执行了不进行复制的语句
1. 错误原因
主库上执行的操作并不会写入 binlog。这里不考虑主库主动关闭 binlog 的情况。
2. 错误信息
由于主库和从库的数据不一致，从而导致主库执行的操作复制到从库后，发生从库执行失败的情况。如：
创建 FEDERATED 引擎的表失败:
2017-01-24T08:04:31.682038Z 3 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '887ca716-e202-11e6-8a82-52540086ae59:7' at master log mysql-bin.000004, end_log_pos 906; Error 'server name: 's' doesn't exist!' on query. Default database: 'mydb'. Query: 'CREATE TABLE `mytbl` ( `idaction` int(10) unsigned NOT NULL AUTO_INCREMENT,) ENGINE=FEDERATED DEFAULT CHARSET=utf8 CONNECTION='s'', Error_code: 143
复制代码
3.原因分析过程
这里以使用 CONNECTION 创建 FEDERATED 引擎的表为例。
查看 error log
Error log 中记录错误信息:
2017-01-24T08:04:31.682038Z 3 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '887ca716-e202-11e6-8a82-52540086ae59:7' at master log mysql-bin.000004, end_log_pos 906; Error 'server name: 's' doesn't exist!' on query.
复制代码
查看主库和从库的 server 表
主库中 server 表中存在名字为 s 的记录:
从库中不存在名字为 s 的记录:
查看 CREATE SERVER 文档说明
文档中记录，create server 语句并不会记录到 binlog 中。所以导致了主库和从库的数据不一致。复制无法正常进行。
对于不进入 binlog 的操作，需要主库和从库同时执行，以防发生主库和从库不一致的情况。
05 从库重复执行 relay log 的语句（非 GTID，非多线程复制）
当变量 relay_log_info_repository 设置为 FILE 时，从库的 SQL 线程每次执行完一个事务后，会把对应的文件和位置信息更新到文件 relay_log.info 中。用于在从库重启时，SQL 能够从正确的位置继续进行复制。
1.错误原因
如果物理机发生宕机或者从库发生意外中断，那么可能发生 SQL 已经执行过了某一个 relay log 中的事务，但是这个事务对应文件和位置信息并没有更新到 relay_log.info 中的情况。在从库发生重启时，会将执行过的事务重新再次执行。
2.错误信息
重复执行的事务包括任何记录到 relay log 中的事务，可能出现的错误信息包括：
创建库或者表失败：
017-04-18T07:52:40.440723Z 6 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:2' at master log binlog001.000001, end_log_pos 493; Error 'Can't create database 'mydb4'; database exists' on query. Default database: 'mydb4'. Query: 'create database mydb4', Error_code: 1007
复制代码
插入语句主键冲突:
2017-04-18T07:57:35.975310Z 10 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 378; Could not execute Write_rows event on table mydb.test; Duplicate entry '10' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 378, Error_code: 1062
复制代码
删除语句找不到对应的语句:
[ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 506; Could not execute Delete_rows event on table mydb.I1; Can't find record in 'I1', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 506, Error_code: 1032
复制代码
由于各种类型的事务均可能执行，这里不再一一列举。
3.原因分析过程
这里以插入语句主键冲突为例。
查看 error log
Error log 中记录以下报错信息：
2017-04-19T03:02:15.448429Z 4 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'binlog001.000001' at position 403, relay log './relaylog002.000002' position: 6162017-04-19T03:02:15.459468Z 4 [ERROR] Slave SQL for channel '': Could not execute Write_rows event on table mydb.k2; Duplicate entry '101' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log binlog001.000001, end_log_pos 621, Error_code: 10622017-04-19T03:02:15.459526Z 4 [Warning] Slave: Duplicate entry '101' for key 'PRIMARY' Error_code: 1062
复制代码
可以看到是 SQL 线程在启动后执行的第一个事务就发生主键冲突的错误。
查看 show slave status
show slave status 显示的信息全部正常，无从库执行事务的 binlog 产生。
查看表 mydb.k2
表中已经存在了这条记录。
查看从库的 relay log 和 binlog
查看从库的 relay log，从复制的起始位置./relaylog002.000002：616 查看:
#170419 11:00:22 server id 30001 end_log_pos 403 CRC32 0x0ef99927 Xid = 7395COMMIT/*!*/;# at 616 relay log的文件位置#170419 11:00:59 server id 30001 end_log_pos 468 CRC32 0xbd3fd6d7 Anonymous_GTID last_committed=1 sequence_number=2 对应主机的事务执行的时间SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;# at 681#170419 11:00:59 server id 30001 end_log_pos 536 CRC32 0x484841bd Query thread_id=553 exec_time=0 error_code=0SET TIMESTAMP=1492570859/*!*/;BEGIN/*!*/;# at 749#170419 11:00:59 server id 30001 end_log_pos 581 CRC32 0x9fd66b9e Table_map: `mydb`.`k2` mapped to number 114# at 794#170419 11:00:59 server id 30001 end_log_pos 621 CRC32 0x4151da88 Write_rows: table id 114 flags: STMT_END_F
BINLOG '69L2WBMxdQAALQAAAEUCAAAAAHIAAAAAAAEABG15ZGIAAmsyAAEDAACea9af69L2WB4xdQAAKAAAAG0CAAAAAHIAAAAAAAEAAgAB//5lAAAAiNpRQQ=='/*!*/;### INSERT INTO `mydb`.`k2`### SET### @1=101# at 834#170419 11:00:59 server id 30001 end_log_pos 652 CRC32 0xf876844e Xid = 7396COMMIT/*!*/;
复制代码
查看从库的 binlog：
#170419 11:00:59 server id 30001 end_log_pos 463 CRC32 0x6ede3a0d Anonymous_GTID last_committed=1 sequence_number=2SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;# at 463#170419 11:00:59 server id 30001 end_log_pos 526 CRC32 0x5fac2d32 Query thread_id=553 exec_time=0 error_code=0SET TIMESTAMP=1492570859/*!*/;BEGIN/*!*/;# at 526#170419 11:00:59 server id 30001 end_log_pos 571 CRC32 0xb51f8ec9 Table_map: `mydb`.`k2` mapped to number 108# at 571#170419 11:00:59 server id 30001 end_log_pos 611 CRC32 0xfa578a3f Write_rows: table id 108 flags: STMT_END_F
BINLOG '69L2WBMxdQAALQAAADsCAAAAAGwAAAAAAAEABG15ZGIAAmsyAAEDAADJjh+169L2WB4xdQAAKAAAAGMCAAAAAGwAAAAAAAEAAgAB//5lAAAAP4pX+g=='/*!*/;### INSERT INTO `mydb`.`k2`### SET### @1=101# at 611#170419 11:00:59 server id 30001 end_log_pos 642 CRC32 0xc3a619a0 Xid = 12COMMIT/*!*/;
复制代码
通过分析上述 binlog 内容，relay log 中并没有记录相同的 insert 语句，而从库的 binlog 显示已经执行过该语句，当从库重启后，试图再次执行相同的 insert 语句，从而导致插入语句的主键冲突。
4.说明
如果复制使用 GTID，那么 GTID 的特性会使从库不执行相同的语句；如果复制使用多线程复制，那么 mts_recovery 会修复这个问题；只有在非多线程复制、非 GTID 复制的情况下才可能出现这个错误。
版本和配置
总体来说，版本和配置的不同，只是会造成各种信息的显示格式不同，并不会对上述的方法造成过多的影响。
01 版本
上述信息收集和分析的举例均是在 MySQL-5.7 版本上进行的举例，不同的大版本在信息的内容或者信息的存放方式上可能存在一定的差异。
MySQL-5.6 版本与 MySQL-5.7 版本在复制相关信息上存在以下差异：
1.日志：
在 MySQL-5.6 在停止复制时，error log 会有错误的信息记录：
2017-04-18 17:32:46 682 [Note] Error reading relay log event: slave SQL thread was killed2017-04-18 17:32:46 682 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)2017-04-18 17:32:46 682 [Note] Slave I/O thread killed while reading event2017-04-18 17:32:46 682 [Note] Slave I/O thread exiting, read up to log 'b5620.000004', position 151
复制代码
2.GTID：
MySQL-5.6 的 gtid_executed 以 global system variables 的方式的展现，MySQL-5.7 是以 mysql.gtid_executed 表的方式展现。
3.BINLOG：
MySQL-5.6 版本在使用自增 ID 时，会使用如下 event 来记录自增 ID。
02 配置
主要体现差异的配置包括 gtid_mode 和 binlog_format。
1.gtid_mode
当 gtid 开启时，gtid 作为判断事务是由谁执行，是否执行过、事务接收和执行进度的判断标准。同时可以通过 show slave status 可以直观的看出 gtid 的接收、执行的情况。
当 gtid 关闭时，file 和 pos 作为接收和执行的判断标准，server_id 作为事务由谁执行的标准。但是事务对应的所有的 server_id 并没有完全的展现出来，所以对于我们排查问题，造成一定的困难。
2. binlog_format
binlog_format 影响的是记录到 binlog 中的日志内容的格式，以同一条 INSERT 语句为例，statement 格式记录到 binlog 中的格式如下（只显示差异部分）：
#170418 17:47:06 server id 30001 end_log_pos 730 CRC32 0xdaf9a789 Query thread_id=154 exec_time=0 error_code=0SET TIMESTAMP=1492508826/*!*/;insert into mydb.m1 values (13)/*!*/;
复制代码
row 格式记录到 binlog 中的格式如下：
#170418 17:46:25 server id 30001 end_log_pos 376 CRC32 0xcfdad7cd Table_map: `mydb`.`m1` mapped to number 114# at 376#170418 17:46:25 server id 30001 end_log_pos 416 CRC32 0xed08eabe Write_rows: table id 114 flags: STMT_END_F
BINLOG 'ceD1WBMxdQAALQAAAHgBAAAAAHIAAAAAAAEABG15ZGIAAm0xAAEDAAHN19rPceD1WB4xdQAAKAAAAKABAAAAAHIAAAAAAAEAAgAB//4NAAAAvuoI7Q=='/*!*/;### INSERT INTO `mydb`.`m1`### SET### @1=13# at 416
复制代码
总结
如果复制发生了错误，通过收集上述的复制相关信息和错误相关信息，分析这些信息中与正常复制异常的地方，便可为排查复制错误提供更多的可以用来排场异常的信息。
当然复制的错误的是多种多样的，并不是所有的错误都可以排查到具体的产生原因。很多复制错误是较难或者无法进行排查的，比如主库或者从库的 binlog 日志文件已经丢失、比如关闭 binlog 后执行某些操作导致复制不一致、再比如某些内核 BUG 导致 MySQL 的复制逻辑本身发生了异常等等。
本文转载自公众号 UCloud 技术（ID：ucloud_tech）。
原文链接：
https://mp.weixin.qq.com/s/pgbcnY0rsIfoS2MAuKX9lQ
评论