问题描述

上周四（2018-07-05），下午1点左右，有个客户反馈业务数据库复制中断。这个客户使用了我们的easydb产品，当时easydb上的的主备状态信息如下，

问题排查

a. 复制信息检查

通过’show slave statusG’命令可以查看复制线程详细的工作状态，对于判断复制中断的原因有一些指导性意义。当时的关键信息如下，

               Slave_IO_State: Waiting for master to send event
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
                   Last_Errno: 1594
                   Last_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.
        Seconds_Behind_Master: NULL
                Last_IO_Errno: 0
               Last_SQL_Errno: 1594
               Last_SQL_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.
     Last_SQL_Error_Timestamp: 180705 11:44:28

从复制信息可以看到，IO线程正常运行而sql线程发生了中断，说明日志还在正常传输但是在从库上进行应用时出现了问题；而从sql线程的报错信息我们可以发现，导致复制中断的原因是因为有一个日志事件无法解析；中断时间发生的时间是当日的11时44分。
一般出现这种现象可能来自于网络异常或者mysql本身的bug，或者是空间问题导致的日志文件损坏。。

b. binlog文件分析

首先要确认无法解析的event是来自master的binary log还是slave的relay log，因此需要分别对主备库的日志文件进行分析。
根据show slave statusG输出中sql线程的工作位点，使用mysqlbinlog对下一个event进行解析。分析结果发现主库上的binlog可以正常解析，而在对备库上的relay log进行解析时发生了报错：

Error in Log_event::read_log_event(): 'read error', data_len: 2197897, event_type

解析binlog的命令如下：

mysqlbinlog  -vv --base64-output=DECODE-ROWS --start-position=? filename > output_filename

从对binlog的分析结果，可以说明IO线程在主库上正常读取了下一个需要执行的event，而传到备库并写入relay log时出现了问题，由于relay log中存储的该event无法解析，进而导致sql线程的工作报错。
那么，在写入slave的relay log时，到底发生了什么？

c. MySQL Error log

接下来分析复制发生中断时间段的error log，看看数据库本身有没有出现异常的状况。从下面的日志可以看到，在当天的11:44，该数据库发生了一次重启操作，而这个重启操作发生在第一次日志解析报错之前。

关于数据库关闭导致的复制中断，官方有相应说法，如下，

Unclean shutdowns might produce problems, especially if the disk cache was not flushed to disk before the problem occurred:

For transactions, the slave commits and then updates relay-log.info. If a crash occurs between these two operations, relay log processing will have proceeded further than the information file indicates and the slave will re-execute the events from the last transaction in the relay log after it has been restarted.

A similar problem can occur if the slave updates relay-log.info but the server host crashes before the write has been flushed to disk. To minimize the chance of this occurring, set sync_relay_log_info=1 in the slave my.cnf file. The default value of sync_relay_log_info is 0, which does not cause writes to be forced to disk; the server relies on the operating system to flush the file from time to time.

这里也只是举例说明，不过我们可以看到，在从库发生异常关闭时可能会导致relay info/log写入不完整，从而出现类似问题。但是这里看起来很像是正常的重启操作。

d. OS message log

查看当天OS的message log，发现在mysqld进程重启之前触发了OS的oom-killer事件，具体信息如下：

e. 原因总结

mysqld进程占用过大内存导致发生OOM，异常关闭导致relay log写入丢失，造成部分event不完整。sql线程无法解析下一个event时发生复制中断。

问题处理

1.首先尝试对从库的事务进行了跳过处理。操作如下：

##通过show slave status\G找到下一个要执行的GTID号.
STOP SLAVE;
SET gtid_next = '下一个事务GTID';
BEGIN;COMMIT;
SET gtid_next = 'AUTOMATIC';
START SLAVE;

2.发现事务虽然跳过了一个，但是报错仍然继续。说明文件损坏导致后面的event也无法正常解析。

3.重新拉取binlog。操作如下：

stop slave;
reset slave;
change master to master_host='host_ip',master_port=port,master_user='user_name',master_password='user_pass',master_auto_position=1;
start slave;

注：reset slave会清空io线程以及sql线程的工作记录，包括日志位点以及备库的relay log，master_auto_position参数会让io线程从目前已执行过的event之后开始读取主库的binlog。

4.人工修复不一致的数据。
由于前面跳过了一个event，因此这里需要人工将这个event补进备库中。具体操作如下：

#1) 主库上解析出这个事务
/opt/mysql/bin/mysqlbinlog  -vv --base64-output=DECODE-ROWS  --include-gtids='uuid:n' mysql-bin.006408 >two_tran.txt

#2) 通过vi/sed处理这个文件，变成可直接执行的sql脚本，这里步骤省略
注：sql脚本开头需要加上set sql_log_bin=0，目的是会话级关闭binlog产生，防止由于双向复制导致的主库上的复制线程报错。

#3) 将编辑好的sql脚本传至备库，执行
mysql -h127.0.0.1 -uroot -P3306 -p <two_tran.sql

预防建议

最后整体检查了一下参数以及error log，给了客户一些预防建议，如下：

1、配置监控告警，以便及时获取复制状态异常的情况
2、尽快调整相关内存参数，主要是innodb_buffer_pool_size.
3、Master/Slave重启或关闭前先正常关闭备库的复制线程. stop slave
4、设置从库数据库参数(sync_relay_log=1,sync_relay_log_info=1)，可提高备库的数据安全性，但是会降低复制效率以及提高系统io负载
5、尽量少使用text或者blob大字段，所有表都创建主键以及使用innodb存储引擎，适当调大数据参数max_allowed_packet的值（发现经常出现dump线程闪断的情况）