操作解析：MySQL如何查看复制信息并排查问题（上）-mysql主主复制存在的问题

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

一、错误排查

1. 收集复制信息

在复制发生异常时，首先要分别收集与复制、错误相关的信息，主要通过以下手段进行。

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线程发生错误的相关描述

1.2 查看错误日志

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

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

(1) 开始复制(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

(2) 停止复制(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

(3) 复制错误信息

复制错误信息的描述会在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

1.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、TABLEMAP、WRITEROW、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

(1) Event的时间

为主库执行事务的时间，不管从库的relay log和binlog，时间均为主库执行事务的时间。

(2) Event的server_id

记录是执行该事务的数据库的server_id，可以用来区分这条事务是主库还是从库执行的。

(3) Event的end log pos

从库relay log中end log pos为对应主库中binlog的该event的真实文件位置。
主库和从库的binlog中，的end log pos为该binlog的文件真实位置。

(4) EVENT的at xxx

at xxx代表该event在文件中的真实位置。

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

Previous_gtids events记录了当前binlog之前执行过的所有的gtid信息，用来定位具体的gtid。
GTID event中对应的GTID，与事务是一一对应的，表明该事务是由主库执行还是由从库执行的。
当错误发生时，事务执行的时间，事务的执行和具体语句。
主库执行数据库操作后，将相关日志记录到主库的binlog中。备库的IO线程接收到主库传输的binlog日志后，将这些日志记录到relay log中，如果备库开启了logslaveupdates选项，那么SQL线程在重放relay log过程中，会记录相关binlog日志。这三个二进制文件日志，执行内容上应该是相同的。

1.4 查看其他变量

查看其他复制相关的系统变量或者状态，如：

执行“show variables like‘gtid_mode’”查看gtid是否开启;
执行“show status like ‘Rplsemisyncmasterstatus’”查看半同步复制的状态。

这里不再一一列举。

2. 排查错误

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

2.1 查看show slave status

查看是哪个线程(IO线程或者SQL线程)发生错误，查看错误原因。

如果是IO线程发生错误，记录发生错误时接收到的binlog文件名和位置(如果开启了GTID则记录GTID);
如果是SQL线程发生错误，记录发生错误时执行到的relay log文件名和位置(如果开启了GTID则记录GTID)。

2.2 查看错误日志

进一步确认发生错误的原因，部分原因只会记录在错误日志中，不会在show slave status中展示。比如，空间不足导致IO线程出错、网络中断导致IO线程异常等。

查看是不是由于其他用户正常关闭复制或者kill复制相关的线程导致复制不可用。

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

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

2.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会有错误的信息记录：

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

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. 配置

主要体现差异的配置包括gtidmode和binlogformat。

(1) gtid_mode

当gtid开启时，gtid作为判断事务由谁执行，是否执行过、事务接收和执行进度的标准。同时,可以通过show slave status直观看出gtid的接收、执行情况。

当gtid关闭时，file和pos作为接收和执行的判断标准，serverid作为事务由谁执行的标准。但是事务对应的所有的serverid并没有完全的展现出来，所以对于我们排查问题，造成一定的困难。

(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

【本文是51CTO专栏机构作者“大U的技术课堂”的原创文章，转载请通过微信公众号(ucloud2012)联系作者】

戳这里，看该作者更多好文