cpu iowait 升高分析以及僵尸进程
摘要:
本文首先介绍了不可中断睡眠状态产生的原因，以及僵尸进程相关的概念，并通过一个简单的案例分析了cpu iowait 升高的 性能定位分析问题的场景。
不可中断睡眠状态
不可中断状态睡眠（Uninterruptible Sleep），一般表示进程正在跟硬件交互，并且交互过程不允许被其他进程或中断打断。
不可中断状态，其实是为了保证进程数据与硬件状态一致，并且正常情况下，不可中断状态在很短时间内就会结束。所以，短时的不可中断状态进程，一般可以忽略。
但如果系统或硬件发生了故障，进程可能会在不可中断状态保持很久，甚至导致系统中出现大量不可中断进程。此时就需要排查系统是不是出现了 I/O 等性能问题？
僵尸进程
正常情况下，当一个进程创建了子进程后，应该通过系统调用 wait() 或者 waitpid() 等待子进程结束，回收子进程的资源；而子进程在结束时，会向它的父进程发送 SIGCHLD 信号，所以，父进程还可以注册 SIGCHLD 信号的处理函数，异步回收资源。如果父进程没进行资源回收，或是子进程执行太快，父进程还没来得及处理子进程状态，子进程就已经提前退出，那这时的子进程就会变成僵尸进程。
正常，僵尸进程持续的时间都比较短，在父进程回收它的资源后就会消亡；或者在父进程退出后，由 init 进程回收后也会消亡。一旦父进程没有处理子进程的终止，还一直保持运行状态，那么子进程就会一直处于僵尸状态。
大量的僵尸进程会用尽 PID 进程号，导致新进程不能创建，所以这种情况一定要避免。
僵尸进程的问题相对容易排查：使用 pstree 找出父进程后，去查看父进程的代码，检查 wait() / waitpid() 的调用，或是 SIGCHLD 信号处理函数的注册就行了。
案例
yine@ubuntu:~$ ps -aux | grep app
root 425349 0.0 0.0 2488 460 ? Ss+ 22:30 0:00 /app
root 425385 7.1 0.0 0 0 ? Z+ 22:30 0:01 [app] <defunct>
root 425386 4.8 0.0 0 0 ? Z+ 22:30 0:00 [app] <defunct>
root 425388 26.6 0.0 0 0 ? Z+ 22:31 0:03 [app] <defunct>
root 425389 25.7 0.0 0 0 ? Z+ 22:31 0:03 [app] <defunct>
root 425390 21.5 3.2 68028 65708 ? R+ 22:31 0:01 /app
root 425391 12.8 3.2 68028 65708 ? R+ 22:31 0:01 /app
yine 425397 0.7 0.0 8900 732 pts/7 S+ 22:31 0:00 grep --color=auto app
root 425398 4.0 3.2 68028 65700 ? D+ 22:31 0:00 /app
root 425399 3.5 3.2 68028 65696 ? D+ 22:31 0:00 /app
s 表示这个进程是一个会话的领导进程，而 + 表示前台进程组。
进程组和会话。它们用来管理一组相互关联的进程，意思其实很好理解。
- 进程组表示一组相互关联的进程，比如每个子进程都是父进程所在组的成员；
- 而会话是指共享同一个控制终端的一个或多个进程组。
- top 观察平均负载
top - 22:41:36 up 3 min, 1 user, load average: 3.20, 1.32, 0.15
Tasks: 371 total, 1 running, 340 sleeping, 0 stopped, 30 zombie
平均负载正在升高，同时僵尸进程数量在增多， 同时各个cpu 的iowait 升高
- dstat 监控
dstat 1 20
You did not select any stats, using -cdngy by default.
--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read writ| recv send| in out | int csw
2 13 72 12 0| 744M 45k| 0 0 |1755B 10k|1269 1068
6 22 64 9 0|1218M 0 | 0 0 | 0 0 |1758 922
4 28 42 26 0|1593M 0 | 0 0 | 0 0 |2367 1275
5 31 35 30 0|1664M 0 | 129B 0 | 0 0 |2180 1018
6 27 39 28 0|1629M 0 | 0 70B| 0 0 |2391 961
0 1 99 0 0| 45M 0 | 0 0 | 0 0 | 329 468
4 21 56 19 0|1199M 0 | 0 0 | 0 0 |1796 1005
4 27 41 29 0|1643M 0 | 0 0 | 0 0 |2372 1138
5 31 33 31 0|1637M 0 | 120B 60B| 0 0 |2157 912
5 26 38 30 0|1670M 0 | 0 0 | 0 0 |2601 1028
0 0 100 0 0| 0 0 | 0 0 | 0 0 | 210 361
可发现 iowait 在升高的时候，磁盘读请求在升高。
- pidstat 找出磁盘读的进程 确定时app 进程在进行磁盘读
pidstat -d 1 10
Linux 5.4.0-54-generic (ubuntu) 12/07/2020 _x86_64_ (4 CPU)
10:56:18 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
10:56:19 PM 0 3217 -1.00 -1.00 -1.00 25 app
10:56:19 PM 0 3218 -1.00 -1.00 -1.00 35 app
10:56:19 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
10:56:20 PM 0 3217 -1.00 -1.00 -1.00 104 app
10:56:20 PM 0 3218 -1.00 -1.00 -1.00 82 app
10:56:20 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
10:56:21 PM 0 3217 -1.00 -1.00 -1.00 95 app
10:56:21 PM 0 3218 -1.00 -1.00 -1.00 106 app
10:56:21 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
10:56:22 PM 0 3217 -1.00 -1.00 -1.00 71 app
10:56:22 PM 0 3218 -1.00 -1.00 -1.00 83 app
10:56:22 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
10:56:23 PM 0 3217 -1.00 -1.00 -1.00 17 app
10:56:23 PM 0 3218 -1.00 -1.00 -1.00 19 app
10:56:23 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
10:56:24 PM 0 3219 -1.00 -1.00 -1.00 30 app
10:56:24 PM 0 3220 -1.00 -1.00 -1.00 39 app
10:56:24 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
10:56:25 PM 0 3219 -1.00 -1.00 -1.00 100 app
10:56:25 PM 0 3220 -1.00 -1.00 -1.00 85 app
4.perf 调用查看 app 调用链情况
发现有直接磁盘读的调用： blkdev_direct_IO
$ perf record -g
$ perf report
+ 8.86% 8.36% kworker/0:1H-kb [kernel.kallsyms] [k] mpt_put_msg_frame ▒
- 7.52% 0.00% app [kernel.kallsyms] [k] entry_SYSCALL_64_aft▒
entry_SYSCALL_64_after_hwframe ▒
- do_syscall_64 ▒
- 7.43% __x64_sys_read ▒
- ksys_read ▒
- 7.43% vfs_read ▒
- 7.43% __vfs_read ▒
new_sync_read ▒
blkdev_read_iter ▒
- generic_file_read_iter ▒
- 7.43% blkdev_direct_IO ▒
- 7.43% __blkdev_direct_IO ▒
+ 5.68% submit_bio ▒
+ 1.34% bio_iov_iter_get_pages ▒
+ 7.52% 0.00% app [kernel.kallsyms] [k] do_syscall_64 ▒
+ 7.52% 0.00% app libc-2.31.so [.] __libc_start_main ▒
- 7.52% 0.00% app app [.] main ▒
- main ▒
+ 7.43% read ▒
+ 7.43% 0.00% app libc-2.31.so [.] read ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] __x64_sys_read ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] ksys_read ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] vfs_read ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] __vfs_read ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] new_sync_read ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] blkdev_read_iter ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] generic_file_read_it▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] blkdev_direct_IO ▒
+ 7.43% 0.00% app [kernel.kallsyms] [k] __blkdev_direct_IO
app 的确在通过系统调用 sys_read() 读取数据。并且从 new_sync_read 和 blkdev_direct_IO 能看出，进程正在对磁盘进行直接读，也就是绕过了系统缓存，每个读请求都会从磁盘直接读，这就可以解释我们观察到的 iowait 升高了。
优化
直接读写磁盘，对 I/O 敏感型应用（比如数据库系统）是很友好的，因为你可以在应用中，直接控制磁盘的读写。但在大部分情况下，最好还是通过系统缓存来优化磁盘 I/O，因此一般的应用删除 O_DIRECT 这个选项可以。
DIR *dirptr = opendir("/dev/");
perror("Failed to open dir");
int fd = open(disk, O_RDONLY | O_DIRECT | O_LARGEFILE, 0755);
perror("failed to open disk");
总结
虽然这个案例是磁盘 I/O 导致了 iowait 升高，不过， iowait 高不一定代表 I/O 有性能瓶颈。当系统中只有 I/O 类型的进程在运行时，iowait 也会很高，但实际上，磁盘的读写远没有达到性能瓶颈的程度。
因此，碰到 iowait 升高时，
- 需要先用 dstat、pidstat 等工具，确认是不是磁盘 I/O 的问题，
- 然后再找是哪些进程导致了 I/O。等待 I/O 的进程一般是不可中断状态，
- 用 ps 命令找到的 D 状态（即不可中断状态）的进程，多为可疑进程。
- 当不能用strace 直接分析 进程的系统调用时，可以通过perf 工具分析cpu时钟事件，找到对应的调用消耗，在源码中对应的系统调用部分，即可定位到实际的问题。
