基础：redis响应严重延迟，如何解决

- 日理万妓 2022-09-17 04:28 270阅读 0赞

# 引言 #

MySQL的MyISAM引擎，主要依赖系统缓存加速磁盘IO的访问。可如果系统中还有其他应用同时运行，MyISAM引擎很难充分利用系统缓存。缓存可能被其他系统占据，甚至被清理掉。

所以，一般不建议，把应用程序的性能优化完全建立在系统缓存上。最好能在应用程序的内部分配内存，构建完全自动控制的缓存；或者使用第三方的缓存应用，比如memcache，redis等

redis是最常用的键值存储系统之一，常用作数据库、高速缓存、消息队列代理等。redis基于内存来存储数据，不过，为了保证在服务器异常时数据不丢失，很多情况下，我们要为它配置持久化，这就可能会引发磁盘IO的性能问题。

# 案例 #

这是⼀个基于 Python Flask 的应⽤程序，它提供了⼀个 查询缓存的接⼝，但接⼝的响应时间⽐较⻓，并不能满⾜线上系统的要求。

## 准备 ##

*  机器配置：2 CPU，8GB 内存
 *  预先安装 docker、sysstat 、git、make 等⼯具，如 apt installdocker.io sysstat

今天的案例由 Python应⽤+Redis 两部分组成。其中，Python 应⽤是⼀个基于 Flask 的应⽤，它会利⽤ Redis ，来管理应⽤程序的缓存，并对外提供三个 HTTP 接⼝：

*  /：返回 hello redis；
 *  /init/：插⼊指定数量的缓存数据，如果不指定数量，默认的是 5000 条；
 *  缓存的键格式为 uuid:
 *  缓存的值为 good、bad 或 normal 三者之⼀
 *  /get\_cache/< type\_name>：查询指定值的缓存数据，并返回处理时间。其中，type\_name 参数只⽀持 good, bad 和  
    normal（也就是找出具有相同 value 的 key 列表）。

今天的案例需要两台虚拟机，其中⼀台⽤作案例分析的⽬标机器，运⾏ Flask 应⽤，它的 IP 地址是 192.168.0.10；⽽另⼀台作为客户端，请求缓存查询接⼝。  
![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_18_color_FFFFFF_t_70_g_se_x_16]  
接下来，打开两个终端，分别 SSH 登录到这两台虚拟机中，并在第⼀台虚拟机中安装上述⼯具。

## 分析 ##

⾸先，我们在第⼀个终端中，执⾏下⾯的命令，运⾏本次案例要分析的⽬标应⽤。正常情况下，你应该可以看到下⾯的输出：

# 注意下⾯的随机字符串是容器ID，每次运⾏均会不同，并且你不需要关注它
    $ docker run --name=redis -itd -p 10000:80 feisky/redis-server
    ec41cb9e4dd5cb7079e1d9f72b7cee7de67278dbd3bd0956b4c0846bff211803
    $ docker run --name=app --network=container:redis -itd feisky/redis-app
    2c54eb252d0552448320d9155a2618b799a1e71d7289ec7277a61e72a9de5fd0

然后，再运⾏ docker ps 命令，确认两个容器都处于运⾏（Up）状态：

$ docker ps
    CONTAINER ID        IMAGE                 COMMAND                  CREATED             STATUS              PORTS                             NAMES
    2c54eb252d05        feisky/redis-app      "python /app.py"         48 seconds ago      Up 47 seconds                                         app
    ec41cb9e4dd5        feisky/redis-server   "docker-entrypoint.s…"   49 seconds ago      Up 48 seconds       6379/tcp, 0.0.0.0:10000->80/tcp   redis

今天的应⽤在 10000 端⼝监听，所以你可以通过http://192.168.0.10:10000 ，来访问前⾯提到的三个接⼝。

⽐如，我们切换到第⼆个终端，使⽤ curl ⼯具，访问应⽤⾸⻚。如果你看到 hello redis 的输出，说明应⽤正常启动：

$ curl http://192.168.0.10:10000/
    hello redis

接下来，继续在终端⼆中，执⾏下⾯的 curl 命令，来调⽤应⽤的 /init 接⼝，初始化 Redis 缓存，并且插⼊ 5000 条缓存信息。这个过程⽐较慢：

