资讯

展开

谁动了我的Redis?频繁AOF重写

作者:快盘下载 人气:

容器化redis服务频繁AOF重写

今天来看线上的一个Redis案例。

01背景介绍

线上的一个Redis实例频繁进行aof重写,进入redis的数据目录,可以看到下面的场景:

谁动了我的Redis?频繁AOF重写

我们可以看到:

1、在redis的数据目录,生成了很多个temp-xxx.aof文件。

2、开始的时间是12:23分左右。

3、每次新的aof文件写到大概8~10个G左右的时候,就会发生切换。

一般情况下,出现多个aof的临时文件,一定是本次aof没有完成,然后Redis重新发起了aof重写操作。

02排查过程

1、服务器层面

查看当前Redis所在的服务器层面的监控指标。

在12:23分左右,发现CPU使用率、负载、磁盘Util值都比较正常。

唯一有点异常的是这个内存使用率,看起来一直在抖动,但是似乎还不至于发生OOM,毕竟内存使用率只有70%不到。

2、查看当前Redis实例的读写量和内存使用

查看出问题期间业务的读写量,可以发现:

读请求大概在1500左右,写请求大概在5000左右

看起来读写量也比较小,应该跟读写没关系。

再来看当前的内存使用量:

17G左右。

3、查看Redis自身使用的内存监控

通过Redis的内存使用监控可以发现,Redis使用内存一直保持在17G左右,但是后面有一堆锯齿,内存有升高然后再降低,一直重复的过程。

云数据库 Redis

4、查看Redis server的日志

这个目的主要是看看这段时间究竟Redis在做什么操作,打开日志,截取部分如下:

24:S 28 Dec 12:23:46.598 * Starting automatic rewriting of AOF on 400% growth
24:S 28 Dec 12:23:47.027 * Background append only file rewriting started by pid 281
24:S 28 Dec 12:26:42.848 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:26:42.955 * Starting automatic rewriting of AOF on 401% growth
24:S 28 Dec 12:26:43.361 * Background append only file rewriting started by pid 282
24:S 28 Dec 12:29:13.027 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:29:13.133 * Starting automatic rewriting of AOF on 401% growth
24:S 28 Dec 12:29:13.583 * Background append only file rewriting started by pid 283
24:S 28 Dec 12:32:03.068 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:32:03.175 * Starting automatic rewriting of AOF on 402% growth
24:S 28 Dec 12:32:03.630 * Background append only file rewriting started by pid 284
24:S 28 Dec 12:35:01.723 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:35:01.828 * Starting automatic rewriting of AOF on 403% growth
24:S 28 Dec 12:35:02.256 * Background append only file rewriting started by pid 285
24:S 28 Dec 12:38:11.077 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:38:11.185 * Starting automatic rewriting of AOF on 403% growth
24:S 28 Dec 12:38:11.636 * Background append only file rewriting started by pid 286
24:S 28 Dec 12:41:01.469 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:41:01.576 * Starting automatic rewriting of AOF on 404% growth
24:S 28 Dec 12:41:02.036 * Background append only file rewriting started by pid 287
24:S 28 Dec 12:43:51.044 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:43:51.152 * Starting automatic rewriting of AOF on 404% growth
24:S 28 Dec 12:43:51.584 * Background append only file rewriting started by pid 288
24:S 28 Dec 12:47:04.495 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:47:04.599 * Starting automatic rewriting of AOF on 405% growth
24:S 28 Dec 12:47:05.072 * Background append only file rewriting started by pid 289
24:S 28 Dec 12:50:18.393 # Background AOF rewrite terminated by signal 9
24:S 28 Dec 12:50:18.499 * Starting automatic rewriting of AOF on 405% growth
24:S 28 Dec 12:50:19.004 * Background append only file rewriting started by pid 290
24:S 28 Dec 12:53:11.886 # Background AOF rewrite terminated by signal 9

从日志中不难猜想出来这么一个场景:Redis达到了aof重写的阈值,也就是400%,

redis > config get auto*
1) "auto-aof-rewrite-percentage"
2) "400"

然后开始重写,但是重写的子进程,被系统signal 9信号给kill了,可以理解为子进程被kill -9 了。

这里,通过系统日志/var/log/message确认一下猜想:

