slave crash unsafe常见问题分析

提示：公众号展示代码会自动折行，建议横屏阅读

「第一部分 背景」

线上主从由于配置的问题，可能会导致slave crash重启后再建立主从时报1062或1032错误。本地复现时，发现crash前后有些binlog event会重复出现，怀疑可能是IO线程重复复制了一些event，才导致了这个问题。

和我们问题相关的另外一个背景是Replication过程中的master info以及relay log info。在MySQL中，master info存储了slave IO线程持久化的relay log的位点信息；relay log info则存储了slave SQL线程已经应用的relay log相关位点信息。它们存储形式分别受master_info_repository和relay_log_info_repository控制。master info和relay log info的sync频率则分别取决于变量sync_master_info和sync_relay_log_info的配置。

上面信息总结如下表：

本文主要分析由于slave crash，可能会出现的下面两个不一致情形，并讨论出现这些不一致情形时，主从同步可能会出现的一些问题：

1、在sync master info过程中，master info记录的持久化relay log位点信息和Slave IO线程实际持久化relay log位点之间的不一致情形。

2、在sync relay log info过程中，relay log info记录已经执行了的relay log位点信息和Slave SQL线程实际已经应用relay log位点之间的不一致情形。

「第二部分 分析」

slave crash后建立主从报错的原因可能是因为slave crash前后实例相关状态信息不一致造成的，而这些可能出现的不一致主要是MySQL中的非事务操作（主要表现为非原子性）引起的。在特定的配置下，MySQL replication过程中有两个行为是非事务操作：sync master info和sync relay log info。下面来分析它们的不一致行为以及这些不一致行为可能造成的问题。

2.1. sync master info的不一致情形

sync master info这一过程主要目的是将relay log的持久化状态保存到master info 中。其他可能影响这一过程的参数配置如下：

# 默认配置relay_log_recovery = OFF
sync_master_info=10000sync_relay_log_info=10000
slave_parallel_type=DATABASE

在该配置下sync master info的调用逻辑如下：

# stack-sync_master_info/--  handle_slave_io # 每接受一个event就执行一次flush_master_info|   /-- flush_master_info |   |   /-- Relay_log_info::flush_current_log # 将从master接受到的event写入relay log日志文件中|   |   /-- Master_info::flush_info |   |   |   /-- Rpl_info_handler::flush_info # 将当前已经接受到的event位点信息写入到master info

上面堆栈可以看出，handle_slave_io中每接受一个event都会在后续的调用中去执行 Rpl_info_handler::flush_info，该函数用于将当前接受到了多少relay log日志文件名和位点持久化master info 中。如果在写relay log和持久化已经接受多少relay log的位点信息到master info这一过程中之间现crash，会导致部分持久化的event位点信息没有及时写入master info ，使得master info 记录的位点信息和实际持久化relay log状态之间不一致。

而slave crash后相关不一致状态受master info存储形式影响，这主要由枚举变量 master_info_repository控制，该变量取值为FILE或者TABLE，分别表示用文件的存储形式或者innodb表的存储形式来持久化这些信息。下面分别考察这两种不同存储形式下的不一致行为。

2.1.1. 在 master_info_repository=FILE下sync master info的不一致

在 master_info_repository=FILE时，slave使用实例data目录下的master.info文件来记录master info的位点信息。此时，上面堆栈中Rpl_info_handler::flush_info函数的调用逻辑如下：

/--  Rpl_info_handler::flush_info|    /-- Rpl_info_file::do_flush_info|    |   /-- flush_io_cache|    |   |   /-- my_b_flush_io_cache # 会写`master.info`文件，但不会sync|    |   /-- my_sync # 每执行sync_master_info次Rpl_info_file::do_flush_info时，会执行这一步

下面分析在sync master info的堆栈中，如果数据库实例发生crash，可能出现不一致的情况。考虑如果数据库实例在my_b_flush_io_cache和my_sync之间crash，但此时操作系统没有crash，那么再次启动时，实例中master info数据和crash前是一致的。但如果在Relay_log_info::flush_current_log和my_b_flush_io_cache 之间出现crash，则可能会造成relay log文件中event的持久化和master info记录的位点信息不一致。

