故障分析|浅谈ERROR 1872与5.6/5.7 MTS group recovery

田帅萌

发布于 2019-05-28 19:33:10

3.1K0

发布于 2019-05-28 19:33:10

转自：神谕的暗影长廊

最近遇到一个在MTS环境下，ERROR 1872 Slave failed to initialize relay log info structure from the repository的故障。本文将浅显分析在MTS环境下，该错误的成因，并简单聊一下MTS crash safe的因素。这个报错在5.6之前，或者单线程复制环境下也有可能出现，一般直接原因是仓库信息不对，如relay log目录不对，权限不对等问题造成，而此处讨论的1872，为MTS环境下的ERROR，注意区分。

故障复现

背景和相关配置如下：结构：简单的master -> slave 复制方式：auto_position=0 （file position based replication）数据库版本：MySQL 5.6.20 （5.6的高版本应该也有这个问题）关键配置：

relay_log_info_repository='TABLE'
gtid_mode=ON
relay_log_recovery=ON
sync_relay_log=10000（默认）
slave_checkpoint_group=512（默认）
slave_checkpoint_period=300（默认）
slave_parallel_workers>0应该就行（此处是8）

复现：（目前测下来，按以上参数设置，5.6这个版本会100%复现） ① 先按上条件和配置构做好复制，sysbench给主库压力 ② kill -9 slave节点的mysqld的pid，等mysqld_safe自己拉起 ③ 观察slave节点error log的输出：

[Note] Slave: MTS group recovery relay log info based on Worker-Id 7, group_relay_log_name $path/mysql-relay.000008, group_relay_log_pos 380015428 group_master_log_name mysql-bin.000680, group_master_log_pos 380015258………… 可能有多个“MTS group recovery relay log info”信息
[Note] Slave: MTS group recovery relay log info group_master_log_name mysql-bin.000680, event_master_log_pos 380015258.[ERROR] --relay-log-recovery cannot be executed when the slave was stoppedwith an error or killed in MTS mode; consider using RESET SLAVE or restartthe server with --relay-log-recovery = 0 followed by START SLAVE UNTIL SQL_AFTER_MTS_GAPS[ERROR] Failed to initialize the master info structure

看起来日志输出了MTS尝试从对应relay log恢复的日志输出，但这个时候，报错了Failed to initialize the master info structure，虽relay_log_recovery打开了，但MTS场景并不是直接简单地重新拉取主库的binlog。这里的【group】可以简单理解为事务，下面还会再提到。

这个时候，SHOW SLAVE STATUS\G的部分输出如下：

Master_Log_File: mysql-bin.000686
Read_Master_Log_Pos: 1049427025
Relay_Log_File: mysql-relay.000008
Relay_Log_Pos: 380014448
Relay_Master_Log_File: mysql-bin.000680
Slave_IO_Running: No
Slave_SQL_Running: No
Exec_Master_Log_Pos: 380014278
Seconds_Behind_Master: NULL

看起来没有任何ERROR号，只是没启动双复制线程的样子，然而直接执行START SLAVE;就会报错ERROR 1872了

mysql> START SLAVE;
ERROR 1872 (HY000): Slave failed to initialize relay log info structure from the repository

故障处理

这种情况，实际上是因为MTS产生了gap事务，但还未恢复导致。那怎么恢复呢？

If you were running the failed multithreaded slave with relay_log_recovery enabled, then you must issue START SLAVE UNTIL SQL_AFTER_MTS_GAPS prior to executing CHANGE MASTER TO.

手册的意思是，如果在MTS的环境下开启了relay_log_recovery，需要先将这些MTS crash后产生的gap，手动恢复掉，再重新change到正确的pos，但这种情况，直接执行START SLAVE UNTIL SQL_AFTER_MTS_GAPS已经没用了（还会报1872）。

检查一下slave_worker_info表和slave_relay_log_info表，可以发现信息是不一致的，这也是很正常的：

mysql> SELECT * FROM mysql.slave_worker_info\G
********************* 8. row *********************
                        Id: 8
            Relay_log_name: $path/mysql-relay.000008
             Relay_log_pos: 380015428
           Master_log_name: mysql-bin.000680
            Master_log_pos: 380015258
 Checkpoint_relay_log_name: $path/mysql-relay.000008
  Checkpoint_relay_log_pos: 379513435
Checkpoint_master_log_name: mysql-bin.000680
 Checkpoint_master_log_pos: 379513265
          Checkpoint_seqno: 511
     Checkpoint_group_size: 64
   Checkpoint_group_bitmap: 

                             8 rows in set (0.00 sec)
-- 因为是5.6，基于database级别的MTS，所以在sysbench压测的时候，只有一个worker在工作，不过不影响测试，其他几个id的worker此处就不展示了。
mysql> SELECT * FROM mysql.slave_relay_log_info\G
********************* 1. row *********************
  Number_of_lines: 7
   Relay_log_name: $path/mysql-relay.000008
    Relay_log_pos: 380014448
  Master_log_name: mysql-bin.000680
   Master_log_pos: 380014278
        Sql_delay: 0
