上一节我讲了 CPU 使用率是什么，并通过一个案例教你使用 top、vmstat、pidstat 等工具，排查高 CPU 使用率的进程，然后再使用 perf top 工具，定位应用内部函数的问题。不过就有人留言了，说似乎感觉高 CPU 使用率的问题，还是挺容易排查的。
那是不是所有 CPU 使用率高的问题，都可以这么分析呢？我想，你的答案应该是否定的。
回顾前面的内容，我们知道，系统的 CPU 使用率，不仅包括进程用户态和内核态的运行，还包括中断处理、等待 I/O 以及内核线程等。所以，当你发现系统的 CPU 使用率很高的时候，不一定能找到相对应的高 CPU 使用率的进程。
今天，我就用一个 Nginx + PHP 的 Web 服务的案例，带你来分析这种情况。
操作和分析
首先，我们在第一个终端，执行下面的命令运行 Nginx 和 PHP 应用：
[root@localhost ~]# docker run --name nginx -p 10000:80 -itd feisky/nginx:sp
724f49267a44fe533de12be885940bb84ff109ccc4eef00d08a705d72e573bd8
[root@localhost ~]# docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp
cc4ff1700f3e17da7757e2565542325b34853bba5c17f7d53626558699b66f71
然后，在第二个终端，使用 curl 访问 http://[VM1 的 IP]:10000，确认 Nginx 已正常启动。你应该可以看到 It works! 的响应。
# 192.168.179.99是第一台虚拟机的IP地址
[root@localhost ~]# curl 192.168.179.99:10000
It works!
接着，我们来测试一下这个 Nginx 服务的性能。在第二个终端运行下面的 ab 命令。要注意，与上次操作不同的是，这次我们需要并发 100 个请求测试 Nginx 性能，总共测试 1000 个请求。
# 并发100个请求测试Nginx性能，总共测试1000个请求
[root@localhost ~]# ab -c 100 -n 1000 http://192.168.179.99:10000/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
...
Requests per second: 87.86 [#/sec] (mean)
Time per request: 1138.229 [ms] (mean)
...
从 ab 的输出结果我们可以看到，Nginx 能承受的每秒平均请求数，只有 87 多一点，是不是感觉它的性能有点差呀。那么，到底是哪里出了问题呢？我们再用 top 和 pidstat 来观察一下。
这次，我们在第二个终端，将测试的并发请求数改成 5，同时把请求时长设置为 10 分钟（-t 600）。这样，当你在第一个终端使用性能分析工具时， Nginx 的压力还是继续的。
继续在第二个终端运行 ab 命令：
[root@localhost ~]# ab -c 5 -t 600 http://192.168.179.99:10000/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 192.168.179.99 (be patient)
然后，我们在第一个终端运行 top 命令，观察系统的 CPU 使用情况：
[root@localhost ~]# top
top - 17:22:58 up 1 day, 17:43, 5 users, load average: 2.82, 1.98, 1.22
Tasks: 131 total, 6 running, 125 sleeping, 0 stopped, 0 zombie
%Cpu(s): 84.1 us, 13.3 sy, 0.0 ni, 1.4 id, 0.0 wa, 0.0 hi, 1.2 si, 0.0 st
KiB Mem : 1765672 total, 143216 free, 186828 used, 1435628 buff/cache
KiB Swap: 524284 total, 478172 free, 46112 used. 1267828 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
76584 101 20 0 33092 2200 776 S 2.7 0.1 0:01.41 nginx
79643 bin 20 0 336684 7696 1912 S 1.7 0.4 0:00.68 php-fpm
79648 bin 20 0 336684 7684 1900 S 1.7 0.4 0:00.70 php-fpm
79657 bin 20 0 336684 7696 1912 S 1.7 0.4 0:00.65 php-fpm
79664 bin 20 0 336684 7684 1900 S 1.7 0.4 0:00.69 php-fpm
79642 root 20 0 60024 3000 2240 S 1.3 0.2 0:00.58 ab
79667 bin 20 0 336684 7688 1904 R 1.3 0.4 0:00.65 php-fpm
17478 root 20 0 627164 71076 27432 S 1.0 4.0 3:18.93 dockerd
76541 root 20 0 109096 3736 2700 S 1.0 0.2 0:00.50 containerd-shim
76611 root 20 0 336300 33092 27696 S 0.3 1.9 0:00.21 php-fpm
89786 bin 20 0 8176 600 104 R 0.3 0.0 0:00.01 stress
89788 bin 20 0 8176 604 104 R 0.3 0.0 0:00.01 stress
1 root 20 0 125600 2712 1564 S 0.0 0.2 0:18.39 systemd
观察 top 输出的进程列表可以发现，CPU 使用率最高的进程也只不过才 2.7%，看起来并不高。
然而，再看系统 CPU 使用率（ %Cpu ）这一行，你会发现，系统的整体 CPU 使用率是比较高的：用户 CPU 使用率（us）已经到了 84.1%，系统 CPU 为 13.3%，而空闲 CPU （id）则只有 1.4%。
为什么用户 CPU 使用率这么高呢？我们再重新分析一下进程列表，看看有没有可疑进程：
- Nginx 和 php-fpm 是运行 Web 服务的，它们会占用一些 CPU 也不意外，并且 1% 的 CPU 使用率也不算高
- 再往下看，后面的进程呢，只有 0.3% 的 CPU 使用率，看起来不太像会导致用户 CPU 使用率达到 80%
那就奇怪了，明明用户 CPU 使用率都 80% 了，可我们挨个分析了一遍进程列表，还是找不到高 CPU 使用率的进程。看来 top 是不管用了，那还有其他工具可以查看进程 CPU 使用情况吗？不知道你记不记得我们的老朋友 pidstat，它可以用来分析进程的 CPU 使用情况。
接下来，我们还是在第一个终端，运行 pidstat 命令：
# 间隔1秒输出一组数据（按Ctrl+C结束）
[root@localhost ~]# pidstat 1
...
05:26:08 PM UID PID %usr %system %guest %CPU CPU Command
05:26:09 PM 0 3026 0.00 1.00 0.00 1.00 1 pidstat
05:26:09 PM 0 29992 0.00 1.00 0.00 1.00 1 kworker/1:0
05:26:09 PM 0 76541 0.00 1.00 0.00 1.00 0 containerd-shim
05:26:09 PM 101 76584 0.00 3.00 0.00 3.00 0 nginx
05:26:09 PM 0 79642 0.00 1.00 0.00 1.00 1 ab
05:26:09 PM 1 79643 0.00 2.00 0.00 2.00 1 php-fpm
05:26:09 PM 1 79648 0.00 1.00 0.00 1.00 0 php-fpm
05:26:09 PM 1 79657 0.00 1.00 0.00 1.00 0 php-fpm
05:26:09 PM 1 79664 0.00 2.00 0.00 2.00 0 php-fpm
05:26:09 PM 1 79667 0.00 1.00 0.00 1.00 1 php-fpm
...
观察一会儿，你是不是发现，所有进程的 CPU 使用率也都不高啊，最高的 pidstat 和 kworker/1:0 也只有 1% 和 1%，即使所有进程的 CPU 使用率都加起来，也不过是 21%，离 80% 还差得远呢！
最早的时候，我碰到这种问题就完全懵了：明明用户 CPU 使用率已经高达 80%，但我却怎么都找不到是哪个进程的问题。到这里，你也可以想想，你是不是也遇到过这种情况？还能不能再做进一步的分析呢？
后来我发现，会出现这种情况，很可能是因为前面的分析漏了一些关键信息。你可以先暂停一下，自己往上翻，重新操作检查一遍。或者，我们一起返回去分析 top 的输出，看看能不能有新发现。
现在，我们回到第一个终端，重新运行 top 命令，并观察一会儿：
[root@localhost ~]# top
top - 17:31:22 up 1 day, 17:51, 6 users, load average: 6.39, 5.64, 3.42
Tasks: 131 total, 6 running, 124 sleeping, 0 stopped, 0 zombie
%Cpu(s): 80.4 us, 11.7 sy, 0.0 ni, 7.3 id, 0.0 wa, 0.0 hi, 0.7 si, 0.0 st
KiB Mem : 1765672 total, 103596 free, 187828 used, 1474248 buff/cache
KiB Swap: 524284 total, 478192 free, 46092 used. 1256084 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
76584 101 20 0 33092 2200 776 S 2.7 0.1 0:15.00 nginx
79643 bin 20 0 336684 7708 1924 S 1.7 0.4 0:08.76 php-fpm
79657 bin 20 0 336684 7704 1920 S 1.7 0.4 0:08.56 php-fpm
79642 root 20 0 60024 4312 2320 S 1.3 0.2 0:07.06 ab
79648 bin 20 0 336684 7692 1908 S 1.3 0.4 0:08.79 php-fpm
79664 bin 20 0 336684 7696 1912 S 1.3 0.4 0:08.64 php-fpm
79667 bin 20 0 336684 7700 1916 S 1.3 0.4 0:08.48 php-fpm
76541 root 20 0 109096 3696 2708 S 1.0 0.2 0:05.49 containerd-shim
17478 root 20 0 627164 71076 27432 S 0.7 4.0 3:22.84 dockerd
962 root 20 0 562408 812 480 S 0.3 0.0 0:42.79 tuned
76652 bin 20 0 8176 600 104 R 0.3 0.0 0:00.01 stress
76653 bin 20 0 8172 596 104 R 0.3 0.0 0:00.01 stress
76660 bin 20 0 8172 600 104 R 0.3 0.0 0:00.01 stress
1 root 20 0 125600 2712 1564 S 0.0 0.2 0:18.41 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.70 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:20.88 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
这次从头开始看 top 的每行输出，咦？Tasks 这一行看起来有点奇怪，就绪队列中居然有 6 个 Running 状态的进程（6 running），是不是有点多呢？
回想一下 ab 测试的参数，并发请求数是 5。再看进程列表里， php-fpm 的数量也是 5，再加上 Nginx，好像同时有 6 个进程也并不奇怪。但真的是这样吗？
再仔细看进程列表，这次主要看 Running（R） 状态的进程。你有没有发现， Nginx 和所有的 php-fpm 都处于 Sleep（S）状态，而真正处于 Running（R）状态的，却是几个 stress 进程。这几个 stress 进程就比较奇怪了，需要我们做进一步的分析。
我们还是使用 pidstat 来分析这几个进程，并且使用 -p 选项指定进程的 PID。首先，从上面 top 的结果中，找到这几个进程的 PID。比如，先随便找一个 24344，然后用 pidstat 命令看一下它的 CPU 使用情况：
[root@localhost ~]# pidstat -p 76652
Linux 3.10.0-693.el7.x86_64 (localhost.localdomain) 11/11/2020 _x86_64_ (2 CPU)
05:32:55 PM UID PID %usr %system %guest %CPU CPU Command
奇怪，居然没有任何输出。难道是 pidstat 命令出问题了吗？之前我说过，在怀疑性能工具出问题前，最好还是先用其他工具交叉确认一下。那用什么工具呢？ ps 应该是最简单易用的。我们在终端里运行下面的命令，看看 24344 进程的状态：
# 从所有进程中查找PID是76652的进程
[root@localhost ~]# ps -aux | grep 76652
root 89099 0.0 0.0 112660 968 pts/1 S+ 17:33 0:00 grep --color=auto 76652
还是没有输出。现在终于发现问题，原来这个进程已经不存在了，所以 pidstat 就没有任何输出。既然进程都没了，那性能问题应该也跟着没了吧。我们再用 top 命令确认一下：
[root@localhost ~]# top
top - 17:34:34 up 1 day, 17:55, 4 users, load average: 1.40, 3.79, 3.14
Tasks: 126 total, 6 running, 120 sleeping, 0 stopped, 0 zombie
%Cpu(s): 78.4 us, 13.2 sy, 0.0 ni, 7.5 id, 0.0 wa, 0.0 hi, 0.8 si, 0.0 st
KiB Mem : 1765672 total, 117032 free, 182640 used, 1466000 buff/cache
KiB Swap: 524284 total, 478196 free, 46088 used. 1273212 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
76584 101 20 0 33092 2200 776 S 2.7 0.1 0:16.71 nginx
89102 bin 20 0 336684 7708 1924 S 2.0 0.4 0:00.17 php-fpm
89114 bin 20 0 336684 7684 1900 S 1.7 0.4 0:00.16 php-fpm
89123 bin 20 0 336684 7684 1900 S 1.7 0.4 0:00.16 php-fpm
89128 bin 20 0 336684 7684 1900 S 1.7 0.4 0:00.15 php-fpm
89106 bin 20 0 336684 7688 1904 S 1.3 0.4 0:00.16 php-fpm
89101 root 20 0 60024 3000 2240 S 1.0 0.2 0:00.13 ab
17478 root 20 0 627164 71076 27432 S 0.7 4.0 3:23.38 dockerd
76541 root 20 0 109096 3712 2708 S 0.7 0.2 0:06.13 containerd-shim
361 root 20 0 36968 5768 5544 S 0.3 0.3 0:13.45 systemd-journal
91779 bin 20 0 8172 1120 104 R 0.3 0.1 0:00.01 stress
91781 bin 20 0 8172 600 104 R 0.3 0.0 0:00.01 stress
91787 bin 20 0 8172 856 104 R 0.3 0.0 0:00.01 stress
1 root 20 0 125600 2712 1564 S 0.0 0.2 0:18.41 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.70 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:20.91 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
好像又错了。结果还跟原来一样，用户 CPU 使用率还是高达 80.9%，系统 CPU 接近 15%，而空闲 CPU 只有 2.8%，Running 状态的进程有 Nginx、stress 等。
可是，刚刚我们看到 stress 进程不存在了，怎么现在还在运行呢？再细看一下 top 的输出，原来，这次 stress 进程的 PID 跟前面不一样了，原来的 PID 76652 不见了，现在的是 91779。
进程的 PID 在变，这说明什么呢？在我看来，要么是这些进程在不停地重启，要么就是全新的进程，这无非也就两个原因：
- 第一个原因，进程在不停地崩溃重启，比如因为段错误、配置错误等等，这时，进程在退出后可能又被监控系统自动重启了。
- 第二个原因，这些进程都是短时进程，也就是在其他应用内部通过 exec 调用的外面命令。这些命令一般都只运行很短的时间就会结束，你很难用 top 这种间隔时间比较长的工具发现（上面的案例，我们碰巧发现了）。
至于 stress，我们前面提到过，它是一个常用的压力测试工具。它的 PID 在不断变化中，看起来像是被其他进程调用的短时进程。要想继续分析下去，还得找到它们的父进程。
要怎么查找一个进程的父进程呢？没错，用 pstree 就可以用树状形式显示所有进程之间的关系：
[root@localhost ~]# pstree | grep stress
| |-containerd-shim-+-php-fpm-+-4*[php-fpm---sh---stress---stress]
从这里可以看到，stress 是被 php-fpm 调用的子进程，并且进程数量不止一个（这里是 4个）。找到父进程后，我们能进入 app 的内部分析了。
首先，当然应该去看看它的源码。运行下面的命令，把案例应用的源码拷贝到 app 目录，然后再执行 grep 查找是不是有代码再调用 stress 命令：
# 拷贝源码到本地
[root@localhost ~]# docker exec -it phpfpm /bin/bash
root@724f49267a44:/app# pwd
/app
root@724f49267a44:/app# ls
404.html index.php ok.php phpinfo.php
root@724f49267a44:/app# exit
exit
[root@localhost ~]# docker cp phpfpm:/app .
[root@localhost ~]# ls
anaconda-ks.cfg app
# grep 查找看看是不是有代码在调用stress命令
[root@localhost ~]# 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 命令。
再来看看 app/index.php 的源代码：
[root@localhost ~]# 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!";
}
可以看到，源码里对每个请求都会调用一个 stress 命令，模拟 I/O 压力。从注释上看，stress 会通过 write() 和 unlink() 对 I/O 进程进行压测，看来，这应该就是系统 CPU 使用率升高的根源了。
不过，stress 模拟的是 I/O 压力，而之前在 top 的输出中看到的，却一直是用户 CPU 和系统 CPU 升高，并没见到 iowait 升高。这又是怎么回事呢？stress 到底是不是 CPU 使用率升高的原因呢？
我们还得继续往下走。从代码中可以看到，给请求加入 verbose=1 参数后，就可以查看 stress 的输出。你先试试看，在第二个终端运行：
[root@localhost ~]# curl http://192.168.179.99:10000?verbose=1
Server internal error: Array
(
[0] => stress: info: [31514] dispatching hogs: 0 cpu, 0 io, 0 vm, 1 hdd
[1] => stress: FAIL: [31515] (563) mkstemp failed: Permission denied
[2] => stress: FAIL: [31514] (394) <-- worker 31515 returned error 1
[3] => stress: WARN: [31514] (396) now reaping child worker processes
[4] => stress: FAIL: [31514] (400) kill error: No such process
[5] => stress: FAIL: [31514] (451) failed run completed in 0s
)
看错误消息 mkstemp failed: Permission denied ，以及 failed run completed in 0s。原来 stress 命令并没有成功，它因为权限问题失败退出了。看来，我们发现了一个 PHP 调用外部 stress 命令的 bug：没有权限创建临时文件。
从这里我们可以猜测，正是由于权限错误，大量的 stress 进程在启动时初始化失败，进而导致用户 CPU 使用率的升高。
分析出问题来源，下一步是不是就要开始优化了呢？当然不是！既然只是猜测，那就需要再确认一下，这个猜测到底对不对，是不是真的有大量的 stress 进程。该用什么工具或指标呢？
我们前面已经用了 top、pidstat、pstree 等工具，没有发现大量的 stress 进程。那么，还有什么其他的工具可以用吗？
# 记录性能事件，等待大约15秒后按 Ctrl+C 退出
$ perf record -g
# 查看报告
$ perf report
这样，你就可以看到下图这个性能报告：
你看，stress 占了所有 CPU 时钟事件的 77%，而 stress 调用调用栈中比例最高的，是随机数生成函数 random()，看来它的确就是 CPU 使用率升高的元凶了。随后的优化就很简单了，只要修复权限问题，并减少或删除 stress 的调用，就可以减轻系统的 CPU 压力。
小结
碰到常规问题无法解释的 CPU 使用率情况时，首先要想到有可能是短时应用导致的问题，比如有可能是下面这两种情况。
- 第一，应用里直接调用了其他二进制程序，这些程序通常运行时间比较短，通过 top 等工具也不容易发现。
- 第二，应用本身在不停地崩溃重启，而启动过程的资源初始化，很可能会占用相当多的 CPU。
对于这类进程，我们可以用 pstree 或者 execsnoop 找到它们的父进程，再从父进程所在的应用入手，排查问题的根源。
