Redis持久化配置不当带来的性能问题分析

Contents

1 一背景说明
2 二分析步骤和思路
3 三小结和收获
4 四参考和链接

一背景说明

两台机器，server1跑Redis缓存数据库和应用；

server2向server1的应用执行一个Redis查询请求，并持续监控该请求延迟；

server1: 172.16.17.7，4C 8G；

server2: 172.16.11.36，24C 64G；

二分析步骤和思路

1 server1启动并验证容器正常工作

[root@guoxin7 ~]# docker run --name=redis -itd -p 10000:80 feisky/redis-server
Unable to find image 'feisky/redis-server:latest' locally
...
be617247edfe0e7603e13db07bdf447153ae8bb7d21547465e5dbc44bc33be3b
[root@guoxin7 ~]# docker run --name=app --network=container:redis -itd feisky/redis-app
Unable to find image 'feisky/redis-app:latest' locally
Trying to pull repository docker.io/feisky/redis-app ... 
...
ae8e5b690d0a5719c3bd646de9fac402e8bbb0446b6e9c35c90ac600455cfd70
[root@guoxin7 ~]# docker ps
CONTAINER ID        IMAGE                 COMMAND                  CREATED             STATUS              PORTS                             NAMES
ae8e5b690d0a        feisky/redis-app      "python /app.py"         2 minutes ago       Up 2 minutes                                          app
be617247edfe        feisky/redis-server   "docker-entrypoint..."   3 minutes ago       Up 3 minutes        6379/tcp, 0.0.0.0:10000->80/tcp   redis
[root@guoxin7 ~]# curl http://172.16.17.7:10000
hello redis
[root@guoxin7 ~]#

2 server1初始化Redis缓存数据

[root@guoxin7 ~]# time curl http://172.16.17.7:10000/init/10000
{"elapsed_seconds":152.70450973510742,"keys_initialized":10000}

real    2m32.714s
user    0m0.007s
sys     0m0.006s
[root@guoxin7 ~]#

3 server2调用接口访问server1 redis

[root@centos-master ~]# curl http://172.16.17.7:10000/get_cache
{"count":3364,"data":["3d6bc5c4-aa48-11ec-abe1-0242ac110002",
....
"elapsed_seconds":62.205448150634766,"type":"good"}
[root@centos-master ~]#

发现，通过接口调用serve1的Redis需要62秒，1分多钟，这太慢了。

4 使用top和iostat工具对server1资源使用情况分析和监测

server2对server1持续进行接口访问请求：

[root@centos-master ~]# while true; do time curl http://172.16.17.7:10000/get_cache ;sleep 10 ;done
...
10002"],"elapsed_seconds":46.78778529167175,"type":"good"}

real    0m46.806s
user    0m0.007s
sys     0m0.006s

然后再在server1上分别使用top监控资源使用情况：

[root@guoxin7 ~]# top
top - 15:02:47 up 2 days,  4:07,  4 users,  load average: 0.52, 0.39, 0.63
Tasks: 229 total,   1 running, 228 sleeping,   0 stopped,   0 zombie
%Cpu0  :  2.7 us,  1.8 sy,  0.0 ni, 51.6 id, 43.6 wa,  0.0 hi,  0.4 si,  0.0 st
%Cpu1  :  0.0 us,  0.0 sy,  0.0 ni, 99.6 id,  0.0 wa,  0.0 hi,  0.4 si,  0.0 st
%Cpu2  :  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu3  :  0.4 us,  0.4 sy,  0.0 ni, 99.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 41037092 total, 35626136 free,  1150372 used,  4260584 buff/cache
KiB Swap:  8257532 total,  8257532 free,        0 used. 36866508 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                           
13627 root      20   0  267236  25456   5148 S   3.5  0.1   8:34.22 python /app.py                                                                                                    
13375 100       20   0   30900   9896   1140 D   1.8  0.0   4:39.50 redis-server /etc/redis.conf                                                                                      
  429 root       0 -20       0      0      0 S   0.4  0.0   0:05.36 [kworker/0:1H]                                                                                                    
 9388 postgres  20   0 3435712   2180   1292 S   0.4  0.0   0:11.54 postgres: autovacuum launcher process                                                                             
15286 root      20   0  162248   2504   1692 R   0.4  0.0   0:52.09 top

看到服务器上CPU资源并没有被严重消耗，同时内存资源也充足，机器整体负载也不高。但是，客户端请求Redis响应就是慢。

使用iostat -dx 1;监测系统磁盘IO情况：

[root@guoxin7 ~]# iostat -dx 1
Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7)     2022年03月23日  _x86_64_        (4 CPU)

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
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.66
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.00
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.66
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.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
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.30
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.00
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.40
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.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
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.30
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.00
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.30
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.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
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.20
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.00
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.20
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.00


