MySQL中MGR中SECONDARY节点磁盘满，导致mysqld进程被OOM Killed

老叶茶馆

发布于 2021-10-12 11:14:13

8670

发布于 2021-10-12 11:14:13

文章被收录于专栏：MySQL修行 | 老叶茶馆MySQL修行 | 老叶茶馆

本文首发于 GreatSQL社区微信公众号。

问题描述
MySQL 8.0.26 测试过程
- disk full报告过程及何时被oom killed
- 关注mysqld进程内存消耗变化
GreatSQL 8.0.25测试过程

在MGR测试中，人为制造磁盘满问题后，节点被oom killed

问题描述

在对MySQL 8.0.26 vs GreatSQL 8.0.25的对比测试过程中，有一个环节是人为制造磁盘满的场景，看看MGR是否还能正常响应请求。

在实测过程中，最后发现磁盘满的那个节点，持续时间足够久后，会因为内存消耗过大而最终被OS给OOM Kill。

这个问题我已报告BUG（#104979），下面是该过程的详细记录。

首先，直接利用dd复制空文件填满磁盘。

MySQL 8.0.26 测试过程

disk full报告过程及何时被oom killed

来看下MySQL 8.0.26遇到disk full时日志都输出哪些内容：

# 首次提示disk full的时刻是 09:44:10.052558，这时其实还能写入日志，只是不能写数据和binlog
2021-09-18T09:44:10.052558+08:00 10 [ERROR] [MY-000035] [Server] Disk is full writing './yejr-mgr3-relay-bin-group_replication_applier.000046' (OS errno 28 - No space left on device). Waiting for someone to free space... Retry in 60 secs. Message reprinted in 600 secs.
2021-09-18T09:44:10.052558+08:00 15 [ERROR] [MY-000035] [Server] Disk is full writing '/data/MySQL/binlog.000039' (OS errno 28 - No space left on device). Waiting for someone to free space... Retry in 60 secs. Message reprinted in 600 secs.
2021-09-18T09:54:10.109075+08:00 15 [ERROR] [MY-000035] [Server] Disk is full writing '/data/MySQL/binlog.000039' (OS errno 28 - No space left on device). Waiting for someone to free space... Retry in 60 secs. Message reprinted in 600 secs.
2021-09-18T09:54:10.109828+08:00 10 [ERROR] [MY-000035] [Server] Disk is full writing './yejr-mgr3-relay-bin-group_replication_applier.000046' (OS errno 28 - No space left on device). Waiting for someone to free space... Retry in 60 secs. Message reprinted in 600 secs.
2021-09-18T09:56:15.020870+08:00 152 [ERROR] [MY-010907] [Server] Error writing file '/data/MySQL/slow.log' (errno: 28 - No space left on device)
# 最后一次提示disk full时是10:04:10.166349，这时候彻底无法写入日志了
2021-09-18T10:04:10.166349+08:00 15 [ERROR] [MY-000035] [Server] Disk is full writing '/data/MySQL/binlog.000039' (OS errno 28 - No space left on device). Waiting for someone to free space... Retry in 60 secs.

从disk full时刻开始，大约过了2.5小时，mysqld进程内存消耗持续上升，最终引发oom kill

Sep 18 12:56:28 mgr3 kernel: docker-containe invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=-500
...
Sep 18 12:56:29 mgr3 kernel: Out of memory: Kill process 9539 (mysqld) score 902 or sacrifice child
Sep 18 12:56:29 mgr3 kernel: Killed process 9539 (mysqld), UID 27, total-vm:17020364kB, anon-rss:14644556kB, file-rss:0kB, shmem-rss:0kB

在这期间某个时刻抓到的待认证事务堆积，在被oom kill前实际不止这么多：

+--------------------------------------+----------+
| id                                   | trx_que  |
+--------------------------------------+----------+
| dbe4f563-1622-11ec-8cc8-525400e802e2 | 87863918 |
+--------------------------------------+----------+

关注mysqld进程内存消耗变化

下面是mysqld进程内存消耗变化情况

# 一开始3G
 9539 3144872 /usr/local/mysql-8.0.26-linux-glibc2.12-x86_64/bin/mysqld --defaults-file=/data/MySQL/my.cnf
...
# 涨到3.47G
 9539 3641984 /usr/local/mysql-8.0.26-linux-glibc2.12-x86_64/bin/mysqld --defaults-file=/data/MySQL/my.cnf
...
# 涨到7G
 9539 7416908 /usr/local/mysql-8.0.26-linux-glibc2.12-x86_64/bin/mysqld --defaults-file=/data/MySQL/my.cnf
...
# 不断增长，直至最后被oom killed前，大约飙到14G
 9539 14638256 /usr/local/mysql-8.0.26-linux-glibc2.12-x86_64/bin/mysqld --defaults-file=/data/MySQL/my.cnf

OS层oom-killer相关日志：

# mysqld进程内存大约飙到14G
Sep 18 12:56:29 mgr3 kernel: Out of memory: Kill process 9539 (mysqld) score 902 or sacrifice child
Sep 18 12:56:29 mgr3 kernel: Killed process 9539 (mysqld), UID 27, total-vm:17020364kB, anon-rss:14644556kB, file-rss:0kB, shmem-rss:0kB

