论 MySQL 如何查看复制信息和排查复制问题(上)

阅读数:40 2019 年 11 月 12 日 18:54

论MySQL如何查看复制信息和排查复制问题(上)

复制作为 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 发生的错误信息,即复制的错误信息,同时也会记录复制的开始和停止的相关信息,记录位置可以通过如下方式查看:

论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 格式如下:

论MySQL如何查看复制信息和排查复制问题(上)

上图显示的为 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,执行如下语句:

论MySQL如何查看复制信息和排查复制问题(上)

发现另外的 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 文件。

评论

发布