Redis持久化配置不当带来的性能问题分析
Contents [hide]
一 背景说明
两台机器，server1跑Redis缓存数据库和应用；
server2向server1的应用执行一个Redis查询请求，并持续监控该请求延迟；
server1: 172.16.17.7，4C 8G；
server2: 172.16.11.36，24C 64G；
二 分析步骤和思路
1 server1启动并验证容器正常工作
x
16
1
[root@guoxin7 ~]# docker run --name=redis -itd -p 10000:80 feisky/redis-server2
Unable to find image 'feisky/redis-server:latest' locally3
...4
be617247edfe0e7603e13db07bdf447153ae8bb7d21547465e5dbc44bc33be3b5
[root@guoxin7 ~]# docker run --name=app --network=container:redis -itd feisky/redis-app6
Unable to find image 'feisky/redis-app:latest' locally7
Trying to pull repository docker.io/feisky/redis-app ... 8
...9
ae8e5b690d0a5719c3bd646de9fac402e8bbb0446b6e9c35c90ac600455cfd7010
[root@guoxin7 ~]# docker ps11
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES12
ae8e5b690d0a feisky/redis-app "python /app.py" 2 minutes ago Up 2 minutes app13
be617247edfe feisky/redis-server "docker-entrypoint..." 3 minutes ago Up 3 minutes 6379/tcp, 0.0.0.0:10000->80/tcp redis14
[root@guoxin7 ~]# curl http://172.16.17.7:1000015
hello redis16
[root@guoxin7 ~]#2 server1初始化Redis缓存数据
1
1
[root@guoxin7 ~]# time curl http://172.16.17.7:10000/init/100002
{"elapsed_seconds":152.70450973510742,"keys_initialized":10000}3
•4
real 2m32.714s5
user 0m0.007s6
sys 0m0.006s7
[root@guoxin7 ~]# 3 server2调用接口访问server1 redis
1
1
[root@centos-master ~]# curl http://172.16.17.7:10000/get_cache2
{"count":3364,"data":["3d6bc5c4-aa48-11ec-abe1-0242ac110002",3
....4
"elapsed_seconds":62.205448150634766,"type":"good"}5
[root@centos-master ~]# 发现，通过接口调用serve1的Redis需要62秒，1分多钟，这太慢了。
4 使用top和iostat工具对server1资源使用情况分析和监测
server2对server1持续进行接口访问请求：
1
1
[root@centos-master ~]# while true; do time curl http://172.16.17.7:10000/get_cache ;sleep 10 ;done2
...3
10002"],"elapsed_seconds":46.78778529167175,"type":"good"}4
•5
real 0m46.806s6
user 0m0.007s7
sys 0m0.006s8
•然后再在server1上分别使用top监控资源使用情况：
1
16
1
[root@guoxin7 ~]# top2
top - 15:02:47 up 2 days, 4:07, 4 users, load average: 0.52, 0.39, 0.633
Tasks: 229 total, 1 running, 228 sleeping, 0 stopped, 0 zombie4
%Cpu0 : 2.7 us, 1.8 sy, 0.0 ni, 51.6 id, 43.6 wa, 0.0 hi, 0.4 si, 0.0 st5
%Cpu1 : 0.0 us, 0.0 sy, 0.0 ni, 99.6 id, 0.0 wa, 0.0 hi, 0.4 si, 0.0 st6
%Cpu2 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st7
%Cpu3 : 0.4 us, 0.4 sy, 0.0 ni, 99.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st8
KiB Mem : 41037092 total, 35626136 free, 1150372 used, 4260584 buff/cache9
KiB Swap: 8257532 total, 8257532 free, 0 used. 36866508 avail Mem 10
•11
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 12
13627 root 20 0 267236 25456 5148 S 3.5 0.1 8:34.22 python /app.py 13
13375 100 20 0 30900 9896 1140 D 1.8 0.0 4:39.50 redis-server /etc/redis.conf 14
429 root 0 -20 0 0 0 S 0.4 0.0 0:05.36 [kworker/0:1H] 15
9388 postgres 20 0 3435712 2180 1292 S 0.4 0.0 0:11.54 postgres: autovacuum launcher process 16
15286 root 20 0 162248 2504 1692 R 0.4 0.0 0:52.09 top 看到服务器上CPU资源并没有被严重消耗，同时内存资源也充足，机器整体负载也不高。但是，客户端请求Redis响应就是慢。
使用iostat -dx 1;监测系统磁盘IO情况：
1
30
1
[root@guoxin7 ~]# iostat -dx 12
Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7) 2022年03月23日 _x86_64_ (4 CPU)3
•4
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util5
sda 0.00 0.08 38.43 16.61 16146.82 1170.35 629.19 2.44 44.28 9.76 124.13 3.03 16.666
scd0 0.00 0.00 0.00 0.00 0.01 0.00 114.22 0.00 6.89 6.89 0.00 6.67 0.007
dm-0 0.00 0.00 38.43 16.70 16146.71 1170.26 628.25 2.47 44.73 9.76 125.23 3.02 16.668
dm-1 0.00 0.00 0.00 0.00 0.01 0.00 50.09 0.00 1.77 1.77 0.00 1.57 0.009
•10
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util11
sda 0.00 0.00 0.00 135.00 0.00 340.50 5.04 0.94 6.93 0.00 6.93 6.99 94.3012
scd0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0013
dm-0 0.00 0.00 0.00 135.00 0.00 343.50 5.09 0.94 6.93 0.00 6.93 6.99 94.4014
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0015
•16
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util17
sda 0.00 0.00 0.00 96.00 0.00 244.00 5.08 0.96 10.11 0.00 10.11 10.03 96.3018
scd0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0019
dm-0 0.00 0.00 0.00 96.00 0.00 244.00 5.08 0.96 10.11 0.00 10.11 10.03 96.3020
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0021
•22
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util23
sda 0.00 0.00 0.00 160.00 0.00 421.50 5.27 0.93 5.83 0.00 5.83 5.83 93.2024
scd0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0025
dm-0 0.00 0.00 0.00 160.00 0.00 421.50 5.27 0.93 5.83 0.00 5.83 5.83 93.2026
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.0027
•28
•29
^C30
[root@guoxin7 ~]# 系统的IO资源使用率偏高，随着时间的推移，当客户的请求结束时，磁盘使用率%util下降。同时，也看到随着磁盘使用率的上升和下降，磁盘的写次数w/s和wkB/s指标也响应的上升和下降。
这里有个疑问出现：客户端请求服务端的Redis，为啥服务端出现比较明显的磁盘写，而不是磁盘读？通常来讲，Redis作为缓存数据库服务来用，应该读大于写才符合常理的啊。
5 pidstat来跟踪Redis进程的磁盘IO
在server2上，通过pidstat -d -l -p redis_pid 1;命令来检测Redis进程的磁盘IO情况：
1
25
1
[root@guoxin7 ~]# pidstat -d -l -p 13375 12
Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7) 2022年03月23日 _x86_64_ (4 CPU)3
•4
15时18分24秒 UID PID kB_rd/s kB_wr/s kB_ccwr/s Command5
15时18分25秒 100 13375 0.00 212.00 0.00 redis-server /etc/redis.conf 6
15时18分26秒 100 13375 0.00 224.00 0.00 redis-server /etc/redis.conf 7
15时18分27秒 100 13375 0.00 172.00 0.00 redis-server /etc/redis.conf 8
15时18分28秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 9
15时18分29秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 10
15时18分30秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 11
15时18分31秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 12
15时18分32秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 13
15时18分33秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 14
15时18分34秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 15
15时18分35秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 16
15时18分36秒 100 13375 0.00 0.00 0.00 redis-server /etc/redis.conf 17
15时18分37秒 100 13375 0.00 40.00 0.00 redis-server /etc/redis.conf 18
15时18分38秒 100 13375 0.00 272.00 0.00 redis-server /etc/redis.conf 19
15时18分39秒 100 13375 0.00 336.00 0.00 redis-server /etc/redis.conf 20
15时18分40秒 100 13375 0.00 204.00 0.00 redis-server /etc/redis.conf 21
15时18分41秒 100 13375 0.00 284.00 0.00 redis-server /etc/redis.conf 22
15时18分42秒 100 13375 0.00 252.00 0.00 redis-server /etc/redis.conf 23
^C24
平均时间: 100 13375 0.00 110.89 0.00 redis-server /etc/redis.conf 25
[root@guoxin7 ~]# 明显可以看到，Redis后台进程的13375磁盘IO也主要是写kB_wr/s，读操作kB_rd/s为0。更为重要的是，跟随客户端调用Redis请求时，13375开始写磁盘，客户端请求停止时，看到磁盘写的值为0.
到这里，基本可以判断出客户端请求Redis响应慢的问题，基本上可以认定是Redis自身的配置或者是使用的问题了。服务器上的资源充足够用，CPU消耗不高，内存够用，缓存也稳定，几乎没有太大抖动，系统负载也不高。
6 跟踪查看Redis进程在内核的系统调用和打开文件信息
strace跟踪进程的内核调用：strace -fp 13375
1
29
1
[root@guoxin7 ~]# strace -fp 133752
...3
[pid 13375] read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n597"..., 16384) = 674
[pid 13375] read(3, 0x7ffd8bb6edf7, 1) = -1 EAGAIN (资源暂时不可用)5
[pid 13375] write(18, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n597"..., 67) = 676
[pid 13375] fdatasync(18) = 07
[pid 13375] write(8, ":1\r\n", 4) = 48
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 51, NULL, 8) = 19
[pid 13375] read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:3f57d508-"..., 16384) = 6110
[pid 13375] read(3, 0x7ffd8bb6edf7, 1) = -1 EAGAIN (资源暂时不可用)11
[pid 13375] write(8, "$3\r\nbad\r\n", 9) = 912
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 50, NULL, 8) = 113
[pid 13375] read(8, "*4\r\n$4\r\nSCAN\r\n$5\r\n13396\r\n$5\r\nMAT"..., 16384) = 4814
[pid 13375] read(3, 0x7ffd8bb6edf7, 1) = -1 EAGAIN (资源暂时不可用)15
[pid 13375] write(8, "*2\r\n$5\r\n14932\r\n*10\r\n$41\r\nuuid:53"..., 500) = 50016
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 50, NULL, 8) = 117
[pid 13375] read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:53e5509a-"..., 16384) = 6118
[pid 13375] read(3, 0x7ffd8bb6edf7, 1) = -1 EAGAIN (资源暂时不可用)19
[pid 13375] write(8, "$4\r\ngood\r\n", 10) = 1020
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 49, NULL, 8) = 121
[pid 13375] read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n53e"..., 16384) = 6722
[pid 13375] read(3, 0x7ffd8bb6edf7, 1) = -1 EAGAIN (资源暂时不可用)23
[pid 13375] write(18, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n53e"..., 67) = 6724
[pid 13375] fdatasync(18^Cstrace: Process 13375 detached25
<detached ...>26
strace: Process 13410 detached27
strace: Process 13411 detached28
strace: Process 13412 detached29
[root@guoxin7 ~]# Redis进程主要系统调用是write（），read（），和fdatasync（）以及epoll_pwait()等操作。
查看进程打开文件信息：lsof -p 13375
1
17
1
[root@guoxin7 ~]# lsof -p 133752
...3
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME4
redis-ser 13375 100 3r FIFO 0,9 0t0 6374739 pipe5
lsof: no pwd entry for UID 1006
redis-ser 13375 100 4w FIFO 0,9 0t0 6374739 pipe7
lsof: no pwd entry for UID 1008
redis-ser 13375 100 5u a_inode 0,10 0 7418 [eventpoll]9
lsof: no pwd entry for UID 10010
redis-ser 13375 100 6u sock 0,7 0t0 6374741 protocol: TCP11
lsof: no pwd entry for UID 10012
redis-ser 13375 100 8u sock 0,7 0t0 6389057 protocol: TCP13
lsof: no pwd entry for UID 10014
redis-ser 13375 100 9u sock 0,7 0t0 6598637 protocol: TCP15
lsof: no pwd entry for UID 10016
redis-ser 13375 100 18w REG 253,0 1125462 210213898 /data/appendonly.aof17
[root@guoxin7 ~]# Redis进程在写文件描述符为18号的文件，读取3号文件是pipe,以及8号文件的TCP Socket文件。
7 调整Redis的持久化配置参数
进入Redis container里，查看Redis的持久化配置：
1
11
1
#1 先进入Redis container2
[root@guoxin7 ~]# docker exec -it redis /bin/sh3
#2 redis-cli连接到Redis4
/data # redis-cli 5
#3 查看持久化配置6
127.0.0.1:6379> CONFIG GET 'append*'7
1) "appendfsync"8
2) "always"9
3) "appendonly"10
4) "yes"11
127.0.0.1:6379> 这里，看到当前的Redis持久化存储方式采用的是AOF (Append Only File)，即追加文件的方式。并且配置(“appendfsync”=”always”)的是每新增一个key-value，就把它持久化写入到文件里，防止内存中的这个key-value丢失。
我们这里尝试把Redis的持久化方式改为”appendfsync”=”no”，即不是每次都要实时写出追加到文件，而是交给文件系统去处理的方式。
1
15
1
127.0.0.1:6379> CONFIG SET appendfsync=no2
(error) ERR Unknown subcommand or wrong number of arguments for 'SET'. Try CONFIG HELP.3
127.0.0.1:6379> CONFIG SET "appendfsync"="no"4
Invalid argument(s)5
127.0.0.1:6379> CONFIG SET appendfsync no6
OK7
127.0.0.1:6379> CONFIG GET appendfsync8
1) "appendfsync"9
2) "no"10
127.0.0.1:6379> CONFIG GET 'append*'11
1) "appendfsync"12
2) "no"13
3) "appendonly"14
4) "yes"15
127.0.0.1:6379> 然后，观察客户端发送的Redis请求从之前的耗时60秒左右，降低到1-2秒左右。
1
1
[root@centos-master ~]# while true; do time curl http://172.16.17.7:10000/get_cache ;sleep 10 ;done2
... "elapsed_seconds":2.073829174041748,"type":"good"}3
•4
real 0m2.089s5
user 0m0.003s6
sys 0m0.009s并且，服务端也不再看到Redis进程频繁的磁盘写操作了。
三 小结和收获
1 思路
客户端发起Redis调用请求耗时偏高，服务端监控到CPU、内存、负载、系统缓存都比较正常；此时，不能判断没有性能问题，客户端请求延迟很高，继续跟踪Redis进程的磁盘IO情况(pidstat -d -l -p redis_pid 1;)，strace -fp redis_pid;和lsof -p redis_pid;查看Redis进程在内核中的系统调用和打开文件信息；判断问题基本上是Redis自身的配置和使用不对；
2 学习了Redis的持久化不同配置方案
详细的信息，可以从Redis官网查看：https://redis.io/topics/persistence
3 主机资源正常不代表没有性能问题
此案例中，服务端监控到CPU、内存、负载、系统缓存都比较正常；此时，不能判断没有性能问题，
4 Redis的异常写操作
Redis的异常写操作和当前的场景不太吻合，客户端发起Redis调用请求，查询缓存数据库，不应该在服务器端看到明显的Redis写请求操作。
四 参考和链接
倪朋飞老师的Linux性能优化实战，29 | 案例篇：Redis响应严重延迟，如何解决？
Redis官网关于持久化配置查看：https://redis.io/topics/persistence
一条评论
Pingback: