如何查pos机系统日志(一个案例摸透MGR故障检测流程)

作者介绍

陈臣，甲骨文MySQL首席解决方案工程师，公众号《MySQL实战》作者，有大规模的MySQL，Redis，MongoDB，ES的管理和维护经验，擅长MySQL数据库的性能优化及日常操作的原理剖析。

故障检测（Failure Detection）是 Group Replication 的一个核心功能模块，通过它可以及时识别集群中的故障节点，并将故障节点从集群中剔除掉。如果不将故障节点及时剔除的话，一方面会影响集群的性能，另一方面还会阻止集群拓扑的变更。

下面结合一个具体的案例，分析 Group Replication 的故障检测流程。

除此之外，本文还会分析以下问题：

当出现网络分区时，对于少数派节点，会有什么影响？

什么是 XCom Cache？如何预估 XCom Cache 的大小？

在线上，为什么 group_replication_member_expel_timeout 不宜设置过大？

一、案例

以下是测试集群的拓扑，多主模式。

本次测试主要包括两步：

模拟网络分区，看它对集群各节点的影响。

恢复网络连接，看看各节点又是如何反应的。

1、模拟网络分区

首先模拟网络分区故障，在 node3 上执行。

# iptables -A INPUT -p tcp -s 192.168.244.10 -j DROP# iptables -A OUTPUT -p tcp -d 192.168.244.10 -j DROP# iptables -A INPUT -p tcp -s 192.168.244.20 -j DROP# iptables -A OUTPUT -p tcp -d 192.168.244.20 -j DROP# date "+%Y-%m-%d %H:%M:%S"2022-07-31 13:03:01

其中，iptables 命令会断开 node3 与 node1、node2 之间的网络连接。date 记录了命令执行的时间。

命令执行完 5s（这个时间是固定的，在源码中通过 DETECTOR_LIVE_TIMEOUT 指定），各个节点开始响应（从各节点的日志中可以观察到这一点）

首先看看 node1 的日志及集群状态。

2022-07-31T13:03:07.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'Member with address 192.168.244.30:3306 has become unreachable.'

mysql> select member_id,member_host,member_port,member_state,member_role from performance_schema.replication_group_members;+--------------------------------------+----------------+-------------+--------------+-------------+| member_id | member_host | member_port | member_state | member_role |+--------------------------------------+----------------+-------------+--------------+-------------+| 207db264-0192-11ed-92c9-e | 192.168.244.10 | 3306 | ONLINE | PRIMARY || 2cee229d-0192-11ed-8eff-f110 | 192.168.244.20 | 3306 | ONLINE | PRIMARY || 4cbfdc79-0192-11ed-8b01-bd0a | 192.168.244.30 | 3306 | UNREACHABLE | PRIMARY |+--------------------------------------+----------------+-------------+--------------+-------------+3 rows in set (0.00 sec)

从 node1，node2 的角度来看，此时 node3 处于 UNREACHABLE 状态。

接下来看看 node3 的。

2022-07-31T13:03:07.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'Member with address 192.168.244.10:3306 has become unreachable.'2022-07-31T13:03:07.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'Member with address 192.168.244.20:3306 has become unreachable.'2022-07-31T13:03:07.-00:00 0 [ERROR] [MY-] [Repl] Plugin group_replication reported: 'This server is not able to reach a majority of members in the group. This server will now block all updates. The server will remain blocked until contact with the majority is restored. It is possible to use group_replication_force_members to force a new group membership.'

mysql> select member_id,member_host,member_port,member_state,member_role from performance_schema.replication_group_members;+--------------------------------------+----------------+-------------+--------------+-------------+| member_id | member_host | member_port | member_state | member_role |+--------------------------------------+----------------+-------------+--------------+-------------+| 207db264-0192-11ed-92c9-e | 192.168.244.10 | 3306 | UNREACHABLE | PRIMARY || 2cee229d-0192-11ed-8eff-f110 | 192.168.244.20 | 3306 | UNREACHABLE | PRIMARY || 4cbfdc79-0192-11ed-8b01-bd0a | 192.168.244.30 | 3306 | ONLINE | PRIMARY |+--------------------------------------+----------------+-------------+--------------+-------------+3 rows in set (0.00 sec)

从 node3 的角度来看，此时 node1，node2 处于 UNREACHABLE 状态。

三个节点，只有一个节点处于 ONLINE 状态，不满足组复制的多数派原则。此时，node3 只能查询，写操作会被阻塞。

