「I/O」- 排查应用程序记录大量日志(由于 write() 引发)

  CREATED BY JENKINSBOT

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

# 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 => 此时可能正在进行 I/O 密集的进程
// Buffer/Cache 占用内存高达 8GB 之多,通过 /proc/meminfo 可以看到系统的 buffer 和 cache 各占多少
// 从进程中,我们可以看到 PID 23054 python /app.py %CPU 96.7

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

# iostat -x -d 1 // -d 表示显示I/O性能指标,-x 表示显示扩展统计(即所有I/O指标)
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

// 磁盘 sda 的 I/O 使用率已经高达 100%,很可能已经接近 I/O 饱和。
// 每秒写磁盘请求数是 82.00 ,写大小是 41 MB,写请求的响应时间为 6 秒,而请求队列长度则达到了 143。

// 超慢的响应时间和特长的请求队列长度,进一步验证了 I/O 已经饱和的猜想

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

# pidstat -d 1

// 从 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。

第六步、问题处理

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

针对该案例的总结

在该案例中,I/O 压力来自于 write() 调用,大量的写入数据给磁盘带来压力。但是,并不是所有的 IO 压力都是写入导致的,还有可能是其他原因。

排查思路:top => iostat => pidstat => strace / lsof

参考文献

26 | 案例篇:如何找出狂打日志的“内鬼”?