环境准备
docker run --name nginx -p 10000:80 -itd feisky/nginx:sp docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp
请求检查环境
curl http://192.168.10.16:10000 It works!
使用ab做压测
[root@master ~]# ab -c 100 -n 1000 http://192.168.10.16: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.10.16 (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests
Server Software: nginx/1.15.4
Server Hostname: 192.168.10.16
Server Port: 10000
Document Path: /
Document Length: 9 bytes
Concurrency Level: 100
Time taken for tests: 12.760 seconds
Complete requests: 1000
Failed requests: 0
Write errors: 0
Total transferred: 172000 bytes
HTML transferred: 9000 bytes
Requests per second: 78.37 [#/sec] (mean) 每秒处理请求数量78.37太慢了
Time per request: 1276.036 [ms] (mean)
Time per request: 12.760 [ms] (mean, across all concurrent requests)
Transfer rate: 13.16 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 4 45.1 1 1004
Processing: 30 1207 220.7 1269 1396
Waiting: 26 1206 220.6 1267 1396
Total: 35 1211 224.4 1270 2260
Percentage of the requests served within a certain time (ms)
50% 1270
66% 1285
75% 1294
80% 1300
90% 1315
95% 1325
98% 1339
99% 1353
100% 2260 (longest request)
将并发数量改成5，一共发送请求10000个
[root@master ~]# ab -c 5 -n 10000 http://192.168.10.16:10000/
在第一个终端运行 top 命令，观察系统的 CPU 使用情况
top - 11:18:41 up 21:59, 4 users, load average: 2.04, 2.51, 3.91
Tasks: 142 total, 5 running, 137 sleeping, 0 stopped, 0 zombie
%Cpu(s): 68.4 us, 23.1 sy, 0.0 ni, 3.5 id, 0.0 wa, 0.0 hi, 4.9 si, 0.0 st
KiB Mem : 8009556 total, 6882636 free, 301124 used, 825796 buff/cache
KiB Swap: 5242876 total, 5242876 free, 0 used. 7374772 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18335 101 20 0 33092 2192 768 R 6.6 0.0 1:25.26 nginx
6499 bin 20 0 336684 9572 1896 S 4.0 0.1 0:00.85 php-fpm
6479 bin 20 0 336684 9596 1920 S 3.3 0.1 0:00.91 php-fpm
6505 bin 20 0 336684 9572 1896 S 3.3 0.1 0:00.86 php-fpm
6508 bin 20 0 336684 9576 1900 S 3.3 0.1 0:00.83 php-fpm
6488 bin 20 0 336684 9572 1896 S 3.0 0.1 0:00.85 php-fpm
18288 root 20 0 109096 8824 2560 S 2.0 0.1 0:28.74 containerd-shim
16354 root 20 0 665628 81792 28940 S 1.3 1.0 0:50.51 dockerd
9 root 20 0 0 0 0 S 1.0 0.0 0:16.38 rcu_sched
14 root 20 0 0 0 0 S 1.0 0.0 0:20.61 ksoftirqd/1
7513 root 20 0 162012 2304 1604 R 0.3 0.0 0:00.06 top
12135 bin 20 0 8168 860 104 R 0.3 0.0 0:00.01 stress
12136 bin 20 0 8172 864 104 R 0.3 0.0 0:00.01 stress
18336 101 20 0 33092 2188 764 S 0.3 0.0 0:02.32 nginx
1 root 20 0 191108 4028 2628 S 0.0 0.1 0:04.87 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.08 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:02.21 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root rt 0 0 0 0 S 0.0 0.0 0:00.60 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain
11 root rt 0 0 0 0 S 0.0 0.0 0:01.87 watchdog/0
12 root rt 0 0 0 0 S 0.0 0.0 0:02.26 watchdog/1
13 root rt 0 0 0 0 S 0.0 0.0 0:00.65 migration/1
16 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/1:0H
18 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kdevtmpfs
用户态CPU达将近69%；观察 top 输出的进程列表可以发现，CPU 使用率最高的进程也只不过才 2.7%，看起来并不高。
然而，再看系统 CPU 使用率（ %Cpu ）这一行，你会发现，系统的整体 CPU 使用率是比较高的：用户 CPU 使用率（us）已经到了68.4%，系统 CPU 为 23.1%，而空闲 CPU （id）则只有 3.5%。
docker-containerd 进程是用来运行容器的，1.3% 的 CPU 使用率看起来正常；Nginx 和 php-fpm 是运行 Web 服务的，它们会占用一些 CPU 也不意外，并且 6.6% 的 CPU 使用率也不算高；再往下看，后面的进程呢，只有 0.3% 的 CPU 使用率，看起来不太像会导致用户 CPU 使用率达到 68%。
第一个终端，运行 pidstat 命令：
[root@linux-xingnengyouhua ~]# pidstat 1 间隔1秒 Linux 3.10.0-957.el7.x86_64 (linux-xingnengyouhua) 2020年08月23日 _x86_64_ (2 CPU) 11时25分53秒 UID PID %usr %system %guest %wait %CPU CPU Command 11时25分54秒 0 7 0.00 0.96 0.00 0.00 0.96 0 migration/0 11时25分54秒 0 14 0.00 0.96 0.00 0.96 0.96 1 ksoftirqd/1 11时25分54秒 1 4118 0.96 3.85 0.00 4.81 4.81 1 php-fpm 11时25分54秒 1 4128 0.00 3.85 0.00 5.77 3.85 1 php-fpm 11时25分54秒 1 4133 0.00 2.88 0.00 6.73 2.88 1 php-fpm 11时25分54秒 1 4135 0.00 1.92 0.00 4.81 1.92 0 php-fpm 11时25分54秒 1 4147 0.00 2.88 0.00 5.77 2.88 1 php-fpm 11时25分54秒 0 7093 0.00 1.92 0.00 0.00 1.92 0 pidstat 11时25分54秒 0 16354 0.96 0.96 0.00 0.00 1.92 1 dockerd 11时25分54秒 0 18288 0.96 1.92 0.00 0.00 2.88 1 containerd-shim 11时25分54秒 101 18335 0.96 5.77 0.00 14.42 6.73 1 nginx
观察一会儿，所有进程的 CPU 使用率也都不高啊，最高的 Docker 和 Nginx 也只有 4% 和 6%，即使所有进程的 CPU 使用率都加起来，也不过是 30%多，离 68% 还差得远呢！
在使用top观察一下
top - 11:29:26 up 22:10, 5 users, load average: 5.89, 3.97, 3.74
Tasks: 140 total, 7 running, 136 sleeping, 0 stopped, 0 zombie
%Cpu(s): 65.1 us, 24.1 sy, 0.0 ni, 5.7 id, 0.0 wa, 0.0 hi, 5.1 si, 0.0 st
KiB Mem : 8009556 total, 6846676 free, 305744 used, 857136 buff/cache
KiB Swap: 5242876 total, 5242876 free, 0 used. 7350044 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18335 101 20 0 33092 2192 768 S 7.0 0.0 1:49.24 nginx
4118 bin 20 0 336684 9596 1920 S 3.7 0.1 0:07.68 php-fpm
4133 bin 20 0 336684 9584 1908 S 3.7 0.1 0:07.60 php-fpm
18288 root 20 0 109096 8824 2560 S 3.7 0.1 0:36.80 containerd-shim
4128 bin 20 0 336684 9584 1908 S 3.3 0.1 0:07.87 php-fpm
4135 bin 20 0 336684 9592 1916 S 3.3 0.1 0:07.74 php-fpm
4147 bin 20 0 336684 9592 1916 S 3.3 0.1 0:07.66 php-fpm
14 root 20 0 0 0 0 S 2.3 0.0 0:24.68 ksoftirqd/1
3 root 20 0 0 0 0 S 1.0 0.0 0:02.53 ksoftirqd/0
7513 root 20 0 162012 2304 1604 R 1.0 0.0 0:01.38 top
16354 root 20 0 665628 81792 28940 S 1.0 1.0 0:55.95 dockerd
9 root 20 0 0 0 0 R 0.7 0.0 0:20.55 rcu_sched
13 root rt 0 0 0 0 S 0.3 0.0 0:00.75 migration/1
18146 root 20 0 161364 6056 4668 S 0.3 0.1 0:02.17 sshd
18336 101 20 0 33092 2188 764 S 0.3 0.0 0:03.01 nginx
20866 bin 20 0 8176 868 104 R 0.3 0.0 0:00.01 stress
20867 bin 20 0 8176 600 104 R 0.3 0.0 0:00.01 stress
1 root 20 0 191108 4028 2628 S 0.0 0.1 0:04.88 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.08 kthreadd
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root rt 0 0 0 0 S 0.0 0.0 0:00.69 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain
11 root rt 0 0 0 0 S 0.0 0.0 0:01.91 watchdog/0
12 root rt 0 0 0 0 S 0.0 0.0 0:02.27 watchdog/1
16 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kwork
Tasks 这一行看起来有点奇怪，就绪队列中居然有 7 个 Running 状态的进程（4running）
ab 测试的参数，并发请求数是 5。再看进程列表里， php-fpm 的数量也是 5，再加上 Nginx，好像同时有 7 个进程也并不奇怪。
再仔细看进程列表，这次主要看 Running（R） 状态的进程。你有没有发现， Nginx 和所有的 php-fpm 都处于 Sleep（S）状态，而真正处于 Running（R）状态的，却是几个 stress 进程。这几个 stress 进程就比较奇怪了
使用pidstat查看这个进程
[root@linux-xingnengyouhua ~]# pidstat -p 20866 Linux 3.10.0-957.el7.x86_64 (linux-xingnengyouhua) 2020年08月23日 _x86_64_ (2 CPU) 11时33分05秒 UID PID %usr %system %guest %wait %CPU CPU Command
没有输出。现在终于发现问题，原来这个进程已经不存在了，所以 pidstat 就没有任何输出。既然进程都没了，那性能问题应该也跟着没了吧。我们再用 top 命令确认一下
top - 11:35:09 up 22:16, 5 users, load average: 6.64, 5.65, 4.56
Tasks: 141 total, 6 running, 135 sleeping, 0 stopped, 0 zombie
%Cpu(s): 67.2 us, 24.5 sy, 0.0 ni, 3.4 id, 0.0 wa, 0.0 hi, 4.9 si, 0.0 st
KiB Mem : 8009556 total, 6824532 free, 308104 used, 876920 buff/cache
KiB Swap: 5242876 total, 5242876 free, 0 used. 7339328 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18335 101 20 0 33092 2192 768 S 6.6 0.0 2:13.38 nginx
4133 bin 20 0 336684 9592 1916 S 3.7 0.1 0:19.44 php-fpm
4118 bin 20 0 336684 9596 1920 S 3.3 0.1 0:19.42 php-fpm
4128 bin 20 0 336684 9596 1920 S 3.3 0.1 0:19.81 php-fpm
4135 bin 20 0 336684 9592 1916 S 3.3 0.1 0:19.53 php-fpm
4147 bin 20 0 336684 9592 1916 S 3.3 0.1 0:19.37 php-fpm
18288 root 20 0 109096 8824 2560 S 2.7 0.1 0:44.79 containerd-shim
16354 root 20 0 665628 81792 28940 S 1.7 1.0 1:01.34 dockerd
14 root 20 0 0 0 0 S 1.0 0.0 0:28.13 ksoftirqd/1
9 root 20 0 0 0 0 S 0.7 0.0 0:22.87 rcu_sched
13 root rt 0 0 0 0 S 0.3 0.0 0:00.85 migration/1
7513 root 20 0 162012 2304 1604 R 0.3 0.0 0:02.25 top
30239 root 20 0 0 0 0 S 0.3 0.0 0:01.94 kworker/1:0
30855 bin 20 0 8172 860 104 R 0.3 0.0 0:00.01 stress
1 root 20 0 191108 4028 2628 S 0.0 0.1 0:04.88 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.08 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:02.78 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root rt 0 0 0 0 S 0.0 0.0 0:00.77 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain
11 root rt 0 0 0 0 S 0.0 0.0 0:01.92 watchdog/0
12 root rt 0 0 0 0 S 0.0 0.0 0:02.28 watchdog/1
16 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/1:0H
18 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kdevtmpfs
19 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 netns
原来，这次 stress 进程的 PID 跟前面不一样了，原来的 PID 20688 不见了，现在的是 30885。
进程的 PID 在变，要么是这些进程在不停地重启，要么就是全新的进程，这无非也就两个原因：
第一个原因，进程在不停地崩溃重启，比如因为段错误、配置错误等等，这时，进程在退出后可能又被监控系统自动重启了。
第二个原因，这些进程都是短时进程，也就是在其他应用内部通过 exec 调用的外面命令。这些命令一般都只运行很短的时间就会结束，你很难用 top 这种间隔时间比较长的工具发现（上面的案例，我们碰巧发现了）。
用 pstree 就可以用树状形式显示所有进程之间的关系：
[root@linux-xingnengyouhua bin]# pstree | grep stress
| | | |-php-fpm---sh---stress
| | | `-3*[php-fpm---sh---stress---stress]
从这里可以看到，stress 是被 php-fpm 调用的子进程，并且进程数量不止一个（这里是 3 个）。找到父进程后，我们能进入 app 的内部分析了
首先，当然应该去看看它的源码。运行下面的命令，把案例应用的源码拷贝到 app 目录，然后再执行 grep 查找是不是有代码再调用 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!";
}
?>
可以看到，源码里对每个请求都会调用一个 stress 命令，模拟 I/O 压力。从注释上看，stress 会通过 write() 和 unlink() 对 I/O 进程进行压测，看来，这应该就是系统 CPU 使用率升高的根源了。不过，stress 模拟的是 I/O 压力，而之前在 top 的输出中看到的，却一直是用户 CPU 和系统 CPU 升高，并没见到 iowait 升高；从代码中可以看到，给请求加入 verbose=1 参数后，就可以查看 stress 的输出
[root@master ~]# curl http://192.168.10.16:10000?verbose=1
Server internal error: Array
(
[0] => stress: info: [12036] dispatching hogs: 0 cpu, 0 io, 0 vm, 1 hdd
[1] => stress: FAIL: [12040] (563) mkstemp failed: Permission denied
[2] => stress: FAIL: [12036] (394) <-- worker 12040 returned error 1
[3] => stress: WARN: [12036] (396) now reaping child worker processes
[4] => stress: FAIL: [12036] (400) kill error: No such process
[5] => stress: FAIL: [12036] (451) failed run completed in 0s
)
看错误消息 mkstemp failed: Permission denied ，以及 failed run completed in 0s。原来 stress 命令并没有成功，它因为权限问题失败退出了。
从这里我们可以推测，正是由于权限错误，大量的 stress 进程在启动时初始化失败，进而导致用户 CPU 使用率的升高。
这时可以使用短时应该工具分析
安装工具
cd /usr/bin/ wget https://raw.githubusercontent.com/brendangregg/perf-tools/master/execsnoop chmod +x execsnoop
运行
[root@linux-xingnengyouhua bin]# execsnoop -d 1 Tracing exec()s for 1 seconds (buffered)... Instrumenting sys_execve PID PPID ARGS 1656 0 <...>-1656 [001] d... 80948.458145: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1657 1655 /usr/local/bin/stress -t 1 -d 1 1660 1642 awk -v o=1 -v opt_name=0 -v name= -v opt_duration=1 [...] 1662 1659 sleep 1 1661 1656 /usr/local/bin/stress -t 1 -d 1 1665 4135 <...>-1665 [000] d... 80948.480052: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1666 1665 /usr/local/bin/stress -t 1 -d 1 1667 4128 <...>-1667 [001] d... 80948.491465: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1669 1667 /usr/local/bin/stress -t 1 -d 1 1671 4147 <...>-1671 [000] d... 80948.518381: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1672 4133 <...>-1672 [000] d... 80948.524852: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1674 1671 /usr/local/bin/stress -t 1 -d 1 1673 4118 <...>-1673 [000] d... 80948.526293: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1676 1673 /usr/local/bin/stress -t 1 -d 1 1677 4135 <...>-1677 [001] d... 80948.542514: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1678 1672 /usr/local/bin/stress -t 1 -d 1 1680 1677 /usr/local/bin/stress -t 1 -d 1 1684 4128 <...>-1684 [001] d... 80948.549942: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1683 4147 <...>-1683 [001] d... 80948.551807: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1685 1684 /usr/local/bin/stress -t 1 -d 1 1686 1683 /usr/local/bin/stress -t 1 -d 1 1689 4118 <...>-1689 [000] d... 80948.576731: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1690 1689 /usr/local/bin/stress -t 1 -d 1 1692 4128 <...>-1692 [001] d... 80948.610012: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1694 1692 /usr/local/bin/stress -t 1 -d 1 1693 4135 <...>-1693 [001] d... 80948.617977: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1695 4147 <...>-1695 [001] d... 80948.618880: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1697 1693 /usr/local/bin/stress -t 1 -d 1 1699 1695 /usr/local/bin/stress -t 1 -d 1 1698 4133 <...>-1698 [001] d... 80948.634464: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1703 1698 /usr/local/bin/stress -t 1 -d 1 1702 4118 <...>-1702 [000] d... 80948.637726: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1705 1702 /usr/local/bin/stress -t 1 -d 1 1707 4128 <...>-1707 [000] d... 80948.655756: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1708 1707 /usr/local/bin/stress -t 1 -d 1 1711 4135 sh-1711 [000] d... 80948.695764: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1712 1711 /usr/local/bin/stress -t 1 -d 1 1710 4118 sh-1710 [001] d... 80948.700254: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1715 4128 sh-1715 [000] d... 80948.705255: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1713 4133 sh-1713 [001] d... 80948.705452: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1714 1710 /usr/local/bin/stress -t 1 -d 1 1717 1715 /usr/local/bin/stress -t 1 -d 1 1718 4147 sh-1718 [001] d... 80948.709707: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1720 1713 /usr/local/bin/stress -t 1 -d 1 1722 1718 /usr/local/bin/stress -t 1 -d 1 1725 4135 sh-1725 [000] d... 80948.744807: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1726 1725 /usr/local/bin/stress -t 1 -d 1 1729 4133 sh-1729 [001] d... 80948.765304: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1728 4128 sh-1728 [001] d... 80948.771795: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1732 1729 /usr/local/bin/stress -t 1 -d 1 1731 1728 /usr/local/bin/stress -t 1 -d 1 1730 4147 sh-1730 [000] d... 80948.775144: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1734 1730 /usr/local/bin/stress -t 1 -d 1 1737 4118 sh-1737 [000] d... 80948.781496: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1738 4135 sh-1738 [001] d... 80948.809752: execsnoop_sys_execve: (SyS_execve+0x0/0x30) 1739 1737 /usr/local/bin/stress -t 1 -d 1 1740 1738 /usr/local/bin/stress -t 1 -d 1 1743 4128 sh-1743 [001] d... 80948.818655: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
发现大量的stress进程
execsnoop 所用的 ftrace 是一种常用的动态追踪技术，一般用于分析 Linux 内核的运行时行为。