mysql> select * from slowtech.t1 where id=1;+----+------+| id | c1 |+----+------+| 1 | a |+----+------+1 row in set (0.00 sec)mysql> delete from slowtech.t1 where id=1;阻塞中。。。

又过了 16s（这里的 16s，实际上与 group_replication_member_expel_timeout 参数有关），node1、node2 会将 node3 驱逐出（expel）集群。此时，集群只有两个节点组成。

看看 node1 的日志及集群状态。

2022-07-31T13:03:23.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'Members removed from the group: 192.168.244.30:3306'2022-07-31T13:03:23.-00:00 0 [System] [MY-] [Repl] Plugin group_replication reported: 'Group membership changed to 192.168.244.10:3306, 192.168.244.20:3306 on view :3.'

mysql> select member_id,member_host,member_port,member_state,member_role from performance_schema.replication_group_members;+--------------------------------------+----------------+-------------+--------------+-------------+| member_id | member_host | member_port | member_state | member_role |+--------------------------------------+----------------+-------------+--------------+-------------+| 207db264-0192-11ed-92c9-e | 192.168.244.10 | 3306 | ONLINE | PRIMARY || 2cee229d-0192-11ed-8eff-f110 | 192.168.244.20 | 3306 | ONLINE | PRIMARY |+--------------------------------------+----------------+-------------+--------------+-------------+2 rows in set (0.00 sec)

再来看看 node3 的，日志没有新的输出，节点状态也没变化。

mysql> select member_id,member_host,member_port,member_state,member_role from performance_schema.replication_group_members;+--------------------------------------+----------------+-------------+--------------+-------------+| member_id | member_host | member_port | member_state | member_role |+--------------------------------------+----------------+-------------+--------------+-------------+| 207db264-0192-11ed-92c9-e | 192.168.244.10 | 3306 | UNREACHABLE | PRIMARY || 2cee229d-0192-11ed-8eff-f110 | 192.168.244.20 | 3306 | UNREACHABLE | PRIMARY || 4cbfdc79-0192-11ed-8b01-bd0a | 192.168.244.30 | 3306 | ONLINE | PRIMARY |+--------------------------------------+----------------+-------------+--------------+-------------+3 rows in set (0.00 sec)

2、恢复网络连接

接下来我们恢复 node3 与 node1、node2 之间的网络连接。

# iptables -F# date "+%Y-%m-%d %H:%M:%S"2022-07-31 13:07:30

首先看看 node3 的日志

