复制作为 MySQL 原生的数据同步功能，在 MySQL 高可用架构中起着至关重要的作用。本文梳理了在运维本公司 MySQL 高可用产品 UDB 的过程中遇到的复制问题，并总结了当复制发生异常时，排查复制异常的方法。
错误排查
01 收集复制信息
在复制发生异常时，我们首先要收集复制相关的信息以及错误相关的信息，主要通过如下手段收集。
1.查看 show slave status
执行命令"show slave status"查看复制相关信息。主要关注以下几条信息：
Master_Log_File: mysql-bin.000063Read_Master_Log_Pos: 282657539
复制代码
IO 线程读取到的主库的 binlog 文件名和该 binlog 中的位置。这两个字段代表复制过程中 binlog 由主库传输到备库的进度。
Relay_Log_File: mysql-relay.000002Relay_Log_Pos: 313885
复制代码
SQL 线程执行到的 relay log 的文件名和该 relay log 中的位置。
Relay_Master_Log_File: mysql-bin.000002Exec_Master_Log_Pos: 316585
复制代码
SQL 线程执行到的 relay log 对应的主库中的 binlog 文件名和该 binlog 的位置。这四个字段代表复制过程中，主库的数据在备库上重放的进度。
Slave_IO_Running: YesSlave_SQL_Running: No
复制代码
当前发生问题的是哪个线程，IO 线程或者时 SQL 线程。
Retrieved_Gtid_Set: ed7c5ee4-762d-11e6-ab9e-6c92bf24c36a:14-3920163Executed_Gtid_Set: 04ffb4f5-762e-11e6-81e4-6c92bf26c5c2:1
复制代码
这两个字段在开启 GTID 后才有意义。分别代表 IO 线程接收到的 binlog 中的事务对应的 GTID 和 SQL 线程执行过的事务对应的 GTID。
这里的 GTID 不会因为复制而发生改变，即主库的 GTID 对应的事务一定是主库执行过之后，通过复制发送过来的。备库的 GTID 对应的事务一定是备库执行的。
Last_Errno/Last_IO_Errno/Last_SQL_ErrnoLaset_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 1942017-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 killed2017-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: 1007Last_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-d4ae52a34783Retrieved_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5Executed_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=7SET @@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=6SET @@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 文件。
评论