# 案例插⼊5000条数据，在实践时可以根据磁盘的类型适当调整，⽐如使⽤SSD时可以调⼤，⽽HDD可以适当调⼩
    $ curl http://192.168.0.10:10000/init/5000
    {
        "elapsed_seconds":30.26814079284668,"keys_initialized":5000}

继续执⾏下⼀个命令，访问应⽤的缓存查询接⼝。如果⼀切正常，你会看到如下输出：

$ curl http://192.168.0.10:10000/get_cache
    {
        "count":1677,"data":["d97662fa-06ac-11e9-92c7-0242ac110002",...],"elapsed_seconds":10.545469760894775,"type":"good"}

我们看到，这个接⼝调⽤居然要花 10 秒！这么⻓的响应时间，显然不能满⾜实际的应⽤需求。

到底出了什么问题呢？我们还是要⽤前⾯学过的性能⼯具和原理，来找到这个瓶颈。

不过别急，同样为了避免分析过程中客户端的请求结束，在进⾏性能分析前，我们先要把 curl 命令放到⼀个循环⾥来执⾏。

你可以在终端⼆中，继续执⾏下⾯的命令：

$ while true; do curl http://192.168.0.10:10000/get_cache; done

接下来，再重新回到终端⼀，查找接⼝响应慢的“病因”。

响应慢，我们自然会先怀疑，是不是系统资源出了问题。所以，先观察CPU、内存和磁盘IO等的使用情况。

我们先在终端⼀中执⾏ top 命令，分析系统的 CPU 使⽤情况：

$ top
    top - 12:46:18 up 11 days,  8:49,  1 user,  load average: 1.36, 1.36, 1.04
    Tasks: 137 total,   1 running,  79 sleeping,   0 stopped,   0 zombie
    %Cpu0  :  6.0 us,  2.7 sy,  0.0 ni,  5.7 id, 84.7 wa,  0.0 hi,  1.0 si,  0.0 st
    %Cpu1  :  1.0 us,  3.0 sy,  0.0 ni, 94.7 id,  0.0 wa,  0.0 hi,  1.3 si,  0.0 st
    KiB Mem :  8169300 total,  7342244 free,   432912 used,   394144 buff/cache
    KiB Swap:        0 total,        0 free,        0 used.  7478748 avail Mem
    
      PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
     9181 root      20   0  193004  27304   8716 S   8.6  0.3   0:07.15 python
     9085 systemd+  20   0   28352   9760   1860 D   5.0  0.1   0:04.34 redis-server
      368 root      20   0       0      0      0 D   1.0  0.0   0:33.88 jbd2/sda1-8
      149 root       0 -20       0      0      0 I   0.3  0.0   0:10.63 kworker/0:1H
     1549 root      20   0  236716  24576   9864 S   0.3  0.3  91:37.30 python3

观察top的输出可以发现，CPU0的iowait比较高，已经达到了84%；而各个进程的CPU使用率都不太高，最高的python和redis-server，也分别只有 8% 和 5%。再看内存，总内存 8GB，剩余内存还有 7GB多，显然内存也没啥问题。

综合top的信息，最有嫌疑的是iowait。所以，接下来还是要继续分析，是不是io问题。

>  *  iowait不代表磁盘I/O存在瓶颈，只是代表CPU上I/O操作的时间占⽤的百分⽐。假如这时候没有其他进程在运⾏，那么很⼩的I/O就会导致iowait升⾼
> 
>  *  只⽤iowait不能说明磁盘瓶颈，需要⽤ iostat

还在第⼀个终端中，先按下 Ctrl+C，停⽌ top 命令；然后，执⾏下⾯的 iostat 命令，查看有没有 I/O 性能问题：

$ iostat -d -x 1
    Device            r/s     w/s     rkB/s     wkB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util
    ...
    sda              0.00  492.00      0.00   2672.00     0.00   176.00   0.00  26.35    0.00    1.76   0.00     0.00     5.43   0.00   0.00

观察 iostat 的输出，我们发现，磁盘 sda 每秒的写数据（wkB/s）为 2.5MB，I/O 使⽤率（%util）是 0。看来，虽然有些io操作，但并没有导致磁盘的IO瓶颈。

排查⼀圈⼉下来，CPU和内存使⽤没问题，I/O 也没有瓶颈，接下来好像就没啥分析⽅向了？

碰到这种情况，还是那句话，反思⼀下，是不是⼜漏掉什么有⽤线索了。