^C
[root@guoxin7 ~]#

系统的IO资源使用率偏高，随着时间的推移，当客户的请求结束时，磁盘使用率%util下降。同时，也看到随着磁盘使用率的上升和下降，磁盘的写次数w/s和wkB/s指标也响应的上升和下降。

这里有个疑问出现：客户端请求服务端的Redis，为啥服务端出现比较明显的磁盘写，而不是磁盘读？通常来讲，Redis作为缓存数据库服务来用，应该读大于写才符合常理的啊。

5 pidstat来跟踪Redis进程的磁盘IO

在server2上，通过pidstat -d -l -p redis_pid 1;命令来检测Redis进程的磁盘IO情况：

[root@guoxin7 ~]# pidstat -d -l -p 13375 1
Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7)     2022年03月23日  _x86_64_        (4 CPU)

15时18分24秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
15时18分25秒   100     13375      0.00    212.00      0.00  redis-server /etc/redis.conf 
15时18分26秒   100     13375      0.00    224.00      0.00  redis-server /etc/redis.conf 
15时18分27秒   100     13375      0.00    172.00      0.00  redis-server /etc/redis.conf 
15时18分28秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分29秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分30秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分31秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分32秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分33秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分34秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分35秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分36秒   100     13375      0.00      0.00      0.00  redis-server /etc/redis.conf 
15时18分37秒   100     13375      0.00     40.00      0.00  redis-server /etc/redis.conf 
15时18分38秒   100     13375      0.00    272.00      0.00  redis-server /etc/redis.conf 
15时18分39秒   100     13375      0.00    336.00      0.00  redis-server /etc/redis.conf 
15时18分40秒   100     13375      0.00    204.00      0.00  redis-server /etc/redis.conf 
15时18分41秒   100     13375      0.00    284.00      0.00  redis-server /etc/redis.conf 
15时18分42秒   100     13375      0.00    252.00      0.00  redis-server /etc/redis.conf 
^C
平均时间:   100     13375      0.00    110.89      0.00  redis-server /etc/redis.conf 
[root@guoxin7 ~]#

明显可以看到，Redis后台进程的13375磁盘IO也主要是写kB_wr/s，读操作kB_rd/s为0。更为重要的是，跟随客户端调用Redis请求时，13375开始写磁盘，客户端请求停止时，看到磁盘写的值为0.

到这里，基本可以判断出客户端请求Redis响应慢的问题，基本上可以认定是Redis自身的配置或者是使用的问题了。服务器上的资源充足够用，CPU消耗不高，内存够用，缓存也稳定，几乎没有太大抖动，系统负载也不高。

6 跟踪查看Redis进程在内核的系统调用和打开文件信息

strace跟踪进程的内核调用：strace -fp 13375

[root@guoxin7 ~]# strace -fp 13375
...
[pid 13375] read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n597"..., 16384) = 67
[pid 13375] read(3, 0x7ffd8bb6edf7, 1)  = -1 EAGAIN (资源暂时不可用)
[pid 13375] write(18, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n597"..., 67) = 67
[pid 13375] fdatasync(18)               = 0
[pid 13375] write(8, ":1\r\n", 4)       = 4
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 51, NULL, 8) = 1
[pid 13375] read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:3f57d508-"..., 16384) = 61
[pid 13375] read(3, 0x7ffd8bb6edf7, 1)  = -1 EAGAIN (资源暂时不可用)
[pid 13375] write(8, "$3\r\nbad\r\n", 9) = 9
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 50, NULL, 8) = 1
[pid 13375] read(8, "*4\r\n$4\r\nSCAN\r\n$5\r\n13396\r\n$5\r\nMAT"..., 16384) = 48
[pid 13375] read(3, 0x7ffd8bb6edf7, 1)  = -1 EAGAIN (资源暂时不可用)
[pid 13375] write(8, "*2\r\n$5\r\n14932\r\n*10\r\n$41\r\nuuid:53"..., 500) = 500
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 50, NULL, 8) = 1
[pid 13375] read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:53e5509a-"..., 16384) = 61
[pid 13375] read(3, 0x7ffd8bb6edf7, 1)  = -1 EAGAIN (资源暂时不可用)
[pid 13375] write(8, "$4\r\ngood\r\n", 10) = 10
[pid 13375] epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 49, NULL, 8) = 1
[pid 13375] read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n53e"..., 16384) = 67
[pid 13375] read(3, 0x7ffd8bb6edf7, 1)  = -1 EAGAIN (资源暂时不可用)
[pid 13375] write(18, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n53e"..., 67) = 67
[pid 13375] fdatasync(18^Cstrace: Process 13375 detached
 <detached ...>
strace: Process 13410 detached
strace: Process 13411 detached
strace: Process 13412 detached
[root@guoxin7 ~]#

Redis进程主要系统调用是write（），read（），和fdatasync（）以及epoll_pwait()等操作。

查看进程打开文件信息：lsof -p 13375

[root@guoxin7 ~]# lsof -p 13375
...
COMMAND     PID     USER   FD      TYPE DEVICE SIZE/OFF      NODE NAME
redis-ser 13375      100    3r     FIFO    0,9      0t0   6374739 pipe
lsof: no pwd entry for UID 100
redis-ser 13375      100    4w     FIFO    0,9      0t0   6374739 pipe
lsof: no pwd entry for UID 100
redis-ser 13375      100    5u  a_inode   0,10        0      7418 [eventpoll]
lsof: no pwd entry for UID 100
redis-ser 13375      100    6u     sock    0,7      0t0   6374741 protocol: TCP
lsof: no pwd entry for UID 100
redis-ser 13375      100    8u     sock    0,7      0t0   6389057 protocol: TCP
lsof: no pwd entry for UID 100
redis-ser 13375      100    9u     sock    0,7      0t0   6598637 protocol: TCP
lsof: no pwd entry for UID 100
redis-ser 13375      100   18w      REG  253,0  1125462 210213898 /data/appendonly.aof
[root@guoxin7 ~]#

Redis进程在写文件描述符为18号的文件，读取3号文件是pipe,以及8号文件的TCP Socket文件。

7 调整Redis的持久化配置参数

进入Redis container里，查看Redis的持久化配置：

#1 先进入Redis container
[root@guoxin7 ~]# docker exec -it redis /bin/sh
#2 redis-cli连接到Redis
/data # redis-cli 
#3 查看持久化配置
127.0.0.1:6379> CONFIG GET 'append*'
1) "appendfsync"
2) "always"
3) "appendonly"
4) "yes"
127.0.0.1:6379>