GreatSQL 8.0.25测试过程

作为对比，我用GreatSQL 8.0.25也做了同样的测试。

# 首次报告disk full
2021-09-18T23:07:49.264992+08:00 89 [ERROR] [MY-000035] [Server] Disk is full writing '/data/GreatSQL/binlog.000085' (OS errno 28 - N
o space left on device). Waiting for someone to free space... Retry in 60 secs. Message reprinted in 600 secs.
2021-09-18T23:07:49.264992+08:00 82 [ERROR] [MY-000035] [Server] Disk is full writing './yejr-mgr3-relay-bin-group_replication_applie
r.000147' (OS errno 28 - No space left on device). Waiting for someone to free space... Retry in 60 secs. Message reprinted in 600 se
cs.

# 发出报错，提示因为disk full，无法写入data/binlog
2021-09-18T23:07:49.838301+08:00 84 [ERROR] [MY-011071] [Repl] Plugin group_replication reported: 'io full on data or binlog director
y'
# 本节点自动改为RO
2021-09-18T23:07:49.852475+08:00 84 [ERROR] [MY-011712] [Repl] Plugin group_replication reported: 'The server was automatically set i
nto read only mode after an error was detected.'
2021-09-18T23:07:49.852633+08:00 0 [ERROR] [MY-011486] [Repl] Plugin group_replication reported: 'Message received while the plugin i
s not ready, message discarded.'
# 接下来准备退出集群了
2021-09-18T23:07:49.856907+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] Re-using server node 0 host 17
2.16.16.53'
2021-09-18T23:07:49.856937+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] Re-using server node 1 host 17
2.16.16.16'
2021-09-18T23:07:49.856950+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] pid 5211 Installed site start={dba4e34 1394386 1} boot_key={dba4e34 1394375 1} event_horizon=10 node 4294967295 chksum_node_list(&site->nodes) 704906340'
2021-09-18T23:07:55.380111+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] Installing leave view.'
2021-09-18T23:07:55.380169+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] ::install_view():: No exchanged data'
2021-09-18T23:07:55.380188+08:00 0 [Note] [MY-011071] [Repl] Plugin group_replication reported: 'on_view_changed is called'
# 发生view change，正式退出集群
2021-09-18T23:07:55.380242+08:00 0 [System] [MY-011504] [Repl] Plugin group_replication reported: 'Group membership changed: This member has left the group.'
2021-09-18T23:07:55.382254+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] Rejecting this message. The gr
oup communication engine has already stopped.'
...中间几条相同的日志
2021-09-18T23:07:55.382325+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] Rejecting this message. The group communication engine has already stopped.'
2021-09-18T23:07:55.382333+08:00 0 [Note] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] Rejecting this message. The group....日志没写完，磁盘彻底填满了
# 下面是第二天我清理磁盘空间后的新日志
2021-09-19T07:10:52.071942+08:00 82 [ERROR] [MY-013309] [Repl] Plugin group_replication reported: 'Transaction '1:38481943' does not exist on Group Replication consistency manager while receiving remote transaction prepare.'
2021-09-19T07:10:52.071990+08:00 82 [ERROR] [MY-011452] [Repl] Plugin group_replication reported: 'Fatal error during execution on the Applier process of Group Replication. The server will now leave the group.'
2021-09-19T07:10:52.072032+08:00 82 [Warning] [MY-011646] [Repl] Plugin group_replication reported: 'Skipping leave operation: member already left the group.'
2021-09-19T07:10:52.072049+08:00 82 [ERROR] [MY-011712] [Repl] Plugin group_replication reported: 'The server was automatically set into read only mode after an error was detected.'

从日志详情中可以看到，当磁盘空间满了之后，GreatSQL会将那个节点主动退出集群，对整个集群的影响非常小。

此外，从集群退出后，也不会再接收认证事务了，所以也没发生内存持续暴涨最终被oom killed的情况，实际观察过程中发现内存反倒还下降了

# 还在集群中的内存消耗
 5211 2790736 /usr/local/GreatSQL-8.0.25-15-Linux-glibc2.17-x86_64-minimal/bin/mysqld
 ...
 # 退出集群后的内存反倒降低了
 5211 2801696 /usr/local/GreatSQL-8.0.25-15-Linux-glibc2.17-x86_64-minimal/bin/mysqld
 5211 968876 /usr/local/GreatSQL-8.0.25-15-Linux-glibc2.17-x86_64-minimal/bin/mysqld
 ...
 # 此后内存一直保持这个值
  5211 969172 /usr/local/GreatSQL-8.0.25-15-Linux-glibc2.17-x86_64-minimal/bin/mysqld

这样对比来看，GreatSQL的可靠性还真是可以的，官方的MySQL MGR的可靠性还有待进一步加强呀。

P.S，本文即将推送前，收到MySQL官方bug团队的回复，认为这不是一个bug，而应该优先解决磁盘满的问题。我补充回复说加个事务缓存上限阈值或许更合理，人继续傲娇的表示我应该先关注磁盘问题。。。

Enjoy MySQL & GreatSQL :)

本文参与腾讯云自媒体分享计划，分享自微信公众号。

原始发表：2021-09-21，如有侵权请联系 cloudcommunity@tencent.com 删除

sql