「LINUX-PERFORMANCE-TUNING」- 高延迟

问题描述

# 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:10000/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 => 负载很高
CPU => iowait 都非常高。特别是 CPU3 iowait 已经高达 98%
MEM => free，剩余内存看起来较少；buff/cache => 系统缓存使用较多；

进程的 CPU 使用率稍微有点高，达到 14%，并不能成为性能瓶颈，但可能跟 iowait 的升高有关；

第二步、观察磁盘使用：iostat

# 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

# 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 系统调用，因为默认不显示子进程

strace -p -f，查看进程的所有线程信息，本例中 python 进程下可能同时存在两个线程，一个线程是 socket 相关，一个是跟文件读写相关，与文件读写相关的会频繁变化，只需跟踪进程树的最后一个线程就可以。可以用 pstree -p 查看 Python 的进程树，然后 strace -p 线程号，不过本例中线程消失非常快，需要写个脚本才行比如：Python 进程号是 13205 strace -p `pstree -p 13205 | tail -n 1 | awk -F ‘(‘ ‘{print $NF}’ | awk -F ‘)’ ‘{print $1}’

第五步、filetop、opensnoop

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

# filetop -C // -C，输出新内容时不清空屏幕
TID COMM READS WRITES R_Kb W_Kb T FILE
514 python 2 0 5957 0 R 651.txt
514 python 2 0 5371 0 R 112.txt
514 python 2 0 4785 0 R 861.txt
514 python 2 0 4736 0 R 213.txt
514 python 2 0 4443 0 R 45.txt
...

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

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

找到相关线程： 

# ps -efT | grep 514
root 12280 514 14626 33 14:47 pts/0 00:00:05 /usr/local/bin/python /app.py

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

鉴于 filetop 只能输出文件名，但是没有文件路径，我们要继续追踪文件路径： 

# opensnoop
12280  python              6   0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/650.txt
12280  python              6   0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/651.txt
12280  python              6   0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/652.txt

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

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

解决方案

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

查看程序，定位问题，找到疯狂输出日志的部分（这里不再继续展开）；

案例总结

该案例，负载来自于线程；

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

参考文献

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

Filed under: K4NZDROID - @ 5:44 PM