多进程应用的案例,带你分析大量不可中断状态和僵尸状态进程的问题
使用的案例环境如下所示:
•机器配置:2 CPU,8GB内存
•预先安装 sysstat、dstat 等工具
这里,dstat是的性能工具,它吸收了 vmstat、iostat、ifstat等几种工具的优点,可以同时观察系统的CPU、磁盘I/O、网络以及内存使用情况。
输入ps命令,确认案例应用已正常启动。如果一切正常,你应该可以看到如下所示的输出:
[root@localhost ~]# docker run --privileged --name=app -itd feisky/app:iowait
af1536f325f007046d1a3e0f4725cf3c49c007b246332ae80f76ad7ad5006c44
[root@localhost ~]# ps -aux | grep app
root 2043 0.2 0.0 4500 588 pts/0 Ss+ 21:48 0:00 /app
从这个界面,我们可以发现多个app进程已经启动,并且它们的状态分别是Ss+和D+。其中S表示可中断睡眠状态,D表示不可中断睡眠状态,那后面的s和+ 是什么意思呢?s表示这个进程是一个会话的领导进程,而+表示前台进程组。
这里又出现了两个新概念,进程组和会话。它们用来管理一组相互关联的进程,意思其实很好理解。
・进程组表示一组相互关联的进程,比如每个子进程都是父进程所在组的成员
・而会话是指共享同一个控制终端的一个或多个进程组
比如,我们通过SSH登录服务器,就会打一个控制终端(TTY),这个控制终端就对应一个会话。而我们在终端中运行的命令以及它们的子进程,就构成了一个个的进程组。其中,在后台运行的命令,构成后台进程组,在前台运行的命令,构成前台进程组。
明白了这些,我们再用top看一下系统的资源使用情况:
# 按下数字 1 切换到所有 CPU 的使用情况,观察一会儿按 Ctrl+C 结束
[root@localhost ~]# top
top - 21:52:44 up 1 day, 22:13, 4 users, load average: 15.05, 13.75, 9.91
Tasks: 201 total, 4 running, 116 sleeping, 0 stopped, 81 zombie
%Cpu(s): 1.1 us, 10.2 sy, 0.0 ni, 0.0 id, 47.0 wa, 0.0 hi, 41.7 si, 0.0 st
KiB Mem : 1765672 total, 225328 free, 1149928 used, 390416 buff/cache
KiB Swap: 524284 total, 412248 free, 112036 used. 403264 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3 root 20 0 0 0 0 S 23.4 0.0 1:57.30 ksoftirqd/0
13 root 20 0 0 0 0 R 22.4 0.0 2:23.41 ksoftirqd/1
2162 root 20 0 70040 65536 44 D 3.0 3.7 0:00.61 app
2168 root 20 0 70040 65536 44 D 3.0 3.7 0:00.48 app
2171 root 20 0 70040 65536 44 D 2.6 3.7 0:00.37 app
2160 root 20 0 0 0 0 Z 2.3 0.0 0:00.70 app
2172 root 20 0 70040 65536 44 D 2.3 3.7 0:00.32 app
2176 root 20 0 70040 65536 44 D 2.3 3.7 0:00.19 app
2177 root 20 0 70040 65536 44 D 2.3 3.7 0:00.19 app
2149 root 20 0 0 0 0 R 2.0 0.0 0:01.29 kworker/0:2
2163 root 20 0 70040 65536 44 D 2.0 3.7 0:00.55 app
2165 root 20 0 70040 65536 44 D 2.0 3.7 0:00.52 app
2166 root 20 0 70040 65536 44 D 2.0 3.7 0:00.51 app
2167 root 20 0 70040 65536 44 D 2.0 3.7 0:00.45 app
2178 root 20 0 70040 20128 44 D 2.0 1.1 0:00.06 app
1588 root 20 0 0 0 0 S 1.7 0.0 0:08.73 kworker/1:0
2164 root 20 0 70040 65536 44 D 1.7 3.7 0:00.49 app
从这里你能看出什么问题吗?这里发现了四个可疑的地方。
- 先看第一行的平均负载(Load Average),过去1分钟、5分钟和15分钟内的平均负载在依次减小,说明平均负载正在升高,而1分钟内的平均负载已经达到系统的CPU个数,说明系统很可能已经有了性能瓶颈。
- 再看第二行的Tasks,有4个正在运行的进程,但僵尸进程比较多,而且还在不停增加,说明有子进程在退出时没被清理。
- 接下来看两个CPU的使用率情况,用户CPU和系统CPU都不高,但iowait是47%,好像有点不正常。
- 最后再看每个进程的情况,CPU使用率最高的进程只有0.3%,看起来并不高,但有两个进 程处于D状态,它们可能在等待I/O,但光凭这里并不能确定是它们导致了 iowait升高。
这四个问题再汇总一下,就可以得到很明确的两点:
- 第一点,iowait太高了,导致系统的平均负载升高,甚至达到了系统CPU的个数。
- 第二点,僵尸进程在不断增多,说明有程序没能正确清理子进程的资源。
使用ps或者top可以查看进程的状态,这些状态包括运行、空闲、不可中断睡眠、可中断睡眠、僵尸以及暂停等。其中,我们重点应该理解不可中断状态和僵尸进程:
- 不可中断状态,一般表示进程正在跟硬件交互,为了保护进程数据与硬件一致,系统不允许其他进程或中断打断该进程。
- 僵尸进程表示进程已经退出,但它的父进程没有回收该进程所占用的资源。
接下来,顺着这两个问题继续分析,找出根源。
iowait分析
我们先来看一下iowait升高的问题。
一提到iowait升高,你首先会想要查询系统的I/O情况。我一般也是这种思路,那么什么工具可以查询系统的I/O情况呢?dstat工具,它的好处是,可以同时查看CPU和I/O这两种资源的使用情况,便于对比分析。那么,我们在终端中运行dstat命令,观察CPU和I/O的使用情况:
[root@localhost ~]# dstat 1 10
You did not select any stats, using -cdngy by default.
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read writ| recv send| in out | int csw
3 2 95 0 0 0| 112k 124k| 0 0 |2129B 3966B| 540 13k
1 31 3 43 0 22| 469M 0 | 120B 842B| 0 0 |2201 312
0 11 32 30 0 27| 479M 2752k| 60B 346B| 0 0 |2148 210
1 11 8 59 0 21| 477M 0 | 120B 422B| 0 0 |1970 170
1 20 5 36 0 39| 478M 0 | 60B 346B| 0 0 |2398 286
0 20 13 51 0 16| 485M 0 | 60B 346B| 0 0 |1811 284
0 7 0 74 0 19| 490M 0 | 106B 406B| 0 0 |1919 210 ^C
从dstat的输出,我们可以看到,每当iowait升高(wai)时,磁盘的读请求(read)都会很 大。这说明iowait的升高跟磁盘的读请求有关,很可能就是磁盘读导致的。
那到底是哪个进程在读磁盘呢?在top里看到的不可中断状态进 程,我觉得它就很可疑,我们试看来分析下。我们继续在刚才的终端中,运行top命令,观察D状态的进程:
[root@localhost ~]# top
top - 19:50:09 up 1 day, 20:10, 2 users, load average: 6.12, 2.00, 0.74
Tasks: 146 total, 5 running, 111 sleeping, 0 stopped, 30 zombie
%Cpu(s): 0.2 us, 16.6 sy, 0.0 ni, 1.8 id, 38.0 wa, 0.0 hi, 43.5 si, 0.0 st
KiB Mem : 1765672 total, 74392 free, 731852 used, 959428 buff/cache
KiB Swap: 524284 total, 478224 free, 46060 used. 725568 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3 root 20 0 0 0 0 R 26.6 0.0 0:35.99 ksoftirqd/0
13 root 20 0 0 0 0 R 22.7 0.0 1:18.58 ksoftirqd/1
1599 root 20 0 70040 20076 44 D 9.5 1.1 0:00.48 app
1600 root 20 0 70040 17700 44 D 9.5 1.0 0:00.44 app
1588 root 20 0 70040 65484 44 D 5.9 3.7 0:00.96 app
1592 root 20 0 70040 65484 44 R 4.3 3.7 0:00.38 app
1586 root 20 0 70040 65476 44 D 3.9 3.7 0:01.24 app
1587 root 20 0 70040 65484 44 D 3.9 3.7 0:00.93 app
1591 root 20 0 70040 65480 44 D 3.9 3.7 0:00.57 app
1593 root 20 0 70040 65484 44 D 3.9 3.7 0:00.60 app
1312 root 20 0 0 0 0 S 3.6 0.0 0:01.68 kworker/1:1
1585 root 20 0 70040 65476 44 D 3.3 3.7 0:01.06 app
1590 root 20 0 70040 65480 44 D 3.3 3.7 0:00.63 app
30 root 20 0 0 0 0 S 2.6 0.0 1:56.55 kswapd0
1589 root 20 0 157712 2208 1540 R 1.6 0.1 0:00.37 top
293 root 20 0 0 0 0 S 1.3 0.0 1:38.48 xfsaild/sda3
1367 root 20 0 0 0 0 S 1.3 0.0 0:02.44 kworker/0:1
我们从top的输出找到D状态进程的PID,你可以发现,这个界面里有许多D状态的进程,PID是1599。接着,我们查看这些进程的磁盘读写情况。对了,别忘了工具是什么。一般要査看某程的资源使用情况,都可以用我们的老朋友pidstat,不过这次记得加上-d参数,以便输出I/O使 用情况。比如,以1599为例,我们在终端里运行下面的pidstat命令,并用-p 1599参数指定进程 号:
[root@localhost ~]# pidstat -d -p 1599 1 3
Linux 3.10.0-693.el7.x86_64 (localhost.localdomain) 11/11/2020 _x86_64_ (2 CPU)
07:51:02 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
07:51:03 PM 0 1599 0.00 0.00 0.00 app
07:51:04 PM 0 1599 0.00 0.00 0.00 app
07:51:05 PM 0 1599 0.00 0.00 0.00 app
Average: 0 1599 0.00 0.00 0.00 app
在这个输出中,kB_rd表示每秒读的KB数,kB_wr表示每秒写的KB数,iodelay表示I/O 的延迟(单位是时钟周期)。它们都是0,那就表示此时没有任何的读写,说明问题不是1599进程导致的。
可是,用同样的方法分析进程1600,你会发现,它也没有任何磁盘读写。那要怎么知道,到底是哪个进程在进行磁盘读写呢?我们继续使用pidstat,这次去掉进程号,干脆就来观察所有进程的I/O使用情况。
在终端中运行下面的pidstat命令:
[root@localhost ~]# pidstat -d 1 10
Linux 3.10.0-693.el7.x86_64 (localhost.localdomain) 11/11/2020 _x86_64_ (2 CPU)
07:52:55 PM UID PID kB_rd/s kB_wr/s kB_ccwr/s Command
07:52:56 PM 0 1651 48000.00 0.00 0.00 app
07:52:56 PM 0 1652 28000.00 0.00 0.00 app
07:52:56 PM 0 1653 7599.61 0.00 0.00 app
07:52:56 PM 0 1654 31600.00 0.00 0.00 app
07:52:56 PM 0 1655 24000.00 0.00 0.00 app
07:52:56 PM 0 1656 35600.00 0.00 0.00 app
07:52:56 PM 0 1657 18000.00 0.00 0.00 app
07:52:56 PM 0 1658 41999.61 0.00 0.00 app
07:52:56 PM 0 1659 29600.00 0.00 0.00 app
07:52:56 PM 0 1660 20400.00 0.00 0.00 app
07:52:56 PM 0 1661 26000.00 0.00 0.00 app
07:52:56 PM 0 1662 24800.00 0.00 0.00 app
07:52:56 PM 0 1663 55600.00 0.00 0.00 app
07:52:56 PM 0 1664 30800.00 0.00 0.00 app
07:52:56 PM 0 1665 32800.39 0.00 0.00 app
07:52:56 PM 0 1666 17200.00 0.00 0.00 app
07:52:56 PM 0 1667 4800.00 0.00 0.00 app
07:52:56 PM 0 1668 18000.00 0.00 0.00 app
07:52:56 PM 0 1669 1600.00 0.00 0.00 app
07:52:56 PM 0 1671 6.25 0.00 0.00 app
07:52:56 PM 0 1672 3.12 0.00 0.00 app
观察一会儿可以发现,的确是app进程在进行磁盘读,并且每秒读的数据有32MB,看来就是 app的问题。不过,app进程到底在执行啥I/O操作呢?
这里,我们需要回顾一下进程用户态和内核态的区别。进程想要访问磁盘,就必须使用系统调用,所以接下来,重点就是找出app进程的系统调用了。
strace正是最常用的跟踪进程系统调用的工具。所以,我们从pidstat的输出中拿到进程的PID号,比如1651,然后在终端中运行strace命令,并用-p参数指定PID号:
[root@localhost ~]# strace -p 1651
strace: attach: ptrace(PTRACE_ATTACH, ...): Operation not permitted
这儿出现了一个奇怪的错误,strace命令居然失败了,并且命令报出的错误是没有权限。按理来说,我们所有操作都已经是以root用户运行了,为什么还会没有权限呢?你也可以先想一 下,碰到这种情况,你会怎么处理呢?
一般遇到这种问题时,我会先检查一下进程的状态是否正常。比如,继续在终端中运行ps命令,并使用grep找出刚才才的1651号进程:
[root@localhost ~]# ps -aux | grep 1651
root 1651 0.5 0.0 0 0 pts/0 Z+ 19:52 0:01 [app] <defunct>
root 1730 12.0 0.0 112664 392 pts/1 S+ 19:55 0:00 grep --color=auto 1651
果然,进程1651已经变成了Z状态,也就是僵尸进程。僵尸进程都是已经退出的进程,所以就没法儿继续分析它的系统调用。关于僵尸进程的处理方法,一会儿再说,现在还是继续分析iowait的问题。
到这一步,你应该注意到了,系统iowait的问题还在继续,但是top、pidstat这类工具已经不能给出更多的信息了。这时,我们就应该求助那些基于事件记录的动态追踪工具了。
你可以用perf top看看有没有新发现。再或者,可以像我一样,在终端中运行perf record, 持续一会儿(例如15秒),然后按Ctrl+C退出,再运行perf report查看报告:
接着,找到我们关注的app进程,按回车键展开调用栈,你就会得到下面这张调用关系图:
这个图里的 swapper 是内核中的调度进程,你可以先忽略掉。
我们来看其他信息,你可以发现, app 的确在通过系统调用 sys_read() 读取数据。并且从 new_sync_read 和 blkdev_direct_IO 能看出,进程正在对磁盘进行直接读,也就是绕过了系统缓存,每个读请求都会从磁盘直接读,这就可以解释我们观察到的 iowait 升高了。
看来,罪魁祸首是app内部进行了磁盘的直接I/O啊!
下面的问题就容易解决了。我们接下来应该从代码层面分析,究竟是哪里出现了直接读请求。查 看源码文件app.c,你会发现它果然使用了 O_DIRECT选项打开磁盘,于是绕过了系统缓存, 直接对磁盘进行读写。
open(disk, O_RDONLY|O_DIRECT|O_LARGEFILE, 0755)
直接读写磁盘,对I/O敏感型应用(比如数据库系统)是很友好的,因为你可以在应用中,直接控制磁盘的读写。但在大部分情况下,我们最好过系统缓存来优化磁盘I/O。换句话说,删除O_DIRECT这个选项就是了。
# 首先删除原来的应用
$ docker rm -f app
# 运行新的应用
$ docker run --privileged --name=app -itd feisky/app:iowait-fix1
删除完之后再使用top检查一下:
$ top
top - 14:59:32 up 19 min, 1 user, load average: 0.15, 0.07, 0.05
Tasks: 137 total, 1 running, 72 sleeping, 0 stopped, 12 zombie
%Cpu0 : 0.0 us, 1.7 sy, 0.0 ni, 98.0 id, 0.3 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 0.0 us, 1.3 sy, 0.0 ni, 98.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
...
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3084 root 20 0 0 0 0 Z 1.3 0.0 0:00.04 app
3085 root 20 0 0 0 0 Z 1.3 0.0 0:00.04 app
1 root 20 0 159848 9120 6724 S 0.0 0.1 0:09.03 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root 20 0 0 0 0 I 0.0 0.0 0:00.40 kworker/0:0
...
你会发现,iowait已经非常低了,只有0.3%,说明刚才的改动已经成功修复了 iowait高的问题,大功告成!不过,别忘了,僵尸进程还在等着你。仔细观察僵尸进程的数量,你会郁闷地发现,僵尸进程还在不断的增长中。
僵尸进程
接下来,我们就来处理僵尸进程的问题。既然僵尸进程是因为父进程没有回收子进程的资源而出现的,那么,要解决掉它们,就要找到它们的根儿,也就是找出父进程,然后在父进程里解决。
父进程的找最简单的就是运pstree命令:
# -a 表示输出命令行选项
# p表PID
# s表示指定进程的父进程
$ pstree -aps 3084
systemd,1
└─dockerd,15006 -H fd://
└─docker-containe,15024 --config /var/run/docker/containerd/containerd.toml
└─docker-containe,3991 -namespace moby -workdir...
└─app,4009
└─(app,3084)
所以,我们接着查看 app 应用程序的代码,看看子进程结束的处理是否正确,比如有没有调用 wait() 或 waitpid() ,抑或是,有没有注册 SIGCHLD 信号的处理函数。
现在查看修复iowait后的源码文件app-fix1.c,找到子进程的创建和清理地方
int status = 0;
for (;;) {
for (int i = 0; i < 2; i++) {
if(fork()== 0) {
sub_process();
}
}
sleep(5);
}
while(wait(&status)>0);
循环语句本来就容易出错,你能找到这里的问题吗?这段代码虽然看起来调用了wait)函数等待子进程结束,但却错误地把 wait()放到了 for 死循环的外面,也就是说,wait(函数实际上并没被调用到,我们把它挪到 for循环的里面就可以了。
修改后的文件我放到了app-fix2中,也打包成了一个Docker镜像,运行下面的命令,你就可以启动它∶
# 先停止产生僵尸进程的 app
$ docker rm -f app
# 然后启动新的 app
$ docker run --privileged --name=app -itd feisky/app:iowait-fix2
启动后使用top最后检查一遍
$ top
top - 15:00:44 up 20 min, 1 user, load average: 0.05, 0.05, 0.04
Tasks: 125 total, 1 running, 72 sleeping, 0 stopped, 0 zombie
%Cpu0 : 0.0 us, 1.7 sy, 0.0 ni, 98.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 0.0 us, 1.3 sy, 0.0 ni, 98.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
...
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3198 root 20 0 4376 840 780 S 0.3 0.0 0:00.01 app
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root 20 0 0 0 0 I 0.0 0.0 0:00.41 kworker/0:0
...
好了,僵尸进程(Z状态)没有了,iowait也是0,问题终于全部解决了。
小结
今天我用一个多进程的案例,带你分析系统等待 I/O 的 CPU 使用率(也就是 iowait%)升高的情况。
虽然这个案例是磁盘 I/O 导致了 iowait 升高,不过, iowait 高不一定代表 I/O 有性能瓶颈。当系统中只有 I/O 类型的进程在运行时,iowait 也会很高,但实际上,磁盘的读写远没有达到性能瓶颈的程度。
因此,碰到 iowait 升高时,需要先用 dstat、pidstat 等工具,确认是不是磁盘 I/O 的问题,然后再找是哪些进程导致了 I/O。
等待 I/O 的进程一般是不可中断状态,所以用 ps 命令找到的 D 状态(即不可中断状态)的进程,多为可疑进程。但这个案例中,在 I/O 操作后,进程又变成了僵尸进程,所以不能用 strace 直接分析这个进程的系统调用。
这种情况下,我们用了 perf 工具,来分析系统的 CPU 时钟事件,最终发现是直接 I/O 导致的问题。这时,再检查源码中对应位置的问题,就很轻松了。
而僵尸进程的问题相对容易排查,使用 pstree 找出父进程后,去查看父进程的代码,检查 wait() / waitpid() 的调用,或是 SIGCHLD 信号处理函数的注册就行了。