该不一致表现为：有一个event位点在master info中没有来得及记录，但是在relay log文件中持久化了，导致在之后slave启动时会从master info中记录的位点去拉取event，使得重启后slave的relay log中会重复记录一个event。

下面是分析过程中两个slave crash后不一致案例：

在上面两个案例中，重新建立主从后，Slave会Rotate一个新的relay log日志文件，并且由于拷贝的起点小于当前持久化日志的最后一个位点。

因此会造成一个event(位于master-bin.0000001:5479~5524)重复。在上面案例1中存在一个Table_map_event重复，即存在两个类似于下面的event。但这个重复的event后面，没有Write_rows_event/Delete_rows_event/Update_rows_event其中任何一个和写数据相关的event，因此不会造成任何问题。

#210220 14:18:31 server id 1  end_log_pos 5609 CRC32 0x808ed9e0     Table_map: `test`.`t1` mapped to number 221

在案例2中存在一个Write_rows_event重复，即存在两个类似于下面的event。

#210220 14:18:31 server id 1  end_log_pos 5564 CRC32 0x44309595     Write_rows: table id 221 flags: STMT_END_F

由于重新建立主从会Rotate一个新的日志文件，在应用在新的relay log日志文件中，上述Write_rows中的table id没有对应的Table_map，因此在应用时也会被跳过。

从上面两个案例，进一步可能会导致下面的两个问题：

问题1： 如果relay log中有类似于下面的一组update_rows_event

master-bin.0000001:120  Table_mapmaster-bin.0000001:130  Update_rowsmaster-bin.0000001:140  Update_rowsmaster-bin.0000001:150  Update_rows flags: STMT_END_F

如果在130到140之间crash，master info中记录的是master-bin.0000001:130，但relay log中记录的是master-bin.0000001:0~140。之后slave会重新拉取master-bin.0000001:140 和master-bin.0000001:150 两个event，而这两个event由于没有对应的Table_map_event，因此它们均不会被执行，使得事务中部分event没有被执行。

问题2： 如果在statement模式下，更容易造成slave在crash重启后，crash位点前后出现两个重复的statement语句，使得该语句在slave被重复执行。

2.1.2. 在 master_info_repository=TABLE情况下sync master info的不一致

在 master_info_repository=TABLE时，slave使用表mysql.slave_master_info来记录master info的位点信息。此时上面堆栈中Rpl_info_handler::flush_info 调用逻辑如下：

/-- Rpl_info_handler::flush_info|   /-- Rpl_info_table::do_flush_info|   |   /-- handler::ha_update_row # 持久化接受到relay log的位点信息到mysql.slave_master_info表中，其中每执行sync_master_info(默认值：10000)次Rpl_info_table::do_flush_info时，会执行这一步

上面堆栈中Rpl_info_handler::flush_info只有在接受sync_master_info个event后，才会将当前接受到的relay log位点信息记录到表mysql.slave_master_info。这会导致在relay log中会有多个event会被重复记录。例如：当前slave同步了master中master-bin.0000001从编号第0到第11131之间的event，但根据上面Rpl_info_table::do_flush_info函数的逻辑，mysql.slave_master_info中只会记录master-bin.0000001中从编号第0到第10000的event，表示这些event被接受。在slave启动后会从master-bin.0000001的第10001个event开始拷贝，导致master中从编号10001到11131的event都被salve重复接受了，这可能会造成多个event被重复应用的问题。

问题：在slave参数gtid_mode打开并且在MASTER_AUTO_POSITION为关闭时，slave会继续使用master info来定位主从binlog的接受位点信息。如果slave出现crash时，其master info记录的位点在事务中间，同时relay log中最后接受的event也处在事务中间，则会使得master info中记录位点后的部分event被重复应用。

event[0] ... event[9990]     #  begin...event[10000]    # crash时master info记录的位点...event[10021]    # commit...event[11127]    # begin...event[11131]    # 接受完该event后，实例crashevent[10001]    # 重启后slave从10001开始复制event...event[10021]    # commit...

