「iodelay」-

  CREATED BY JENKINSBOT

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

# docker run --name=app-iodelay -p 10000:80 -itd feisky/word-pop

# curl http://10.10.50.188:10000/ // 确认案例正常启动
hello world

# curl http://10.10.50.188:1000/popularity/word // 访问示例应用

// 我们发现这个接口居然长时间都没响应

# df // 查看一下文件系统的使用情况

// 这么简单的命令,居然也要等好久才有输出

// 运行如下命令,以制造负载,用于问题排查

# while true; do time curl http://10.10.50.188:10000/popularity/word; sleep 1; done

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

# top
top - 10:49:54 up 57 days,  1:06,  1 user,  load average: 4.26, 1.50, 0.88
Tasks: 191 total,   1 running, 190 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.3 us,  1.0 sy,  0.0 ni, 36.5 id, 62.1 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  1.3 us,  2.3 sy,  0.0 ni,  0.7 id, 95.4 wa,  0.0 hi,  0.3 si,  0.0 st
%Cpu2  :  2.3 us,  5.0 sy,  0.0 ni,  3.7 id, 89.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu3  :  0.3 us,  1.7 sy,  0.0 ni,  0.0 id, 98.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem : 11854.82+total,  117.410 free, 1456.715 used, 10280.70+buff/cache
MiB Swap:    0.000 total,    0.000 free,    0.000 used. 9987.316 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
31234 root      20   0  110964  31064   4004 S  10.6  0.3   0:30.08 /usr/local/bin/python /app.py
   43 root      20   0       0      0      0 D   1.0  0.0   0:59.81 [kswapd0]

// load average => 负载很高
// wa => CPU 的 iowait 都非常高
// buff/cache => 系统缓存使用较多
// /usr/local/bin/python /app.py => 进程的 CPU 使用率稍微有点高

第二步、运行 iostat 命令,观察 I/O 的使用情况

# iostat -x -d 1
...
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   37.00     0.00 17880.00   966.49   144.79 2912.05    0.00 2912.05  27.03 100.00
sdb               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
...

// 磁盘 sda 的 I/O 使用率已经达到 100%,每秒写入请求 37,每秒写入数据量 20,写入等待时间 3s
// 此时我们可以推断,要么磁盘本身有问题,要么就是请求过多导致磁盘压力

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

# pidstat -d 1
...
11:12:14 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
11:12:15 AM    27      7102      0.00   3832.00     12.00  mysqld
11:12:15 AM     0     31234      0.00 137752.00      0.00  python

11:12:15 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
11:12:16 AM    27      7102      0.00    664.00      0.00  mysqld
11:12:16 AM     0     31234      0.00 137992.00      0.00  python
...

// 可以看到 PID 31234 python 在进行磁盘写入

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

# strace -p 31234 -f // 多进程和多线程可以同时跟踪
...
stat("/usr/local/lib/python3.7/getpass.py", {st_mode=S_IFREG|0644, st_size=5994, ...}) = 0
stat("/usr/local/lib/python3.7/getpass.py", {st_mode=S_IFREG|0644, st_size=5994, ...}) = 0
stat("/usr/local/lib/python3.7/getpass.py", {st_mode=S_IFREG|0644, st_size=5994, ...}) = 0
stat("/usr/local/lib/python3.7/lib-dynload/termios.cpython-37m-x86_64-linux-gnu.so", {st_mode=S_IFREG|0755, st_size=55408, ...}) = 0
stat("/usr/local/lib/python3.7/lib-dynload/termios.cpython-37m-x86_64-linux-gnu.so", {st_mode=S_IFREG|0755, st_size=55408, ...}) = 0
stat("/usr/local/lib/python3.7/lib-dynload/termios.cpython-37m-x86_64-linux-gnu.so", {st_mode=S_IFREG|0755, st_size=55408, ...}) = 0
...

// 从 strace 中,你可以看到大量的 stat 系统调用,并且大都为 python 的文件,但是,请注意,这里并没有任何 write 系统调用。
// 如果不使用 -f 选项将无法看到 write 系统调用,因为默认不显示子进程

filetop、opensnoop

在 bcc 中,基于 Linux 内核的 eBPF(extended Berkeley Packet Filters)机制,主要跟踪内核中文件的读写情况,并输出线程 ID(TID)、读写大小、读写类型以及文件名称。

# filetop -C // -C,输出新内容时不清空屏幕

// 输出了 8 列内容,分别是线程 ID、线程命令行、读写次数、读写的大小(单位 KB)、文件类型、读写的文件名称

// 多观察一会儿就会发现,每隔一段时间,线程 514 的 python 应用,先写入大量的 txt 文件,再读取大量的 txt 文件。

# ps -efT | grep 514

// 线程号为 514 正是 python 的子进程,问题的原因还是出现在 python 进程上

// 我们要继续追踪文件路径,因为 filetop 只能输出文件名,但是没有文件路径。

# opensnoop

// 通过 opensnoop 的输出,你可以看到,这些 txt 路径位于 /tmp 目录下。你还能看到,它打开的文件数量,按照数字编号,从 0.txt 依次增大到 999.txt,这可远多于前面用 filetop 看到的数量。

// 而且 opensnoop 观察到的路径还在变化,这说明这些目录都是应用程序动态生成的,用完就删了。

第五步、问题处理

我们基本可以判断,案例应用会动态生成一批文件,用来临时存储数据,用完就会删除它们。但不幸的是,正是这些文件读写,引发了 I/O 的性能瓶颈,导致整个处理过程非常慢。

查看程序,定位问题,找到疯狂输出日志的部分(这里不再继续展开)。

针对该案例的总结

排查思路:top => iostat => pidstat => strace -p -f / filetop / opensnoop

参考文献

27 | 案例篇:为什么我的磁盘I/O延迟很高?