这里，看到当前的Redis持久化存储方式采用的是AOF (Append Only File)，即追加文件的方式。并且配置(“appendfsync”=”always”)的是每新增一个key-value，就把它持久化写入到文件里，防止内存中的这个key-value丢失。

我们这里尝试把Redis的持久化方式改为”appendfsync”=”no”，即不是每次都要实时写出追加到文件，而是交给文件系统去处理的方式。

127.0.0.1:6379> CONFIG SET appendfsync=no
(error) ERR Unknown subcommand or wrong number of arguments for 'SET'. Try CONFIG HELP.
127.0.0.1:6379> CONFIG SET "appendfsync"="no"
Invalid argument(s)
127.0.0.1:6379> CONFIG SET appendfsync no
OK
127.0.0.1:6379> CONFIG GET appendfsync
1) "appendfsync"
2) "no"
127.0.0.1:6379> CONFIG GET 'append*'
1) "appendfsync"
2) "no"
3) "appendonly"
4) "yes"
127.0.0.1:6379>

然后，观察客户端发送的Redis请求从之前的耗时60秒左右，降低到1-2秒左右。

[root@centos-master ~]# while true; do time curl http://172.16.17.7:10000/get_cache ;sleep 10 ;done
... "elapsed_seconds":2.073829174041748,"type":"good"}

real    0m2.089s
user    0m0.003s
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

Post Views: 2,866

Redis持久化配置不当带来的性能问题分析

一背景说明

二分析步骤和思路

1 server1启动并验证容器正常工作

2 server1初始化Redis缓存数据

3 server2调用接口访问server1 redis

4 使用top和iostat工具对server1资源使用情况分析和监测

5 pidstat来跟踪Redis进程的磁盘IO

6 跟踪查看Redis进程在内核的系统调用和打开文件信息

7 调整Redis的持久化配置参数

三小结和收获

1 思路

2 学习了Redis的持久化不同配置方案

3 主机资源正常不代表没有性能问题

4 Redis的异常写操作

四参考和链接

一条评论

Pingback:

留言取消回复

一 背景说明

二 分析步骤和思路

1 server1启动并验证容器正常工作

2 server1初始化Redis缓存数据

3 server2调用接口访问server1 redis

4 使用top和iostat工具对server1资源使用情况分析和监测

5 pidstat来跟踪Redis进程的磁盘IO

6 跟踪查看Redis进程在内核的系统调用和打开文件信息

7 调整Redis的持久化配置参数

三 小结和收获

1 思路

2 学习了Redis的持久化不同配置方案

3 主机资源正常不代表没有性能问题

4 Redis的异常写操作

四 参考和链接

您可能也喜欢

如何手工启停PostgreSQL数据库

如何使用parted来管理存储空间大于2TB的磁盘设备

如何在CentOS上源码安装PostgreSQL数据库

一条评论

Pingback:

留言 取消回复

一背景说明

二分析步骤和思路

三小结和收获

四参考和链接

留言取消回复