上图中，从event[9990]...event[10021]是一个完整的事务，而从event[11127]...event[11131]是一个不完整的事务。首先slave在接受完event[11131]后crash，重启后slave发现master info中记录的位点是master-bin.0000001的第10000个event，因此slave从event[10001]开始从master拉取后面的event。这使得event[11127]...event[11131]，event[10001]...event[10021]组成了一个新的事务。造成event[10001]...event[10021]重复应用，使得slave产生1062中断问题。

在gtid_mode以及MASTER_AUTO_POSITION都打开的情况下，在slave不再使用master info来同步，而使用Gtid_Set以事务为单位来同步event。由于Gtid_Set信息是以innodb表的形式存储的，而对innodb表的更新都是原子性的，因此可以避免这个问题中出现的不一致情形。

2.2. sync relay log info的不一致情形

在sync relay log info过程中，relay_log_info_repository的值可以为TABLE或FILE。在relay_log_info_repository=TABLE时，slave用mysql.slave_relay_log_info来记录relay log info的信息，对relay log info的更新是作为用户事务的一部分来执行的。已经应用的relay log和relay log info记录的位点信息是一致的，可以参考官方对sync_relay_log_info变量的解释。因此只考虑relay_log_info_repository=FILE的情况，此时配置和上面保持一样。

此时，其调用逻辑如下：

/--  Xid_apply_log_event::do_apply_event # 在执行每个事务的XID_EVENT（事务的commit语句）时会执行这一步|    /-- Xid_log_event::do_commit # 提交事务|    /-- Relay_log_info::flush_info|    |   /-- Rpl_info_handler::flush_info|    |   |   |   /-- Rpl_info_file::do_flush_info|    |   |   |   |   /-- flush_io_cache|    |   |   |   |   |   /-- my_b_flush_io_cache # 会写文件，但不会sync|    |   |   |   |   /-- my_sync # 每执行sync_master_info(10000)次Rpl_info_file::do_flush_info时，执行这一步

在sync relay log info的逻辑中，如果在Xid_log_event::do_commit和my_b_flush_io_cache之间crash，则会使得relay log info中记录的执行位点信息和relay log实际应用了的relay log位点之间不一致。这使得部分事务重复执行，从而导致1062或者1032问题。假设有下面的执行语句，如果slave在执行完trx2的提交后在Rpl_info_file::do_flush_info中crash，而此时relay log中记录的是master-bin.0000001:160，那么在slave重启后又会从trx2开始应用，导致trx2被重复执行。

master-bin.0000001:120   Query (begin)  # trx1....master-bin.0000001:150   Xid (commit)master-bin.0000001:160   Query (begin)  # trx2            ...master-bin.0000001:190   Xid (commit

「第三部分 结论」

基于一定的参数配置，上面提到的master info的日志接受位点和relay log持久化状态以及relay log info执行位点和relay log实际执行位点的这些不一致情形，可能导致一些event或事务被重复执行。这在Write_rows_event中会导致1062问题（记录已存在）。在Update_rows_event或者Delete_rows_event中则会导致1032问题（记录找不到）。

为了避免这些问题，给出在server crash safe（数据库实例进程crash后仍能安全建立主从）级别下，slave的相关配置方案建议：

（1）在非GTID模式下，可以通过下面开启两个参数可以保证server crash safe：

relay_log_info_repository = TABLE relay_log_recovery = ON

（2）在GTID模式下，可以通过复制协议COM_BINLOG_DUMP_GTID来保证server crash safe，可以通过开启下面参数来保证：

MASTER_AUTO_POSITION = ONrelay_log_recovery = ON

腾讯数据库技术团队对内支持QQ空间、微信红包、腾讯广告、腾讯音乐、腾讯新闻等公司自研业务，对外在腾讯云上依托于CBS+CFS的底座，支持TencentDB相关产品，如TDSQL-C(原CynosDB)、TencentDB for MySQL(CDB)、CTSDB、MongoDB、CES等。腾讯数据库技术团队专注于持续优化数据库内核和架构能力，提升数据库性能和稳定性，为腾讯自研业务和腾讯云客户提供“省心、放心”的数据库服务。此公众号旨在和广大数据库技术爱好者一起推广和分享数据库领域专业知识，希望对大家有所帮助。