复制作为MySQL原生的数据同步功能，在MySQL高可用架构中起着至关重要的作用。本文梳理了在运维本公司MySQL高可用产品UDB的过程中遇到的复制问题，并总结了当复制发生异常时，排查复制异常的方法。

错误排查

01 收集复制信息

在复制发生异常时，我们首先要收集复制相关的信息以及错误相关的信息，主要通过如下手段收集。

1.查看show slave status

执行命令"show slave status"查看复制相关信息。主要关注以下几条信息：

Master_Log_File: mysql-bin.000063
Read_Master_Log_Pos: 282657539

IO线程读取到的主库的binlog文件名和该binlog中的位置。这两个字段代表复制过程中binlog由主库传输到备库的进度。

Relay_Log_File: mysql-relay.000002
Relay_Log_Pos: 313885

SQL线程执行到的relay log的文件名和该relay log中的位置。

Relay_Master_Log_File: mysql-bin.000002
Exec_Master_Log_Pos: 316585

SQL线程执行到的relay log对应的主库中的binlog文件名和该binlog的位置。这四个字段代表复制过程中，主库的数据在备库上重放的进度。

Slave_IO_Running: Yes
Slave_SQL_Running: No

当前发生问题的是哪个线程，IO线程或者时SQL线程。

Retrieved_Gtid_Set: ed7c5ee4-762d-11e6-ab9e-6c92bf24c36a:14-3920163
Executed_Gtid_Set: 04ffb4f5-762e-11e6-81e4-6c92bf26c5c2:1

这两个字段在开启GTID后才有意义。分别代表IO线程接收到的binlog中的事务对应的GTID和SQL线程执行过的事务对应的GTID。

这里的GTID不会因为复制而发生改变，即主库的GTID对应的事务一定是主库执行过之后，通过复制发送过来的。备库的GTID对应的事务一定是备库执行的。

Last_Errno/Last_IO_Errno/Last_SQL_Errno
Laset_Error/Last_IO_Error/Last_SQL_Error

IO/SQL线程发生的错误的相关描述。

2.查看错误日志

错误日志记录了MySQL发生的错误信息，即复制的错误信息，同时也会记录复制的开始和停止的相关信息，记录位置可以通过如下方式查看：

在error log中，主要关注如下的信息:

开始复制（start slave）

在从库启动复制时，error log中会记录复制起始位置，包括IO线程读取主库端binlog的起始位置和SQL线程执行的relay log的起始位置。同时error log中还会记录开始复制的具体时间。

2017-04-17T14:47:19.691088Z 7 [Note] Slave I/O thread for channel '': connected to master 'repl@192.168.150.21:30001',replication started in log 'binlog001.000002' at position 194
2017-04-17T14:47:19.693377Z 8 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'binlog001.000002' at position 194, relay log './relaylog002.000217' position: 407

停止复制（stop slave）

在从库停止复制时，error log会记录IO线程停止时读取到的主库的binlog的位置，以及停止复制的时间。

2017-04-18T03:05:52.920750Z 14 [Note] Error reading relay log event for channel '': slave SQL thread was killed
2017-04-18T03:05:52.922007Z 13 [Note] Slave I/O thread killed while reading event for channel ''
2017-04-18T03:05:52.922041Z 13 [Note] Slave I/O thread exiting for channel '', read up to log 'binlog001.000002', position 443

复制错误信息

复制错误信息的描述会在 show slave status 中的last_error中展现，但是如果错误信息较长的话（尤其是在多线程复制的情况下），show slave status并不能完全的显示错误的全部信息，需要查看错误日志才能查看到完整的错误信息。比如:

Last_Errno: 1007
Last_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:4' at master log binlog001.000002, end_log_pos 605. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
 Skip_Counter: 0

上述错误信息并不是一个完整的错误信息描述，可以在error log中看到更完成的信息描述，以及发生错误的时间。

2017-04-18T03:19:00.037806Z 23 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:4' at master log binlog001.000002, end_log_pos 605; Error 'Can't create database 'mydb3'; database exists' on query. Default database: 'mydb3'. Query: 'create database mydb3', Error_code: 1007

3.查看二进制日志文件