Number_of_workers: 8
               Id: 1
1 row in set (0.00 sec)

可以发现，slave_worker_info.Master_log_pos > slave_relay_log_info.Master_log_pos。

如果要强行修掉这个ERROR，可以考虑： 1、通过Exec_Master_Log_Pos和mysql.slave_worker_info查出来的差异信息手动apply。这种方式，也是淘宝内核月报和姜博文章里提到的【需要根据Coordinator和每个Worker的记录信息来进行恢复，推进到一个一致状态后再开始并行】 2、仍通过sql_after_mts_gaps语法修复：

1、配置文件中添加relay_log_recovery=0
2、配置文件中添加skip-slave-start
3、重启mysqld实例
4、START SLAVE UNTIL SQL_AFTER_MTS_GAPS，apply掉这些gap事务
5、START SLAVE sql_thread

3、额外的一个思路，比如这个故障环境，gtid_mode是开的，思考下是否能够打开auto_position=1来恢复（未测）

恢复gap后，errorlog会输出如下日志：

[Note] Slave SQL thread stopped according to UNTIL SQL_AFTER_MTS_GAPS as it has
processed all gap transactions left from the previous slave session.

如果实在不放心，还是重建一下好了，5.6版本的MTS，出现什么问题都不奇怪。

为什么会导致这个问题呢？

非auto_position的单线程复制里，其实只要保证relay_log_recovery=1 and relay_log_info_repository=TABLE.就行了，因为relay_log_info更新是支持事务的，所以在crash时，只需要根据该表重新拉取binlog就行了，easy。

但多线程复制的情况，每个worker都从各自队列里取事务执行，而coordinator这个家伙呢，类似于分发者角色，并保存着一个checkpoint，简单理解为这个checkpoint之前所有的relay log都已经被apply完了。这个点也就是代码里定义的lwm（Low-Water-Mark），表示最近一次checkpoint指定到的位置。

checkpoint之后的事务信息，又被coordinator保存到一个叫做GAQ（global assigned queue）里，每个worker也保存了一个bitmap，用于表示它所执行的事务（mysql.slave_worker_info里的Checkpoint_group_bitmap）。每遇到一次checkpoint，每个worker里的bitmap也将更新，CAQ中也对应剔除了之前的事务，进行推进。被剔除的事务，最大的sequence_number，也就是lwm。

所以，在chechpoint过程中，遇到没有完成的group（一个事务在binlog中对应的一组event序列，或简单理解为事务），也就是遇到了所谓的gap。

checkpoint的时机，由参数slave_checkpoint_period和slave_checkpoint_group来控制。

这块更具体流程和实现，可以参考最后的参考文档，淘宝内核月报那个。

比如，worker a还在执行2，而worker b的事务已经执行完3，4。

+----+----+--------------+----+----+----+----+----+
| a  | c  | a            | b  | b  |    |    |    |
+----+----+--------------+----+----+----+----+----+
| 0  | 1  | 2(applying)  | 3  | 4  | 5  | 6  | 7  |
+----+----+--------------+----+----+----+----+----+

这个时候，如果发生crash，就需要找这个2找出来，并apply掉。

而且，在MTS环境里Exec_Master_Log_Pos不一定是准确的，实际上为上一次checkpoint的位置，所以slave_realy_info_log也不是实时“事务更新”的，这个时候就可能遇到gap，就需要做MTS独有的recovery。

这个gap如何找呢？实际上是比对mysql.slave_worker_info和mysql.slave_relay_log_info所记录的信息，因为worker info表是准确的。恢复逻辑会找relay log，并从lwm开始扫，直至扫到worker info表里的pos为止，将汇总的信息逐个比对，如果崩溃前就已经做了，那么跳过，反之去做apply。

auto-position的情况下，这就简单了，因为可以跳过已经执行了的事务，不用先恢复这些gap。

5.6.31以前和5.7.13以前：

可以看到，MySQL内部定义了一个mts_recovery_group_cnt，定义注释为number of group to execute at recovery，在MTS环境下crash拉起后，因该值非空，所以需要恢复。但不会自动处理的，仅做扫描，errorlog里有输出，本文开头也有贴（此处感谢重庆八怪大哥百忙之中暗中指点）。实际上是没有做真正的恢复处理。这被怀疑是一个bug，可以参考：

https://bugs.mysql.com/bug.php?id=83713
https://bugs.mysql.com/bug.php?id=80102
https://bugs.mysql.com/bug.php?id=77496 -- 这个被官方认定
https://bugs.mysql.com/bug.php?id=80103 -- 这里也介绍了手动恢复办法

当然复现场景所需要的参数设置不是一的。上面模拟出的故障里，即使按照官方给的MTS crash safe设置：

When using file position based replication, set relay_log_recovery=1,
sync_relay_log=1, and relay_log_info_repository=TABLE.

也就是，将sync_relay_log=1，也是可能复现这个问题的。想一下，我做的是kill -9 `pidof mysqld`，而不是对机器做power off，所以此时设置成1还是10000不太重要。

