问题描述
我们运行如下程序，但是我们发现系统负载快速升高，需要进行问题排查；
# docker run -v /tmp:/tmp --name=app-log -itd feisky/logapp // 运行应用程序 # ps -ef | grep /app.py // 确认案例应用正常启动 root 23054 23036 45 08:30 pts/0 00:00:02 python /app.py root 23089 20643 0 08:30 pts/0 00:00:00 grep --color=auto /app.py
原因分析
第一步、观察总体情况：top
# top top - 08:32:22 up 56 days, 22:49, 1 user, load average: 3.57, 1.70, 0.89 Tasks: 196 total, 2 running, 194 sleeping, 0 stopped, 0 zombie %Cpu0 : 0.7 us, 1.3 sy, 0.0 ni, 0.0 id, 97.7 wa, 0.0 hi, 0.3 si, 0.0 st %Cpu1 : 17.9 us, 78.8 sy, 0.0 ni, 3.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu2 : 1.0 us, 0.3 sy, 0.0 ni, 97.0 id, 1.7 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu3 : 2.0 us, 0.3 sy, 0.0 ni, 97.3 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st MiB Mem : 11854.82+total, 1368.898 free, 1653.500 used, 8832.430 buff/cache MiB Swap: 0.000 total, 0.000 free, 0.000 used. 9793.617 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 23054 root 20 0 1040092 644228 3304 R 96.7 5.3 1:25.50 python /app.py 7294 apache 20 0 369372 30468 4136 S 2.0 0.3 102:08.77 php-fpm: pool www ...
%Cpu1 的使用率非常高，sy 78.8；
%Cpu0 wa 97.7 => 此时可能正在进行 IO 密集的进程
Buffer/Cache 占用内存高达 8GB 之多，通过 /proc/meminfo 可以看到系统的 buffer 和 cache 各占多少
从进程中，我们可以看到 PID 23054 python /app.py %CPU 96.7
第二步、观察磁盘使用：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 82.00 0.00 41984.00 1024.00 143.55 642.94 0.00 642.94 12.20 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 // -d 表示显示 I/O 性能指标，-x 表示显示扩展统计（即所有 I/O 指标）
// 磁盘 sda 的 IO 使用率已经高达 100%，很可能已经接近 IO 饱和；
// 每秒写磁盘请求数是 82.00，写大小是 41 MB，写请求的响应时间为 6 秒，而请求队列长度则达到了 143；
// 超慢的响应时间和特长的请求队列长度，进一步验证了 IO 已经饱和的猜想
第三步、观察进程运行：pidstat
# pidstat -d 1 15:08:35 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 15:08:36 0 18940 0.00 45816.00 0.00 96 python 15:08:36 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 15:08:37 0 354 0.00 0.00 0.00 350 jbd2/sda1-8 15:08:37 0 18940 0.00 46000.00 0.00 96 python 15:08:37 0 20065 0.00 0.00 0.00 1503 kworker/u4:2 // 从 pidstat 的输出，可以发现只有 python 进程的写比较大 // 往下看 iodelay 项。虽然只有 python 在大量写数据，但有两个进程（kworker 和 jbd2）的延迟比 python 进程还大很多； // kworker 是一个内核线程，而 jbd2 是 ext4 文件系统中用来保证数据完整性的内核线程； // 他们都是保证文件系统基本功能的内核线程，所以具体细节暂时就不用管了，我们只需要明白，大量 I/O 导致它们高延迟；
第四步、观察系统调用：strace
# strace -p 23054
...
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f40204b1000
write(3, "2020-08-11 01:28:41,353 - __main"..., 314572844) = 314572844
munmap(0x7f40204b1000, 314576896) = 0
...
lseek(3, 0, SEEK_CUR) = 943718535
munmap(0x7f401b9b1000, 314576896) = 0
close(3) = 0
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0
...
// 进程向文件描述符编号为 3，写入 300MB 的数据
// 再观察后面的 stat() 调用，你可以看到，它正在获取 /tmp/logtest.txt.1 的状态，
// 类似与日志论转格式的文件名，那么日志文件可能是 /tmp/logtest.txt
第五步、观察打开文件：lsof
# lsof -p 23054 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME python 28500 root cwd DIR 0,36 17 65749020 / ... python 28500 root 2u CHR 136,0 0t0 3 /dev/pts/0 python 28500 root 3w REG 253,0 943718535 4341230 /tmp/logtest.txt // FD 表示文件描述符号，TYPE 表示文件类型，NAME 表示文件路径 // 最后一行说明这个进程打开了文件 /tmp/logtest.txt，并且它的文件描述符是 3 号，而 3 后面的 w，表示以写的方式打开；
这跟刚才 strace 完我们猜测的结果一致，看来这就是问题的根源：进程 python /app.py 以每次 300MB 的速度，在“疯狂”写日志，而日志文件的路径是 /tmp/logtest.txt；
解决方案
查看程序，定位问题，找到疯狂输出日志的部分（这里不再继续展开）；
案例总结
在该案例中，IO 压力来自于 write() 调用，大量的写入数据给磁盘带来压力。但是，并不是所有的 IO 压力都是写入导致的，还有可能是其他原因；
排查思路：top => iostat => pidstat => strace + lsof => 结合应用的原理
参考文献