「redis」- 由于 Redis 错误配置导致的 I/O 压力

配置环境，以创建负载场景

# docker run --name=redis -itd -p 10000:80 feisky/redis-server

# docker run --name=app --network=container:redis -itd feisky/redis-app

# docker ps // 确认两个容器都处于运行状态

# curl http://10.10.50.188:10000/ // 检测应用正常启动
hello redis

// 初始化 Redis 缓存，并且插入 5000 条缓存信息

curl http://10.10.50.188:10000/init/5000
{"elapsed_seconds":30.26814079284668,"keys_initialized":5000}

// 测试接口调用

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

// 接口调用响应时间较长，需要花费 10 秒

// 循环执行命令，以创造负载，用于调试

# while true; do curl http://10.10.50.188:10000/get_cache; done

第一步、运行 top 命令，观察资源使用情况

# 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

// CPU0 的 iowait 比较高，已经达到了 84%
// 内存，总内存 8GB，剩余内存还有 7GB 多
// 进程的 CPU 使用率都不太高，最高的 python 和 redis-server ，也分别只有 8% 和 5%

// 最有嫌疑的就是 iowait。所以接下来还是要继续分析，是不是 I/O 问题。

第二步、运行 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

// 磁盘 sda 每秒的写数据（wkB/s）为 2.5MB，I/O 使用率（%util）是 0
// 对查询来说，对应的 I/O 应该是磁盘的读操作，但刚才我们用 iostat 看到的却是写操作
// 为什么会有磁盘写呢

iowait 不代表磁盘I/O存在瓶颈，只是代表 CPU 上 I/O 操作的时间占用的百分比。假如这时候没有其他进程在运行，那么很小的 I/O 就会导致 iowait 升高

第三步、运行 pidstat 命令，观察进程 I/O 使用情况

# 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

// I/O 最多的进程是 PID 为 9085 的 redis-server，并且它也刚好是在写磁盘。
// 这说明确实是 redis-server 在进行磁盘写

第四步、运行 strace 命令，分析进程的系统调用

# strace -f -p 9085 -T -tt // -f 表示跟踪子进程和子线程，-T 表示显示系统调用的时长，-tt 表示显示跟踪时间
[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>

// 那么刚才观察到的写磁盘，应该就是 write 或者 fdatasync 导致的

查看 3 5 7 8 描述符

# 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

// 如果熟悉 Redis 持久话，就会发现问题在哪里，我们这里可以推断是 Redis 的持久化配置存在问题

// 结合前面 read(8) 中可以看到，redis 收到的请求指令为 GET 与 SADD，而 SADD 会 是一个写操作

// 查询 appendonly 和 appendfsync 的配置

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

// appendfsync = always 每个操作都会执行一次 fsync，是最为安全的方式
// 意味着每次写数据时，都会调用一次 fsync，从而造成比较大的磁盘 I/O 压力

# strace -f -p 9085 -T -tt -e fdatasync // 通过 -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

定位请求的来源

// 由于这两个容器共享同一个网络命名空间，所以我们只需要进入app的网络命名空间即可

# PID=$(docker inspect --format {{.State.Pid}} app)

# nsenter --target $PID --net -- lsof -i // -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, FD=8 => localhost:6379->localhost:32996 => localhost:32996->localhost:6379 => python, PID=9181
// 是我们的 Python 应用程序（进程号为 9181）

问题解决办法

第一步、把 appendfsync 改成 everysec
第二步、检查程序源码，找到 SADD 指令，查看源码对 SADD 指令的使用是否正确。

参考文献

29 | 案例篇：Redis响应严重延迟，如何解决？

Filed under: K4NZDROID - @ 5:43 PM