谁动了我的Redis？频繁AOF重写问题解析

淡淡的烟草味﹌ 2024-03-24 10:55 142阅读 0赞

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

## 01 背景介绍 ##

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

![487923156734e751815a336648757bff.png][]

我们可以看到:

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%不到。

![ebbe0854aff58d0b6a35426afd3a3cdb.png][]

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

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

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

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

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

17G左右。

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

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

![96b5c83232b4e7af089a367e38e0a003.png][]

### **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。

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

![6523029b100c84b8c860241f44f2e550.png][]

本来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、源码分析**

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

[487923156734e751815a336648757bff.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/2988985e2f274ed8865f7e4df86e3f0d.png
[ebbe0854aff58d0b6a35426afd3a3cdb.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/767cb542b0634aee9770e37c5bba477c.png
[96b5c83232b4e7af089a367e38e0a003.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/0204cea5cef34950ad3884685f5d23d4.png
[6523029b100c84b8c860241f44f2e550.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/24/89b1bda51c2442fab6eb9705108bfbc8.png