谁动了我的Redis？频繁AOF重写
作者:快盘下载 人气:容器化redis服务频繁AOF重写
今天来看线上的一个Redis案例。
01背景介绍
线上的一个Redis实例频繁进行aof重写，进入redis的数据目录，可以看到下面的场景：
我们可以看到:
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左右，但是后面有一堆锯齿，内存有升高然后再降低，一直重复的过程。
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占用的内存有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会发生什么情况？有兴趣可以自己动手测试一下。
加载全部内容