配置环境,以创建负载场景
# 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
参考文献