这里的二进制日志文件包括主库的binlog、从库的relay log、从库的binlog：主库的binlog是指主库执行过的事务记录的binlog日志;从库的relay log是指从库接收到的主库的binlog日志;从库的binlog是指从库SQL线程复现relay log后记录的日志（log-slave-updates开启）以及从库执行过的事务记录的binlog日志。

二进制日志文件中记录的日志是以event为单位进行记录，比如一个DML语句通常由4-5个event组成，一个DDL语句通常由2个event组成。二进制日志文件可以通过命令‘show binlog events’或者工具mysqlbinlog来将binlog日志转换为可识别的格式。

show binlog events格式如下：

上图显示的为ROW格式的binlog中记录的内容，其中包含了一个DML语句和一条DDL语句。DML语句包含了GTID、QUERY、TABLE_MAP、WRITE_ROW、XID五个event，DDL语句包含了GTID、QUERY两个event。

mysqlbinlog工具同样可以解析binlog，提供与show binlog event类似的event信息，以其中一个event为例来说明：

#170417 23:18:37 server id 30001  end_log_pos 412 CRC32 0x818b4058      Write_rows: table id 110 flags: STMT_END_F

BINLOG '
zdz0WBMxdQAALQAAAHQBAAAAAG4AAAAAAAEABG15ZGIAAkkxAAEDAAF0sqv/
zdz0WB4xdQAAKAAAAJwBAAAAAG4AAAAAAAEAAgAB//4KGgAAWECLgQ==
'/*!*/;
### INSERT INTO `mydb`.`I1`
### SET
###   @1=6666
# at 412

Event的时间：
为主库执行事务的时间，无论从库的relay log和binlog，时间均为主库执行事务的时间。
Event的server_id：
记录的是执行该事务的数据库的server_id，可以用来区分这条事务是主库还是从库执行的。
Event 的end_log_pos：
从库的relay log中的end_log_pos为对应的主库中的binlog的该event的真实文件位置；
主库和从库的binlog中的end_log_pos为该binlog的文件真实位置。
EVENT的at xxx：
at xxx代表该event在文件中的真实位置。

对于以上的二进制日志文件的内容，我们需要关注的信息包括：

1.Previous_gtids events记录了当前binlog之前执行过的所有的gtid信息，用来定位具体的gtid；

2.GTID event中对应的GTID，与事务是一一对应的，表名该事务是由主库执行还是由重库执行的；

3.当错误发生时，事务执行的时间，事务的执行具体语句；

4.主库执行数据库操作后，将相关日志记录到主库的binlog中。备库的IO线程接收到主库传输的binlog日志后，将这些日志记录到relay log中，如果备库开启了log_slave_updates选项，那么SQL线程在重放relay log的过程中，会记录相关binlog日志。这三个二进制文件日志，执行内容上应该是相同的。

4.查看其他变量

查看其他复制相关的系统变量或者状态，如：执行“show variables like‘gtid_mode’”查看gtid是否开启；执行“show status like ‘Rpl_semi_sync_master_status’”查看半同步复制的状态；这里不再一一列举。

02 排查错误

在收集到以上复制信息后，主要通过如下手段排查复制错误：

1.查看show slave status

查看发生错误的是哪个线程（IO线程或者SQL线程），查看错误原因：

如果是IO线程发生错误，记录发生错误时接收到的binlog的文件名和位置（如果开启了GTID则记录GTID）；

如果是SQL线程发生错误，记录发生错误时执行到的relay log的文件名和位置（如果开启了GTID则记录GTID）。

2.查看错误日志

进一步确认发生错误的原因，部分原因只会记录在错误日志中，不会在show slave status中展示。比如空间不足导致IO线程出错、比如网络中断导致IO线程异常等等。查看是否是由于其他用户正常关闭复制或者kill复制相关的线程导致复制不可用。

查看发生错误时，是否为刚刚启动复制、发生错误的语句是否为第一条复制执行的语句。如果为第一条语句，则需要考虑是否由于搭建复制错误的原因导致复制异常，是否由于意外宕机等其他因素导致复制相关二进制日志文件不正确。

