复制作为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=0
use `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: 616
2017-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: 1062
2017-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 = 7395
COMMIT/*!*/;
# 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=0
SET 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 '
69L2WBMxdQAALQAAAEUCAAAAAHIAAAAAAAEABG15ZGIAAmsyAAEDAACea9af
69L2WB4xdQAAKAAAAG0CAAAAAHIAAAAAAAEAAgAB//5lAAAAiNpRQQ==
'/*!*/;
### INSERT INTO `mydb`.`k2`
### SET
###   @1=101
# at 834
#170419 11:00:59 server id 30001  end_log_pos 652 CRC32 0xf876844e      Xid = 7396
COMMIT/*!*/;

查看从库的binlog：

#170419 11:00:59 server id 30001  end_log_pos 463 CRC32 0x6ede3a0d      Anonymous_GTID  last_committed=1        sequence_number=2
SET @@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=0
SET 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+1
69L2WB4xdQAAKAAAAGMCAAAAAGwAAAAAAAEAAgAB//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 = 12
COMMIT/*!*/;

通过分析上述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 killed
2017-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 event
2017-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=0
SET 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 '
ceD1WBMxdQAALQAAAHgBAAAAAHIAAAAAAAEABG15ZGIAAm0xAAEDAAHN19rP
ceD1WB4xdQAAKAAAAKABAAAAAHIAAAAAAAEAAgAB//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

创作场景

论 MySQL 如何查看复制信息和排查复制问题（下）