2022-07-31T13:07:30.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'Member with address 192.168.244.10:3306 is reachable again.'2022-07-31T13:07:30.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'Member with address 192.168.244.20:3306 is reachable again.'2022-07-31T13:07:30.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'The member has resumed contact with a majority of the members in the group. Regular operation is restored and transactions are unblocked.'2022-07-31T13:07:37.-00:00 0 [ERROR] [MY-] [Repl] Plugin group_replication reported: 'Member was expelled from the group due to network failures, changing member status to ERROR.'2022-07-31T13:07:37.-00:00 0 [Warning] [MY-] [Repl] Plugin group_replication reported: 'Due to a plugin error, some transactions were unable to be certified and will now rollback.'2022-07-31T13:07:37.-00:00 0 [ERROR] [MY-] [Repl] Plugin group_replication reported: 'The server was automatically set into read only mode after an error was detected.'2022-07-31T13:07:37.-00:00 31 [ERROR] [MY-] [Repl] Plugin group_replication reported: 'Error while waiting for conflict detection procedure to finish on session 31'2022-07-31T13:07:37.-00:00 31 [ERROR] [MY-] [Repl] Run function 'before_commit' in plugin 'group_replication' failed2022-07-31T13:07:37.-00:00 33 [System] [MY-] [Repl] Plugin group_replication reported: 'Setting super_read_only=ON.'2022-07-31T13:07:37.-00:00 34 [System] [MY-] [Repl] Plugin group_replication reported: 'Started auto-rejoin procedure attempt 1 of 3'2022-07-31T13:07:37.-00:00 0 [System] [MY-] [Repl] Plugin group_replication reported: 'Group membership changed: This member has left the group.'2022-07-31T13:07:37.-00:00 36 [System] [MY-] [Repl] 'CHANGE MASTER TO FOR CHANNEL 'group_replication_applier' executed'. Previous state master_host='', master_port= 0, master_log_file='', master_log_pos= 351, master_bind=''. New state master_host='', master_port= 0, master_log_file='', master_log_pos= 4, master_bind=''.2022-07-31T13:07:39.-00:00 34 [System] [MY-] [Repl] Plugin group_replication reported: 'Auto-rejoin procedure attempt 1 of 3 finished. Member was able to join the group.'2022-07-31T13:07:40.-00:00 0 [System] [MY-] [Repl] Plugin group_replication reported: 'Distributed recovery will transfer data using: Incremental recovery from a group donor'2022-07-31T13:07:40.-00:00 0 [System] [MY-] [Repl] Plugin group_replication reported: 'Group membership changed to 192.168.244.10:3306, 192.168.244.20:3306, 192.168.244.30:3306 on view :4.'2022-07-31T13:07:40.-00:00 46 [System] [MY-] [Repl] 'CHANGE MASTER TO FOR CHANNEL 'group_replication_recovery' executed'. Previous state master_host='', master_port= 0, master_log_file='', master_log_pos= 4, master_bind=''. New state master_host='192.168.244.20', master_port= 3306, master_log_file='', master_log_pos= 4, master_bind=''.2022-07-31T13:07:40.-00:00 47 [Warning] [MY-] [Repl] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.2022-07-31T13:07:40.-00:00 47 [System] [MY-] [Repl] Slave I/O thread for channel 'group_replication_recovery': connected to master 'repl@192.168.244.20:3306',replication started in log 'FIRST' at position -07-31T13:07:40.-00:00 46 [System] [MY-] [Repl] 'CHANGE MASTER TO FOR CHANNEL 'group_replication_recovery' executed'. Previous state master_host='192.168.244.20', master_port= 3306, master_log_file='', master_log_pos= 4, master_bind=''. New state master_host='', master_port= 0, master_log_file='', master_log_pos= 4, master_bind=''.2022-07-31T13:07:40.-00:00 0 [System] [MY-] [Repl] Plugin group_replication reported: 'This server was declared online within the replication group.'2022-07-31T13:07:40.-00:00 53 [System] [MY-] [Repl] Plugin group_replication reported: 'Setting super_read_only=OFF.'

日志的输出包括两部分，以空格为分界线。

当网络连接恢复后，node3 与 node1、node2 重新建立起了连接，发现自己已经被集群驱逐，于是节点进入到 ERROR 状态。

mysql> select member_id,member_host,member_port,member_state,member_role from performance_schema.replication_group_members;+--------------------------------------+----------------+-------------+--------------+-------------+| member_id | member_host | member_port | member_state | member_role |+--------------------------------------+----------------+-------------+--------------+-------------+| 4cbfdc79-0192-11ed-8b01-bd0a | 192.168.244.30 | 3306 | ERROR | |+--------------------------------------+----------------+-------------+--------------+-------------+1 row in set (0.00 sec)

节点进入到 ERROR 状态，会自动设置为只读，即日志中看到的 super_read_only=ON。注意，ERROR 状态的节点设置为只读是默认行为，与后面提到的 group_replication_exit_state_action 参数无关。

如果group_replication_autorejoin_tries不为 0，对于 ERROR 状态的节点，会自动重试，重新加入集群（auto-rejoin）。重试的次数由 group_replication_autorejoin_tries 决定，从 MySQL 8.0.21 开始，默认为 3。重试的时间间隔是 5min。重试成功后，会进入到分布式恢复阶段。

接下来看看 node1 的日志。

2022-07-31T13:07:39.-00:00 0 [System] [MY-] [Repl] Plugin group_replication reported: 'Group membership changed to 192.168.244.10:3306, 192.168.244.20:3306, 192.168.244.30:3306 on view :4.'2022-07-31T13:07:40.-00:00 0 [System] [MY-] [Repl] Plugin group_replication reported: 'The member with address 192.168.244.30:3306 was declared online within the replication group.'

node3 又重新加入到集群中。

二、故障检测流程

结合上面的案例，我们来看看 Group Repliction 的故障检测流程。

1）集群中每个节点都会定期（每秒 1 次）向其它节点发送心跳信息。如果在 5s 内（固定值，无参数调整）没有收到其它节点的心跳信息，则会将该节点标记为可疑节点，同时会将该节点的状态设置为 UNREACHABLE 。如果集群中有等于或超过 1/2 的节点显示为 UNREACHABLE ，则该集群不能对外提供写服务。