Dec 28 12:23:45  kernel: memory+swap: usage 20740096kB, limit 9007199254740988kB, failcnt 0
Dec 28 12:23:45  kernel: kmem: usage 0kB, limit 9007199254740988kB, failcnt 0
Dec 28 12:23:45  kernel: Memory cgroup stats for /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod3ae01d1b_0d39_11eb_adc7_1c98ec1b7874.slice/do
cker-9c9cd155c58b6f28b9d5771a230ea711d48fdb5fb50c99caa14a1afb474d6b54.scope: cache:28KB rss:20740068KB rss_huge:0KB mapped_file:0KB swap:0KB inactive_anon:0KB active_anon:2
0739924KB inactive_file:12KB active_file:8KB unevictable:0KB
Dec 28 12:23:45  kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
Dec 28 12:23:45  kernel: [22253]     0 22253     2932      154      10        0           999 startredis.sh
Dec 28 12:23:45  kernel: [22302]     0 22302    27565      290      58        0           999 sudo
Dec 28 12:23:45  kernel: [22313]  1000 22313  4672591  4659513    9119        0           999 redis-server
Dec 28 12:23:45  kernel: [26944]  1000 26944  4719696  4688593    9214        0           999 redis-server
Dec 28 12:23:45  kernel: Memory cgroup out of memory: Kill process 26944 (redis-server) score 1905 or sacrifice child
Dec 28 12:23:45  kernel: Killed process 26944 (redis-server) total-vm:18878784kB, anon-rss:18753972kB, file-rss:400kB, shmem-rss:0kB

确认当前Redis的子进程由于OOM被kill掉了。

5、分析

那到底是什么地方设置了内存限制,导致子进程被kill了呢?maxmemory?

通常情况下,当Redis占用的内存达到了maxmemory,会触发淘汰策略,这个策略由maxmemory-policy控制,经过查看,当前Redis配置的策略如下:

redis > config get maxmemory-policy
1) "maxmemory-policy"
2) "allkeys-lru"

这个策略是指从所有的key中按照lru算法进行淘汰。按道理,不会导致Redis子进程挂掉。

其实答案就在系统日志里面:

Memory cgroup out of memory

由于线上的Redis是以pod形式跑在K8S集群中的,Pod本身就是一个个的容器,Pod内部利于Cgroup技术对内存有限制。

通过K8S的api查询对应的限制值,如下:

apiVersion: v1
kind: Pod
metadata:
  annotations:
    resources/cpu-limit: "1.2076"
    resources/cpu-request: "0.6038"
    resources/egress-bandwidth-limit: "209715200"
    resources/egress-bandwidth-request: "1048576"
    resources/memory-limit: "21237858304"
    resources/memory-request: "10618929152"
    scheduler/policy: normal
    scheduler/service: redis
  creationTimestamp: "2020-10-13T09:48:21Z"
  labels:
    port: "22392"
    service_type: redis

这个值21237858304具体是多少呢?利用mysql计算一下吧:

select 21237858304/1024/1024/1024;
+----------------------------+
| 21237858304/1024/1024/1024 |
+----------------------------+
|            19.779296875000 |
+----------------------------+
1 row in set (0.00 sec)

也就是大概19.77GB。

到这里,一切都清楚了,再来看这个内存的使用图,就好理解了:

云数据库 Redis

本来Redis占用的内存有17G左右,后面不断的上升,然后下降,一直循环。其本质原因就是:aof重写需要额外的内存空间,Redis aof重写的过程中,总的内存使用量达到了Cgroup的内存限制,导致子进程被kill,然后内存下降,一直不断重复这个过程,所以就产生了很多锯齿,也就有很多temp-xxx.aof文件。

03

总结&&发散

遇到Redis 相关的问题,排查思路可以从下面几个步骤着手:

1、服务器层面

先统筹观察一下,这里站的角度可能会比较高。主要观察服务器的常用指标:CPU、负载、内存、磁盘、网络带宽、TCP连接数等

2、Redis实例层面

确认服务器无误之后,查看Redis实例本身的运行状态

读写QPS、内存使用、Maxmemory、aof重写策略等

3、Redis日志分析

通过Redis日志,查看当前Redis在故障时间点的一些日志信息

4、系统日志、监控辅助排查

到这里,大概会有一个简单的结论,然后根据这个结论去猜测,找其他的元素来佐证结论。

5、源码分析

如果到这里还解决不了,可能需要从源码层面查看了。

发散:

1、文中提到了cgroup技术,如果不了解,可以看看之前的文章:

云原生技术之docker学习笔记(5)

2、如果Redis的占用的内存达到了Redis的maxmemory配置,此时发生重写,Redis会发生什么情况?有兴趣可以自己动手测试一下。

加载全部内容

相关教程
猜你喜欢
用户评论
快盘暂不提供评论功能!