MySQL复制异常大扫盲：快速溯源与排查错误全解

Posted 2020-09-22 技术为王

mysql复制异常大扫盲：快速溯源与排查错误全解
https://mp.weixin.qq.com/s/0Ic8BnUokyOj7m1YOrk1tA

作者介绍
王松磊，现任职于UCloud，从事MySQL数据库内核研发工作，主要负责UCloud云数据库UDB的内核故障排查工作以及数据库新特性的研发工作。

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

一、错误排查

1、收集复制信息

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

（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）查看错误日志

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



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


开始复制（start slave）

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



停止复制（stop slave）

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




复制错误信息

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



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



（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为例来说明：



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在文件中的真实位置

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

Previous_gtids events记录了当前binlog之前执行过的所有的gtid信息，用来定位具体的gtid。
GTID event中对应的GTID，与事务是一一对应的，表名该事务是由主库执行还是由重库执行的。
当错误发生时，事务执行的时间，事务的执行具体语句。
主库执行数据库操作后，将相关日志记录到主库的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’”查看半同步复制的状态。

这里不再一一列举。

二、排查错误

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

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）时日志中记录的操作是否相同。

查看备库的二进制文件，备库是否执行过与主库冲突的操作。


总结

对于处于正常状态的复制，应处于以下状态：

查看复制状态应该是正常状态，如show slave status显示IO线程和SQL线程的运行状态均为YES，如半同步复制中show status like “rpl%”显示的半同步复制状态为ON。
主库和备库均没有复制相关的错误信息报出。
主库和备库的二进制日志文件中记录的数据库操作内容应一致，主库和备库中的数据内容应保持一致。

通过对比分析上述信息，查看异常的状态或者日志，可以为我们排查复制相关的错误提供更多的帮助。

三、版本和配置

总体来说，版本和配置的不同，只是会造成各种信息的显示格式不同，并不会对上述的方法造成过多的影响。

1、版本

上述信息收集和分析的举例均是在mysql-5.7版本上进行的举例，不同的大版本在信息的内容或者信息的存放方式上可能存在一定的差异。

mysql-5.6版本与mysql-5.7版本在复制相关信息上存在以下差异：

日志：
在mysql-5.6在停止复制时，error log会有错误的信息记录：



GTID：
mysql-5.6的gtid_executed以global system variables的方式的展现，mysql-5.7是以mysql.gtid_executed表的方式展现。

BINLOG：
mysql-5.6版本在使用自增ID时，会使用如下event来记录自增ID。

#170419 11:27:12 server id 30061  end_log_pos 494 CRC32 0x7a9f75c6      Intvar
SET INSERT_ID=1/*!*/;

2、配置

主要体现差异的配置包括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中的格式如下（只显示差异部分）：



row格式记录到binlog中的格式如下：



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

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

1、从库执行语句与主库冲突

（1）错误原因

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

（2）错误信息

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

创建库或者表失败



插入语句主键冲突



删除语句找不到对应的语句



由于这是比较常见的原因，所有导致主从冲突的操作均会导致复制出错，这里不再一一列举。

（3）原因分析过程

这里以由于数据库存在而导致创建数据库出错为例来分析原因。


查看error log

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



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


查看show slave status

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



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



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


查看从库binlog日志

从库binlog日志记录的是SQL线程复现的主机的binlog信息或者时从库本身执行的事务的binlog日志。这些事务是可以通过server_id或者GTID来区分。

这里以创建数据库失败为例，在从库binlog中，查找3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1对应的事务，发现如下信息：




查看从库relay log日志

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




总结

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

2、主库的binlog丢失

（1）错误原因

复制过程中，由于从库需要读取的主库的binlog丢失，从而导致复制发生异常。导致主库binlog丢失的主要原因如下：

主库执行reset master命令
主库执行purge binary/master logs命令
主库设置了expire_logs_days，自动删除了binlog
主库的binlog被误删除

（2）错误信息

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



（3）原因分析过程


查看error log

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



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


查看主库binlog日志

查看主库的binlog日志文件列表，可能会发现主库的binlog变成重新开始记录：



或者需要复制的binlog已经被删除：




总结

如果binlog重新开始记录，通常是由于主库执行了reset master命令，导致所有的binlog被删除。