2）如果在group_replication_member_expel_timeout（从 MySQL 8.0.21 开始，该参数的默认值为 5，单位 s，最大可设置值为3600，即 1 小时）时间内，可疑节点恢复正常，则会直接应用 XCom Cache 中的消息。XCom Cache 的大小由group_replication_message_cache_size 决定，默认是 1G。

3）如果在group_replication_member_expel_timeout时间内，可疑节点没有恢复正常，则会被驱逐出集群。

4）而少数派节点呢，不会自动离开集群，它会一直维持当前的状态，直到：

网络恢复正常。

达到 group_replication_unreachable_majority_timeout 的限制。注意，该参数的起始计算时间是连接断开 5s 之后，不是可疑节点被驱逐出集群的时间。该参数默认为 0。

5）无论哪种情况，都会触发：

节点状态从 ONLINE 切换到 ERROR 。

回滚当前被阻塞的写操作。

mysql> delete from slowtech.t1 where id=1;ERROR 3100 (HY000): Error on observer while running replication hook 'before_commit'.

6）ERROR 状态的节点会自动设置为只读。

7）如果group_replication_autorejoin_tries不为 0，对于 ERROR 状态的节点，会自动重试，重新加入集群（auto-rejoin）。

8）如果group_replication_autorejoin_tries为 0 或重试失败，则会执行 group_replication_exit_state_action 指定的操作。可选的操作有：

READ_ONLY：只读模式。在这种模式下，会将 super_read_only 设置为 ON。默认值。

OFFLINE_MODE：离线模式。在这种模式下，会将 offline_mode 和 super_read_only 设置为 ON，此时，只有CONNECTION_ADMIN（SUPER）权限的用户才能登陆，普通用户不能登录。

# mysql -h 192.168.244.3. -P 3306 -ut1 -pERROR 3032 (HY000): The server is currently in offline mode

ABORT_SERVER：关闭实例。

三、XCom Cache

XCom Cache 是 XCom 使用的消息缓存，用来缓存集群节点之间交换的消息。缓存的消息是共识协议的一部分。如果网络不稳定，可能会出现节点失联的情况。

如果节点在一定时间（由 group_replication_member_expel_timeout 决定）内恢复正常，它会首先应用 XCom Cache 中的消息。如果 XCom Cache 没有它需要的所有消息，这个节点会被驱逐出集群。驱逐出集群后，如果 group_replication_autorejoin_tries 不为 0，它会重新加入集群（auto-rejoin）。

重新加入集群会使用 Distributed Recovery 补齐差异数据。相比较直接使用 XCom Cache 中的消息，通过 Distributed Recovery 加入集群需要的时间相对较长，过程也较复杂，并且集群的性能也会受到影响。

所以，我们在设置 XCom Cache 的大小时，需预估 group_replication_member_expel_timeout + 5s 这段时间内的内存使用量。如何预估，后面会介绍相关的系统表。

下面我们模拟下 XCom Cache 不足的场景。

1）将group_replication_message_cache_size调整为最小值（128 MB），重启组复制使其生效。

mysql> set global group_replication_message_cache_size=;Query OK, 0 rows affected (0.00 sec)mysql> stop group_replication;Query OK, 0 rows affected (4.15 sec)mysql> start group_replication;Query OK, 0 rows affected (3.71 sec)

2）将group_replication_member_expel_timeout调整为 3600。这样，我们才有充足的时间进行测试。

mysql> set global group_replication_member_expel_timeout=3600;Query OK, 0 rows affected (0.01 sec)

3）断开 node3 与node1、node2 之间的网络连接。

# iptables -A INPUT -p tcp -s 192.168.244.10 -j DROP# iptables -A OUTPUT -p tcp -d 192.168.244.10 -j DROP# iptables -A INPUT -p tcp -s 192.168.244.20 -j DROP# iptables -A OUTPUT -p tcp -d 192.168.244.20 -j DROP

4）反复执行大事务。

mysql> insert into slowtech.t1(c1) select c1 from slowtech.t1 limit ;Query OK, rows affected (10.03 sec)Records: Duplicates: 0 Warnings: 0

5）观察错误日志。

如果 node1 或 node2 的错误日志中提示以下信息，则意味着 node3 需要的消息已经从 XCom Cache 中逐出了。

[Warning] [MY-] [Repl] Plugin group_replication reported: '[GCS] Messages that are needed to recover node 192.168.244.30: have been evicted from the message cache. Consider resizing the maximum size of the cache by setting group_replication_message_cache_size.'

