文章目录
- 案例背景
- 案例分析
- 准备工作
- 操作和分析
- 总结
- Tips
- 关于execsnoop
案例背景
系统的 CPU 使用率
,不仅包括进程用户态和内核态的运行,还包括中断处理
、等待 I/O
以及内核线程
等。所以,当你发现系统的 CPU 使用率
很高的时候,不一定能找到相对应的高CPU 使用率
的进程
。
案例分析
准备工作
1. 本次案例基于 Ubuntu 18.04,同样适用于其他的 Linux 系统
1. 机器配置:2 CPU,8GB 内存
2. 预先安装 docker、sysstat、perf、ab 等工具,如 apt install docker.io sysstat linux-tools-common apache2-utils
操作和分析
- 安装环境
docker run --name nginx -p 10000:80 -itd feisky/nginx:sp
docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp
- 在第二个终端,使用
ab
请求测试Nginx
性能
# 并发100个请求测试Nginx性能,总共测试1000个请求
$ ab -c 100 -n 1000 http://127.0.0.1:10000/
This is ApacheBench, Version 2.3 <$Revision: 1706008 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd,
...
Requests per second: 87.86 [#/sec] (mean)
Time per request: 1138.229 [ms] (mean)
...
Nginx
能承受的每秒平均请求数,只有87
多一点,显然性能很差.那么,到底是哪里出了问题呢?
- 继续在第二个终端测试
$ ab -c 5 -t 600 http://192.168.0.10:10000/
并发请求5个 持续600秒
- 打开第三个终端,使用
top
查看
$ top
...
%Cpu(s): 80.8 us, 15.1 sy, 0.0 ni, 2.8 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st
...
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6882 root 20 0 8456 5052 3884 S 2.7 0.1 0:04.78 docker-containe
6947 systemd+ 20 0 33104 3716 2340 S 2.7 0.0 0:04.92 nginx
7494 daemon 20 0 336696 15012 7332 S 2.0 0.2 0:03.55 php-fpm
7495 daemon 20 0 336696 15160 7480 S 2.0 0.2 0:03.55 php-fpm
10547 daemon 20 0 336696 16200 8520 S 2.0 0.2 0:03.13 php-fpm
10155 daemon 20 0 336696 16200 8520 S 1.7 0.2 0:03.12 php-fpm
10552 daemon 20 0 336696 16200 8520 S 1.7 0.2 0:03.12 php-fpm
15006 root 20 0 1168608 66264 37536 S 1.0 0.8 9:39.51 dockerd
4323 root 20 0 0 0 0 I 0.3 0.0 0:00.87 kworker/u4:1
...
1.
CPU
使用率最高的进程也只不过才2.7%
,看起来并不高。
2. 但是用户CPU
使用率(us)
已经到了80%
,系统CPU
为15.1%
,而空闲CPU (id
)则只有2.8%
。
- 进一步分析
docker-containerd
进程是用来运行容器的,2.7% 的 CPU 使用率看起来正常;Nginx
和php-fpm
是运行Web
服务的,它们会占用一些CPU
也不意外,并且2%
的CPU
使用率也不算高;- 再往下看,后面的进程呢,只有
0.3%
的CPU
使用率,看起来不太像会导致用户CPU
使用率达到80%
。
根据上述分析还是找不到高 CPU 使用率
的进程
,此时考虑更换工具使用pidstat
继续查找原因
- 运行
pidstat
继续查找原因
# 间隔1秒输出一组数据(按Ctrl+C结束)
$ pidstat 1
...
04:36:24 UID PID %usr %system %guest %wait %CPU CPU Command
04:36:25 0 6882 1.00 3.00 0.00 0.00 4.00 0 docker-containe
04:36:25 101 6947 1.00 2.00 0.00 1.00 3.00 1 nginx
04:36:25 1 14834 1.00 1.00 0.00 1.00 2.00 0 php-fpm
04:36:25 1 14835 1.00 1.00 0.00 1.00 2.00 0 php-fpm
04:36:25 1 14845 0.00 2.00 0.00 2.00 2.00 1 php-fpm
04:36:25 1 14855 0.00 1.00 0.00 1.00 1.00 1 php-fpm
04:36:25 1 14857 1.00 2.00 0.00 1.00 3.00 0 php-fpm
04:36:25 0 15006 0.00 1.00 0.00 0.00 1.00 0 dockerd
04:36:25 0 15801 0.00 1.00 0.00 0.00 1.00 1 pidstat
04:36:25 1 17084 1.00 0.00 0.00 2.00 1.00 0 stress
04:36:25 0 31116 0.00 1.00 0.00 0.00 1.00 0 atopacctd
...
观察一会儿,发现所有进程的 CPU 使用率也都不高,最高的
Docker
和Nginx
也只有4%
和3%
,即使所有进程的 CPU 使用率都加起来,也不过是21%
,离80%
还差得远呢!
- 重新运行
top
命令,并观察一会儿
$ top
top - 04:58:24 up 14 days, 15:47, 1 user, load average: 3.39, 3.82, 2.74
Tasks: 149 total, 6 running, 93 sleeping, 0 stopped, 0 zombie
%Cpu(s): 77.7 us, 19.3 sy, 0.0 ni, 2.0 id, 0.0 wa, 0.0 hi, 1.0 si, 0.0 st
KiB Mem : 8169348 total, 2543916 free, 457976 used, 5167456 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 7363908 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6947 systemd+ 20 0 33104 3764 2340 S 4.0 0.0 0:32.69 nginx
6882 root 20 0 12108 8360 3884 S 2.0 0.1 0:31.40 docker-containe
15465 daemon 20 0 336696 15256 7576 S 2.0 0.2 0:00.62 php-fpm
15466 daemon 20 0 336696 15196 7516 S 2.0 0.2 0:00.62 php-fpm
15489 daemon 20 0 336696 16200 8520 S 2.0 0.2 0:00.62 php-fpm
6948 systemd+ 20 0 33104 3764 2340 S 1.0 0.0 0:00.95 nginx
15006 root 20 0 1168608 65632 37536 S 1.0 0.8 9:51.09 dockerd
15476 daemon 20 0 336696 16200 8520 S 1.0 0.2 0:00.61 php-fpm
15477 daemon 20 0 336696 16200 8520 S 1.0 0.2 0:00.61 php-fpm
24340 daemon 20 0 8184 1616 536 R 1.0 0.0 0:00.01 stress
24342 daemon 20 0 8196 1580 492 R 1.0 0.0 0:00.01 stress
24344 daemon 20 0 8188 1056 492 R 1.0 0.0 0:00.01 stress
24347 daemon 20 0 8184 1356 540 R 1.0 0.0 0:00.01 stress
...
1. 观察
Tasks
就绪队列中居然有 6 个Running
状态的进程,回想一下ab
测试的参数,并发请求数是 5。再看进程列表里,php-fpm
的数量也是 5,再加上Nginx
,好像同时有 6 个进程也并不奇怪.但仔细查看nginx
和php-fpm
的状态发现,它们都处于Sleep(S)
状态,而真正处于Running(R)
状态的,却是几个stress
进程。
- 使用
pidstat
指定上面top
中几个进程的pid
查看
$ pidstat -p 24344
16:14:55 UID PID %usr %system %guest %wait %CPU CPU Command
居然没有任何输出
- 我们再用 top 命令确认一下
$ top
...
%Cpu(s): 80.9 us, 14.9 sy, 0.0 ni, 2.8 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st
...
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6882 root 20 0 12108 8360 3884 S 2.7 0.1 0:45.63 docker-containe
6947 systemd+ 20 0 33104 3764 2340 R 2.7 0.0 0:47.79 nginx
3865 daemon 20 0 336696 15056 7376 S 2.0 0.2 0:00.15 php-fpm
6779 daemon 20 0 8184 1112 556 R 0.3 0.0 0:00.01 stress
...
- 用户
CPU 使用率
还是高达80.9%
,系统CPU
接近15%
,而空闲 CPU
只有2.8%
,Running
状态的进程有Nginx
、stress
等- 这次
stress
进程的PID
跟前面不一样了,原来的PID 24344
不见了,现在的是6779
根据上面分析发现,stress
的进程PID
一直在不停的更换,而进程PID
更换原因一般为如下两种:
进程
在不停地崩溃重启
,比如因为段错误
、配置错误
等等,这时,进程在退出后可能又被监控系统自动重启
了- 这些进程都是短时进程,也就是在其他应用内部通过
exec
调用的外面命令。这些命令一般都只运行很短的时间就会结束,你很难用top
这种间隔时间比较长的工具发现
stress
,我们前面提到过,它是一个常用的压力测试工具。它的 PID
在不断变化中,看起来像是被其他进程调用的短时进程。要想继续分析下去,还得找到它们的父进程
- 使用pstree命令 查看stress的父进程
$ pstree | grep stress
|-docker-containe-+-php-fpm-+-php-fpm---sh---stress
| |-3*[php-fpm---sh---stress---stress]
- 查看源码中是否又调用
# 拷贝源码到本地
$ docker cp phpfpm:/app .
# grep 查找看看是不是有代码在调用stress命令
$ grep stress -r app
app/index.php:// fake I/O with stress (via write()/unlink()).
app/index.php:$result = exec("/usr/local/bin/stress -t 1 -d 1 2>&1", $output, $status);
果然是 app/index.php
文件中直接调用了 stress
命令,果断打开文件查看如下:
$ cat app/index.php
<?php
// fake I/O with stress (via write()/unlink()).
$result = exec("/usr/local/bin/stress -t 1 -d 1 2>&1", $output, $status);
if (isset($_GET["verbose"]) && $_GET["verbose"]==1 && $status != 0) {
echo "Server internal error: ";
print_r($output);
} else {
echo "It works!";
}
?>
从代码中可以看到,给请求加入 verbose=1
参数后,就可以查看 stress
的输出
$ curl http://127.0.0.1:10000?verbose=1
Server internal error: Array
(
[0] => stress: info: [19607] dispatching hogs: 0 cpu, 0 io, 0 vm, 1 hdd
[1] => stress: FAIL: [19608] (563) mkstemp failed: Permission denied
[2] => stress: FAIL: [19607] (394) <-- worker 19608 returned error 1
[3] => stress: WARN: [19607] (396) now reaping child worker processes
[4] => stress: FAIL: [19607] (400) kill error: No such process
[5] => stress: FAIL: [19607] (451) failed run completed in 0s
)
看错误消息 mkstemp failed: Permission denied
,以及 failed run completed in 0s
。原来stress
命令并没有成功,它因为权限问题失败退出了。看来,我们发现了一个 PHP
调用外部 stress
命令的 bug:没有权限创建临时文件
- 在上面的案例中
top
、idstat
、pstree
等工具,都没有发现大量的stress
进程,此时如果使用perf
分析cpu
是非常合适的
# 记录性能事件,等待大约15秒后按 Ctrl+C 退出
$ perf record -g
# 查看报告
$ perf report
stress
占了所有 CPU 时钟事件
的 77%
,而 stress
调用栈中比例最高的,是随机数生成函数 random()
,看来它的确就是 CPU 使用率
升高的元凶了。随后的优化就很简单了,只要修复权限问题,并减少或删除 stress
的调用,就可以减轻系统的 CPU 压力
总结
- 当
pidstat
,vmstat
,top
无法定位到问题的时候 - 因考虑进程本身,是否存在短时运行的情况
- 对于这类进程,可以用
pstree
execsnoop
perf
排查
Tips
关于execsnoop
execsnoop 是一个专为短时进程设计的工具。它通过 ftrace 实时监控进程的 exec() 行为,并输出短时进程的基本信息,包括进程 PID、父进程 PID、命令行参数以及执行的结果。
用 execsnoop
监控上述案例,就可以直接得到 stress
进程的父进程 PID
以及它的命令行参数,并可以发现大量的 stress
进程在不停启动:
# 按 Ctrl+C 结束
$ execsnoop
PCOMM PID PPID RET ARGS
sh 30394 30393 0
stress 30396 30394 0 /usr/local/bin/stress -t 1 -d 1
sh 30398 30393 0
stress 30399 30398 0 /usr/local/bin/stress -t 1 -d 1
sh 30402 30400 0
stress 30403 30402 0 /usr/local/bin/stress -t 1 -d 1
sh 30405 30393 0
stress 30407 30405 0 /usr/local/bin/stress -t 1 -d 1
...
execsnoop 所用的 ftrace 是一种常用的动态追踪技术,一般用于分析 Linux 内核的运行时行为