如果binlog任然在继续记录，只是从库需要的binlog被删除，通常是由于主库手动执行了purge binary logs命令，或者日志的保留时间超过了expire_logs_days设置的时间。

3、从库没有执行主库复制的语句

由于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中记录错误信息：




查看show slave status

show slave status显示的信息全部正常，无从库执行事务的binlog产生。这里不排除从库关闭binlog执行drop table操作的可能。


查看表

分别在主机和从库执行命令show create table mydb.mytbl4，发现从库上并未不存在mydb.mytbl4。

（4）解析binlog日志

解析主机binlog日志，查看建表的事务日志：



解析从库的binlog日志，查找是否存在建表的事务日志：



这时我们发现对于相同的GTID，从库和主机执行的语句是不相同的。

（5）总结

通过上述分析，我们推断是从库并没有执行建表语句，从而导致主库数据不一致。

（6）说明

这种情况在mysql-5.7版本会在复制时有更严格的校验，如果主机发送GTID要少于从库的GTID，那么会报告出如下的错误：



但是即使在5.7版本，如果启动复制的时（错误后重新启动），主库执行的GTID超过了从库，仍然会报出同样的错误。

4、主库执行了不进行复制的语句

（1）错误原因

主库上执行的操作并不会写入binlog。这里不考虑主库主动关闭binlog的情况。

（2）错误信息

由于主库和从库的数据不一致，从而导致主库执行的操作复制到从库后，发生从库执行失败的情况。如：

创建FEDERATED引擎的表失败



（3）原因分析过程

这里以使用CONNECTION创建FEDERATED引擎的表为例。


查看error log

Error log中记录错误信息：




查看主库和从库的server表

主库中server表中存在名字为s的记录：



从库中不存在名字为s的记录：




查看CREATE SERVER文档说明

文档中记录，create server语句并不会记录到binlog中。所以导致了主库和从库的数据不一致。复制无法正常进行。


总结

对于不记入binlog的操作，需要主库和从库同时执行，以防发生主库和从库不一致的情况。

5、从库重复执行relay log的语句（非GTID，非多线程复制）

当变量relay_log_info_repository设置为FILE时，从库的SQL线程每次执行完一个事务后，会把对应的文件和位置信息更新到文件relay_log.info中。用于在从库重启时，SQL能够从正确的位置继续进行复制。

（1）错误原因

如果物理机发生宕机或者从库发生意外中断，那么可能发生SQL线程已经执行过了某一个relay log中的事务，但是这个事务对应文件和位置信息并没有及时更新到relay_log.info中的情况。在从库发生重启之后，会将执行过的事务重新再次执行。

（2）错误信息

重复执行的事务包括任何记录到relay log中的事务，可能出现的错误信息包括：

创建库或者表失败：



插入语句主键冲突：



删除语句找不到对应的语句：



由于各种类型的事务均可能执行，这里不再一一列举。

（3）原因分析过程

这里以插入语句主键冲突为例。


查看error log

Error log中记录以下报错信息：



可以看到是SQL线程在启动后执行的第一个事务就发生主键冲突的错误。


查看show slave status

show slave status显示的信息全部正常，无从库执行事务的binlog产生。


查看表mydb.k2

表中已经存在了这条记录。


查看从库的relay log和binlog

查看从库的relay log，从复制的起始位置./relaylog002.000002：616查看



查看从库的binlog：




总结

通过分析上述binlog内容，relay log中并没有记录相同的insert语句，而从库的binlog显示已经执行过该语句，当从库重启后，试图再次执行相同的insert语句，从而导致插入语句的主键冲突。


说明

如果复制使用GTID，那么GTID的特性会使从库不执行相同的语句。
如果在5.7版本复制使用多线程复制，那么mts_recovery会修复这个问题。
只有在非多线程复制、非GTID复制的情况下才可能出现这个错误。

五、总结

如果复制发生了错误，通过收集上述的复制相关信息和错误相关信息，分析这些信息中与正常复制异常的地方，便可为排查复制错误提供更多的可以用来排除异常的信息。

当然复制的错误是多种多样的，并不是所有的错误都可以排查到具体的产生原因。很多复制错误是较难或者无法进行排查的，比如主库或者从库的binlog日志文件已经丢失、比如关闭binlog后执行某些操作导致复制不一致，再比如某些内核BUG导致MySQL的复制逻辑本身发生了异常等。