五. 性能优化之案例篇：系统的 CPU 使用率很高，但为啥却找不到高 CPU 的应用？

文章目录

案例背景案例分析准备工作操作和分析 总结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 内核的运行时行为