回想一下，今天的案例问题是从redis缓存中查询数据慢。对查询来说，对应的IO应该是磁盘的读操作，但刚才我们用iostat看到的确是写操作。虽然IO本身并没有性能瓶颈，但这里的磁盘写也是比较奇怪的。为什会有磁盘写呢？那我们就得知道，到底是哪个进行在写磁盘。

pidstat工具可以观察进程的IO情况，从而得到IO请求来自哪些进程：

$ pidstat -d 1
    12:49:35      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
    12:49:36        0       368      0.00     16.00      0.00      86  jbd2/sda1-8
    12:49:36      100      9085      0.00    636.00      0.00       1  redis-server

从 pidstat 的输出，我们看到，I/O 最多的进程是 PID 为 9085 的 redis-server，并且它也刚好是在写磁盘。这说明，确实是redis-server 在进⾏磁盘写。

当然，光找到读写磁盘的进程还不够，我们还要再⽤ strace+lsof 组合，看看 redis-server 到底在写什么。

接下来，还是在终端⼀中，执⾏ strace 命令，并且指定 redis-server 的进程号 9085：

# -f表示跟踪子进程和子线程，-T表示显示系统调用的时长，-tt表示显示跟踪时间
    $ strace -f -T -tt -p 9085
    [pid  9085] 14:20:16.826131 epoll_pwait(5, [{
        EPOLLIN, {
        u32=8, u64=8}}], 10128, 65, NULL, 8) = 1 <0.000055>
    [pid  9085] 14:20:16.826301 read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:5b2e76cc-"..., 16384) = 61 <0.000071>
    [pid  9085] 14:20:16.826477 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000063>
    [pid  9085] 14:20:16.826645 write(8, "$3\r\nbad\r\n", 9) = 9 <0.000173>
    [pid  9085] 14:20:16.826907 epoll_pwait(5, [{
        EPOLLIN, {
        u32=8, u64=8}}], 10128, 65, NULL, 8) = 1 <0.000032>
    [pid  9085] 14:20:16.827030 read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:55862ada-"..., 16384) = 61 <0.000044>
    [pid  9085] 14:20:16.827149 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000043>
    [pid  9085] 14:20:16.827285 write(8, "$3\r\nbad\r\n", 9) = 9 <0.000141>
    [pid  9085] 14:20:16.827514 epoll_pwait(5, [{
        EPOLLIN, {
        u32=8, u64=8}}], 10128, 64, NULL, 8) = 1 <0.000049>
    [pid  9085] 14:20:16.827641 read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:53522908-"..., 16384) = 61 <0.000043>
    [pid  9085] 14:20:16.827784 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000034>
    [pid  9085] 14:20:16.827945 write(8, "$4\r\ngood\r\n", 10) = 10 <0.000288>
    [pid  9085] 14:20:16.828339 epoll_pwait(5, [{
        EPOLLIN, {
        u32=8, u64=8}}], 10128, 63, NULL, 8) = 1 <0.000057>
    [pid  9085] 14:20:16.828486 read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 16384) = 67 <0.000040>
    [pid  9085] 14:20:16.828623 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000052>
    [pid  9085] 14:20:16.828760 write(7, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 67) = 67 <0.000060>
    [pid  9085] 14:20:16.828970 fdatasync(7) = 0 <0.005415>
    [pid  9085] 14:20:16.834493 write(8, ":1\r\n", 4) = 4 <0.000250>

从上面可以看出，epoll\_wait、read、write、fdatasync这些系统调用都比较频繁。那么，刚才观察到的写磁盘，应该就是write或者fdatasync导致的了。

接着再来运⾏ lsof 命令，找出这些系统调⽤的操作对象：

$ lsof -p 9085
    redis-ser 9085 systemd-network 3r FIFO 0,12 0t0 15447970 pipe
    redis-ser 9085 systemd-network 4w FIFO 0,12 0t0 15447970 pipe
    redis-ser 9085 systemd-network 5u a_inode 0,13 0 10179 [eventpoll]
    redis-ser 9085 systemd-network 6u sock 0,9 0t0 15447972 protocol: TCP
    redis-ser 9085 systemd-network 7w REG 8,1 8830146 2838532 /data/appendonly.aof
    redis-ser 9085 systemd-network 8u sock 0,9 0t0 15448709 protocol: TCP

现在你会发现，描述符编号为 3 的是⼀个 pipe 管道，5 号是 eventpoll，7 号是⼀个普通⽂件，⽽ 8 号是⼀个 TCP socket。