6）查看系统表。

除了错误日志，我们还可以通过系统表来判断 XCom Cache 的使用情况。

mysql> select * from performance_schema.memory_summary_global_by_event_name where event_name like "%GCS_XCom::xcom_cache%"\G*************************** 1. row *************************** EVENT_NAME: memory/group_rpl/GCS_XCom::xcom_cache COUNT_ALLOC: COUNT_FREE: SUM_NUMBER_OF_BYTES_ALLOC: SUM_NUMBER_OF_BYTES_FREE: LOW_COUNT_USED: 0 CURRENT_COUNT_USED: 924 HIGH_COUNT_USED: LOW_NUMBER_OF_BYTES_USED: 0CURRENT_NUMBER_OF_BYTES_USED: HIGH_NUMBER_OF_BYTES_USED: row in set (0.00 sec)

其中，

COUNT_ALLOC：缓存过的消息数量。

COUNT_FREE：从缓存中删除的消息数量。

CURRENT_COUNT_USED：当前正在缓存的消息数量，等于 COUNT_ALLOC - COUNT_FREE。

SUM_NUMBER_OF_BYTES_ALLOC：分配的内存大小。

SUM_NUMBER_OF_BYTES_FREE：被释放的内存大小。

CURRENT_NUMBER_OF_BYTES_USED：当前正在使用的内存大小，等于 SUM_NUMBER_OF_BYTES_ALLOC - SUM_NUMBER_OF_BYTES_FREE。

LOW_COUNT_USED，HIGH_COUNT_USED：CURRENT_COUNT_USED 的历史最小值和最大值。

LOW_NUMBER_OF_BYTES_USED，HIGH_NUMBER_OF_BYTES_USED：CURRENT_NUMBER_OF_BYTES_USED 的历史最小值和最大值。

如果断开连接之后，在反复执行大事务的过程中，发现 COUNT_FREE 发生了变化，同样意味着 node3 需要的消息已经从 XCom Cache 中驱逐了。

7）恢复 node3 与 node1、node2 之间的网络连接。

在 group_replication_member_expel_timeout 期间，网络恢复了，而 node3 需要的消息在 XCom Cache 中不存在了，则 node3 同样会被驱逐出集群。以下是这种场景下 node3 的错误日志。

[ERROR] [MY-] [Repl] Plugin group_replication reported: '[GCS] Node 0 is unable to get message {4aec99ca 7562 0}, since the group is too far ahead. Node will now exit.'[ERROR] [MY-] [Repl] Plugin group_replication reported: 'Member was expelled from the group due to network failures, changing member status to ERROR.'[ERROR] [MY-] [Repl] Plugin group_replication reported: 'The server was automatically set into read only mode after an error was detected.'[System] [MY-] [Repl] Plugin group_replication reported: 'Setting super_read_only=ON.'[System] [MY-] [Repl] Plugin group_replication reported: 'Started auto-rejoin procedure attempt 1 of 3'

四、注意事项

如果集群中存在 UNREACHABLE 的节点，会有以下限制和不足：

不能调整集群的拓扑，包括添加和删除节点。

在单主模式下，如果 Primary 节点出现故障了，无法选择新主。

如果 Group Replication 的一致性级别等于 AFTER 或 BEFORE_AND_AFTER，则写操作会一直等待，直到 UNREACHABLE 节点 ONLINE 并应用该操作。

集群吞吐量会下降。如果是单主模式，可将 group_replication_paxos_single_leader （MySQL 8.0.27 引入的）设置为 ON 解决这个问题。

所以，在线上 group_replication_member_expel_timeout 不宜设置过大。

>>>>

参考资料

Extending replication instrumentation: account for memory used in

MySQL Group Replication - Default response to network partitions has Ping Will Tear Us Apart - Enabling member auto-rejoin in Group

作者丨陈臣

来源丨公众号：MySQL实战（ID：MySQLInAction）

dbaplus社群欢迎广大技术人员投稿，投稿邮箱：editor@dbaplus.cn

关于我们

dbaplus社群是围绕Database、BigData、AIOps的企业级专业社群。资深大咖、技术干货，每天精品原创文章推送，每周线上技术分享，每月线下技术沙龙，每季度Gdevops&DAMS行业大会。

关注公众号【dbaplus社群】，获取更多原创技术文章和精选工具下载