短時應用程序重啟導致CPU使用率升高，排查方法
阿新 • • 發佈：2020-08-23
環境準備
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 這一行看起來有點奇怪，就緒佇列中居然有 4 個 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 核心的執行時行為。