结合磁盘写的线程，我们知道，只有7号普通文件才会产生磁盘写，而它操作的文件路径是 /data/appendonly.aof，相应的系统调用包括write和fdatasync。

上面的文件路径和fdatasync的系统调用，对应的就是redis持久化配置中的appendonly和appendfync选项。很可能就是因为它们的配置不合理，导致磁盘写比较多。

接下来就验证⼀下这个猜测，我们可以通过 Redis 的命令⾏⼯具，查询这两个选项的配置。

继续在终端⼀中，运⾏下⾯的命令，查询 appendonly 和 appendfsync 的配置：

$ docker exec -it redis redis-cli config get 'append*'
    1) "appendfsync"
    2) "always"
    3) "appendonly"
    4) "yes"

从这个结果你可以发现，appendfsync 配置的是 always，⽽ appendonly 配置的是 yes。

> redis提供了两种数据持久化方式，分别是快照和追加文件
> 
>  *  **快照方式**：
>     
>      *  会按照指定的时间间隔，生成数据的快照，并且保存到磁盘文件中。
>      *  为了避免阻塞主进程，redis还会fork出一个子进程，来负责快照的保存。
>      *  这种方式的性能好，无论是备份还是恢复，都比追加文件好很多。
>      *  不过，它的缺点也很明显。在数据量大时，fork子进程需要用到比较大的内存，保存数据也很耗时。所以，你需要设置一个比较长的时间间隔来应对，比如至少5分钟。这样，如果发生故障，你丢失的就是几分钟的数据
>  *  **追加方式**：
>     
>      *  是用在文件末尾追加记录的方式，对redis写入的数据，一次进行持久化，所以它的持久化也更安全。
>      *  此外，，它还提供了⼀个⽤ appendfsync 选项设置 fsync 的策略，确保写⼊的数据都落到磁盘中，具体选项包括 always、everysec、no 等。
>         
>          *  always表示，每个操作都会执⾏⼀次 fsync，是最为安全的⽅式；
>      *  everysec表示，每秒钟调⽤⼀次 fsync ，这样可以保证即使是最坏情况下，也只丢失1秒的数据；
>      *  ⽽ no 表示交给操作系统来处理

appendfsync配置的是always，意味着每次写数据时，都会调用一次fsync，从而造成比较大的磁盘IO压力。

当然，你还可以⽤ strace ，观察这个系统调⽤的执⾏情况。⽐如通过 -e 选项指定 fdatasync 后，你就会得到下⾯的结果：

$ strace -f -p 9085 -T -tt -e fdatasync
    strace: Process 9085 attached with 4 threads
    [pid 9085] 14:22:52.013547 fdatasync(7) = 0 <0.007112>
    [pid 9085] 14:22:52.022467 fdatasync(7) = 0 <0.008572>
    [pid 9085] 14:22:52.032223 fdatasync(7) = 0 <0.006769>
    ...
    [pid 9085] 14:22:52.139629 fdatasync(7) = 0 <0.008183>

从这⾥你可以看到，每隔 10ms 左右，就会有⼀次 fdatasync 调⽤，并且每次调⽤本身也要消耗 7~8ms。

不管哪种⽅式，都可以验证我们的猜想，配置确实不合理。这样，我们就找出了 Redis 正在进⾏写⼊的⽂件，也知道了产⽣  
⼤量 I/O 的原因。

> 不过，为什么查询时会有磁盘写呢？按理来说不应该只有数据的读取吗？

这就需要我们再来审查⼀下 strace -f -T -tt -p 9085 的结果。

read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:53522908-"..., 16384)
    write(8, "$4\r\ngood\r\n", 10)
    read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 16384)
    write(7, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 67)
    write(8, ":1\r\n", 4)

根据 lsof 的分析，⽂件描述符编号为 7 的是⼀个普通⽂件 /data/appendonly.aof，⽽编号为8的是TCP socket。观察上面的内容，8号对应的是TCP读写，是一个标准的“请求-响应”格式。

*  从 socket 读取 GET uuid:53522908-… 后，响应 good；
 *  再从 socket 读取 SADD good 535… 后，响应 1。

对redis来说，SADD是一个写操作，所以redis还会把它保存到用于持久化的appendonly.aof文件中。

观察更多的 strace 结果，你会发现，每当 GET 返回 good 时，随后都会有⼀个 SADD 操作，这也就导致了，明明是查询接⼝，Redis 却有⼤量的磁盘写。