对比主库和备库的错误日志，查看是否均发生了同样的复制错误，是否主库做了特殊的错误处理。

3.对比二进制日志文件

对比备库正在接收的binlog与主库正在执行的binlog是否存在冲突（备库接收的binlog的文件和位置要大于主库执行的）。

如果开启了GTID，查看备库是否本身执行了数据库操作产生了GTID，查看备库执行过的GTID是否要多于主库，备库是否执行过其他主机的GTID。

根据发生错误时的binlog的文件和位置（或者GTID），解析主库和备库的二进制文件，对比相同的文件和位置（或者相同的GTID）时日志中记录的操作是否相同；查看备库的二进制文件，备库是否执行过与主库冲突的操作。

常见复制错误原因及分析过程

在收集到上述复制相关信息和错误信息后，我们需要根据实际的错误信息进行分析，这里罗列了几种常见的复制错误，我们可以通过部分或者全部在上述章节收集的相关信息，分析出复制错误发生原因。

01 从库执行语句与主库冲突

1.错误原因

从库执行DML语句或者DDL语句后，主库和从库会出现数据不一致的情况。从而导致主库执行的语句在从库没有办法正常执行。

2.错误信息

由于从库执行与主库冲突的语句而导致复制错误，常见的错误信息如下：

创建库或者表失败：

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-18T08:22:26.885713Z 16 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6' at master log binlog001.000001, end_log_pos 1710; Error 'Can't create database 'mydb10'; database exists' on query. Default database: 'mydb10'. Query: 'create database mydb10', Error_code: 1007

显示在执行GTID 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6时失败。错误原因为数据库已经存在，无法创建。

查看show slave status

当错误发生后，查看show slave status显示的信息时，会发现如下信息：

Master_UUID: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783
Retrieved_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5
Executed_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5,
3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1

在Executed_Gtid_Set显示的信息中，除了Master的UUID对应的GTID外，还存在另外一个GTID，我们可以查看从库的GTID，执行如下语句:

发现另外的GTID是由从库执行而产生的的。

查看从库binlog日志

从库binlog日志记录的是SQL线程复现的主机的binlog信息或者时从库本身执行的事务的binlog日志。这些事务是可以通过server_id或者GTID来区分。这里以创建数据库失败为例，在从库binlog中，查找3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1对应的事务，发现如下信息：

#170418 16:22:15 server id 30002  end_log_pos 1791 CRC32 0xfa89e69a     GTID    last_committed=6        sequence_number=7
SET @@SESSION.GTID_NEXT= '3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1'/*!*/;
# at 1791
……
create database mydb10

查看从库relay log日志

从库relay log日志记录的是IO线程从主库接收到的binlog日志信息，我们查看执行失败的GTID对应的事务信息：

#170418 16:22:26 server id 30001  end_log_pos 1610 CRC32 0x27c8228f     GTID    last_committed=5        sequence_number=6
SET @@SESSION.GTID_NEXT= '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6'/*!*/;
# at 519
……
create database mydb10
/*!*/;

最终可以确认是由于从库执行了创建数据库语句后，SQL线程再次执行创建数据库的语句时发生复制失败的情况。

02 主库的binlog丢失

1.错误原因

复制过程中，由于从库需要读取的主库的binlog丢失，从而导致复制发生异常。导致主库binlog丢失的主要原因如下：主库执行reset master命令;主库执行purge binary/master logs命令;主库设置expire_logs_days，自动删除了binlog;主库的binlog被误删除。

2.错误信息

如果发生找不到主机binlog的情况，从库error log会报出如下错误：

2017-04-18T09:01:42.894612Z 17 [ERROR] Slave I/O for channel '': Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the first event '' at 4, the last event read from './binlog001.000002' at 154, the last byte read from './binlog001.000002' at 154.', Error_code: 1236

3.原因分析过程

查看error log

Error log中显示的详细错误信息如下：

2017-04-18T09:01:42.894612Z 17 [ERROR] Slave I/O for channel '': Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the first event '' at 4, the last event read from './binlog001.000002' at 154, the last byte read from './binlog001.000002' at 154.', Error_code: 1236

错误信息显示无法找到对应的binlog文件。

创作场景

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