要更轻易复现的话，只需要将slave_checkpoint_period和slave_checkpoint_group设置到一个较大的值即可。有想法的可以自己测测。而且，这个应该叫做Gap-free low-watermark，底下会再提一下。

5.6.31和5.7.13以后，MTS大致的恢复流程应该是这样的：

同样，异常crash后，检查slave_parallel_workers > 0的情况，开始做MTS group recovery，先读取relay log，并补齐因MTS产生的gap，所以这个时候就需要relay log是完整的，官方的意思是，MTS场景下，且以pos点做的复制，建议sync_relay_log=1（可避免os级别的crash，kill -9测试的话，无所谓），gap补齐后，再继续追binlog。

这个版本以后，爽就爽在，已经自动化了这一切，可以在5.7.13的Release Notes里体现：

Replication: If a multithreaded replication slave running with relay_log_recovery=1 stopped unexpectedly, during restart the relay log recovery process could fail. This was due to transaction inconsistencies not being filled, see Handling an Unexpected Halt of a Replication Slave. Prior to this fix, to recover from this situation required manually setting relay_log_recovery=0, starting the slave with START SLAVE UNTIL SQL_AFTER_MTS_GAPS to fix any transaction inconsistencies and then restarting the slave with relay_log_recovery=1. This process has now been automated, enabling relay log recovery of a multithreaded slave upon restart automatically. (Bug #77496, Bug #21507981)

所以这个时候虽然设置了relay_log_recovery，但废弃掉现有的relay log也是在MTS group recovery之后做的，所以relay_log_recovery设置为1也是没问题的。

5.7后，也可以通过设置slave_preserve_commit_order来减少这种gap的可能，并不是完全消除。因为呢，即使没有上述提到的gap，也有可能应用到了Exec_master_log_pos之后的事务，这个玩意就是刚说的Gap-free low-watermark，而且设置了slave_preserve_commit_order=1也是没用的，毕竟之前也说了，slave_realy_info_log非“事务更新”的。

一个小总结

当然，无论是5.6还是5.7，为了保证slave crash safe，还是可以设置一下sync_relay_log=1（OS级别的safe），因无论是自动还是5.6和5.7.13之前版本的手动恢复，都是依赖relay log的完整性的，否则不一定能在relay log里找到gap对应的event。

总结

因技术有限，暂只能写到这个程度，待以时日再深入理解一下。

但无论如何，下次再遇到这种问题，可尽量快速定位到：可能是低版本MySQL带来的BUG，也有可能是配置了非slave crash safe的参数而导致的故障，并且有了除了【重建Slave】之外的修复思路。

同时，也大致理解了MTS crash后的恢复逻辑。

再重复发一下，官网推荐的MTS环境下的crash safe参数设置：

When using GTIDs and MASTER_AUTO_POSITION, set relay_log_recovery=1.
With this configuration the setting of relay_log_info_repository 
and other variables does not impact on recovery.

When using file position based replication, set relay_log_recovery=1,
sync_relay_log=1, and relay_log_info_repository=TABLE.

不过话又说回来，为了用MTS+file position based replication的组合，设置sync_relay_log=1，真的好吗？可以想像一下sync_relay_log=1将带来多少额外的io开销。当然也不难看出，只要是auto_position的，就简单多了：无论在MySQL 5.6还是5.7，只要简单设置relay_log_recovery=1，且relay_log_info_repository=TABLE就好了。

所以总结中的总结就是： MySQL 5.6，别用MTS（反正也是基于DATABASE的分发） MySQL 5.7，强行要用MTS，需要考虑双主间，seconds_behind_master不准的情况，且开启GTID和auto_position，配置crash safe的选项参数

GTID NB，auto_position NB，这么好用的东西，为什么不用呢。

参考文档：

MySQL多线程复制问题处理之Error_code: 1872 - 姜承尧 关于MySQL的GTID和crash safe(https://github.com/ChenHuajun/chenhuajun.github.io/blob/master/_posts/2016-11-30-%E5%85%B3%E4%BA%8EMySQL%E7%9A%84GTID%E5%92%8Ccrash%20safe.md) - 苏宁云商陈华军 MySQL 5.7 MTS源码分析(https://github.com/eurekaka/wiki/wiki/MySQL-5.7-MTS源码分析)- Kenan Yao MySQL · 功能分析 · 5.6 并行复制实现分析(http://mysql.taobao.org/monthly/2015/08/09/) - tb内核月报 MySQL · 特性分析 · 5.6 并行复制恢复实现(http://mysql.taobao.org/monthly/2015/09/07/)- tb内核月报 Handling an Unexpected Halt of a Replication Slave(https://dev.mysql.com/doc/refman/5.7/en/replication-solutions-unexpected-slave-halt.html) - 手册 Replication and Transaction Inconsistencies(https://dev.mysql.com/doc/mysql-replication-excerpt/5.7/en/replication-features-transaction-inconsistencies.html) - 手册