到这⾥，我们就找出了 Redis 写磁盘的原因。不过，在下最终结论前，我们还是要确认⼀下，8 号 TCP socket 对应的 Redis客户端，到底是不是我们的案例应⽤。

我们可以给 lsof 命令加上 -i 选项，找出 TCP socket 对应的 TCP 连接信息。不过，由于 Redis 和 Python 应⽤都在容器中运⾏，我们需要进⼊容器的⽹络命名空间内部，才能看到完整的 TCP 连接。

注意：下⾯的命令⽤到的 nsenter ⼯具，可以进⼊容器命名空间。如果你的系统没有安装，请运⾏下⾯命令安装 nsenter：  
docker run --rm -v /usr/local/bin:/target jpetazzo/nsenter

还是在终端⼀中，运⾏下⾯的命令：

# 由于这两个容器共享同一个网络命名空间，所以我们只需要进入app的网络命名空间即可
    $ PID=$(docker inspect --format {
         {
         .State.Pid}} app)
    # -i表示显示网络套接字信息
    $ nsenter --target $PID --net -- lsof -i
    COMMAND    PID            USER   FD   TYPE   DEVICE SIZE/OFF NODE NAME
    redis-ser 9085 systemd-network    6u  IPv4 15447972      0t0  TCP localhost:6379 (LISTEN)
    redis-ser 9085 systemd-network    8u  IPv4 15448709      0t0  TCP localhost:6379->localhost:32996 (ESTABLISHED)
    python    9181            root    3u  IPv4 15448677      0t0  TCP *:http (LISTEN)
    python    9181            root    5u  IPv4 15449632      0t0  TCP localhost:32996->localhost:6379 (ESTABLISHED)

这次我们可以看到，redis-server 的 8 号⽂件描述符，对应 TCP 连接 localhost:6379->localhost:32996。其中，localhost:6379 是 redis-server ⾃⼰的监听端⼝，⾃然 localhost:32996 就是 redis 的客户端。再观察最后⼀⾏，localhost:32996 对应的，正是我们的 Python 应⽤程序（进程号为 9181）。

历经各种波折，我们总算找出了 Redis 响应延迟的潜在原因。总结⼀下，我们找到两个问题。

*  第一个问题，redis配置的appendfsync是always，这就导致redis每次的写操作，都会触发fdatasync系统调用。没必要⽤这么⾼频的同步写，使⽤默认的 1s 时间间隔，就⾜够了。
 *  第二个问题，python应用在查询接口中会调用redis的sadd命令，这很可能是不合理的使用缓存导致的

对于第⼀个配置问题，我们可以执⾏下⾯的命令，把 appendfsync 改成 everysec：

$ docker exec -it redis redis-cli config set appendfsync everysec
    OK

改完后，切换到终端⼆中查看，你会发现，现在的请求时间，已经缩短到了 0.9s：

{
        ..., "elapsed_seconds":0.9368953704833984,"type":"good"}

⽽第⼆个问题，就要查看应⽤的源码了。  
![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_13_color_FFFFFF_t_70_g_se_x_16]  
果然，Python 应⽤把 Redis 当成临时空间，⽤来存储查询过程中找到的数据。不过我们知道，这些数据放内存中就可以了，完全没必要再通过⽹络调⽤存储到 Redis 中。

基于这个思路，我把修改后的代码也推送到了相同的源码⽂件中，你可以通过http://192.168.0.10:10000/get\_cache\_data 这个接⼝来访问它。

我们切换到终端⼆，按 Ctrl+C 停⽌之前的 curl 命令；然后执⾏下⾯的 curl 命令，调⽤  
http://192.168.0.10:10000/get\_cache\_data 新接⼝：

$ while true; do curl http://192.168.0.10:10000/get_cache_data; done
    {
        ...,"elapsed_seconds":0.16034674644470215,"type":"good"}

你可以发现，解决第⼆个问题后，新接⼝的性能⼜有了进⼀步的提升，从刚才的 0.9s ，再次缩短成了不到 0.2s。

当然，案例最后，不要忘记清理案例应⽤。切换到终端⼀中，执⾏下⾯的命令进⾏清理：

$ docker rm -f app redis

[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_18_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/a798834e45c544c2b2fc983239788b7a.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAT2NlYW4mJlN0YXI_size_13_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/f94e11e7dcc34c1aba6bfca1d629f9e6.png