案例分析
你的準備
今天依舊探究系統CPU使⽤率⾼的情況，所以這次實驗的準備⼯作，與上節課的準備⼯作基本相同，差別在於案例所⽤的Docker 鏡像不同。
本次還是基於 Ubuntu 18.04，同樣適⽤於其他的 Linux 系統。我使⽤的案例環境如下所示：
機器配置：2 CPU，8GB 內存
預先安裝 docker、sysstat、perf、ab 等⼯具，如 apt install docker.io sysstat linux-tools-common 。由於Nginx 和 PHP 的配置比較麻煩，我把它們打包成了兩個 Docker 鏡像，這樣只需要運⾏兩個容器，就可以得到模擬環境。注意，這個案例要⽤到兩臺虛擬機，如下圖所示：
你可以看到，其中⼀臺⽤作 Web 服務器，來模擬性能問題；另⼀臺⽤作 Web 服務器的客戶端，來給 Web 服務增加壓⼒請求。使用兩臺虛擬機是為了相互隔離，避免“交叉感染”。
接下來，我們打開兩個終端，分別 SSH 登錄到兩臺機器上，並安裝上述⼯具。
同樣注意，下⾯所有命令都默認以 root ⽤戶運⾏，如果你是⽤普通⽤戶身份登陸系統，請運⾏ sudo su root 命令切換到 root ⽤戶。
⾛到這⼀步，準備⼯作就完成了。接下來，我們正式進入操作環節。
溫馨提示：案例中 PHP 應⽤的核⼼邏輯⽐較簡單，你可能一眼就能看出問題，但實際生產環境中的源碼就複雜多了。所以，我依舊建議，操作之前別看源碼，避免先⼊為主，⽽要把它當成⼀個⿊盒來分析。這樣，你可以更好把握，怎麼從系統的資源使⽤問題出發，分析出瓶頸所在的應⽤，以及瓶頸在應⽤中⼤概的位置。
操作和分析
⾸先，我們在第⼀個終端，執⾏下⾯的命令運⾏ Nginx 和 PHP 應⽤：
$ 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://[VM1的IP]:10000，確認 Nginx 已正常啟動。你應該可以看到 It works! 的響應。
# 192.168.0.10是第⼀臺虛擬機的IP地址
$ curl http://192.168.0.10:10000/
It works!
接著，我們來測試一下這個 Nginx 服務的性能。在第⼆個終端運⾏下⾯的 ab 命令。要注意，與上次操作不同的是，這次我們
需要併發100個請求測試Nginx性能，總共測試1000個請求。# 併發100個請求測試Nginx性能，總共測試1000個請求
<code>$ ab -c 100 -n 1000 http://192.168.0.10:10000/
This is ApacheBench, Version 2.3
Copyright 1996 Adam Twiss, Zeus Technology Ltd,
Requests per second: 87.86 [#/sec] (mean)
Time per request: 1138.229 [ms] (mean)/<code>
...
從ab的輸出結果我們可以看到，Nginx能承受的每秒平均請求數，只有 87 多⼀點，是不是感覺它的性能有點差呀。那麼，到底是哪⾥出了問題呢？我們再⽤ top 和 pidstat 來觀察⼀下。
這次，我們在第⼆個終端，將測試的併發請求數改成5，同時把請求時⻓設置為10分鐘（-t 600）。這樣，當你在第⼀個終端
使⽤性能分析⼯具時， Nginx 的壓⼒還是繼續的。
繼續在第⼆個終端運⾏ ab 命令：
$ ab -c 5 -t 600 http://192.168.0.10:10000/
然後，我們在第⼀個終端運⾏ top 命令，觀察系統的 CPU 使⽤情況：
$ top
...
<code>%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/<code>
<code>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/<code>
...
觀察 top 輸出的進程列表可以發現，CPU 使⽤率最⾼的進程也只不過才 2.7%，看起來並不⾼。
然⽽，再看系統 CPU 使⽤率（ %Cpu ）這⼀⾏，你會發現，系統的整體 CPU 使⽤率是⽐較⾼的：⽤戶 CPU 使⽤率（us）
已經到了 80%，系統 CPU 為 15.1%，⽽空閒 CPU （id）則只有 2.8%。
為什麼⽤戶 CPU 使⽤率這麼⾼呢？我們再重新分析⼀下進程列表，看看有沒有可疑進程：docker-containerd 進程是⽤來運⾏容器的，2.7% 的 CPU 使⽤率看起來正常；
Nginx 和 php-fpm 是運⾏ Web 服務的，它們會佔⽤⼀些 CPU 也不意外，並且 2% 的 CPU 使⽤率也不算⾼；
再往下看，後⾯的進程呢，只有 0.3% 的 CPU 使⽤率，看起來不太像會導致⽤戶 CPU 使⽤率達到 80%。
那就奇怪了，明明⽤戶 CPU 使⽤率都80%了，可我們挨個分析了⼀遍進程列表，還是找不到⾼ CPU 使⽤率的進程。看來top
是不管⽤了，那還有其他⼯具可以查看進程 CPU 使⽤情況嗎？不知道你記不記得我們的⽼朋友 pidstat，它可以⽤來分析進程
的 CPU 使⽤情況。
接下來，我們還是在第⼀個終端，運⾏ 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% 還差得遠呢！
最早的時候，我碰到這種問題就完全懵了：明明⽤戶 CPU 使⽤率已經⾼達 80%，但我卻怎麼都找不到是哪個進程的問題。到
這⾥，你也可以想想，你是不是也遇到過這種情況？還能不能再做進⼀步的分析呢？
後來我發現，會出現這種情況，很可能是因為前⾯的分析漏了⼀些關鍵信息。你可以先暫停⼀下，⾃⼰往上翻，重新操作檢查
⼀遍。或者，我們⼀起返回去分析 top 的輸出，看看能不能有新發現。
現在，我們回到第⼀個終端，重新運⾏ 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
...
這次從頭開始看 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 使⽤情況：
$ pidstat -p 24344
16:14:55 UID PID %usr %system %guest %wait %CPU CPU Command
奇怪，居然沒有任何輸出。難道是pidstat 命令出問題了嗎？之前我說過，在懷疑性能⼯具出問題前，最好還是先⽤其他⼯具
交叉確認⼀下。那⽤什麼⼯具呢？ ps 應該是最簡單易⽤的。我們在終端⾥運⾏下⾯的命令，看看 24344 進程的狀態：# 從所有進程中查找PID是24344的進程
$ ps aux | grep 24344
root 9628 0.0 0.0 14856 1096 pts/0 S+ 16:15 0:00 grep --color=auto 24344
還是沒有輸出。現在終於發現問題，原來這個進程已經不存在了，所以 pidstat 就沒有任何輸出。既然進程都沒了，那性能問
題應該也跟著沒了吧。我們再⽤ 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 進程不存在了，怎麼現在還在運⾏呢？再細看⼀下 top 的輸出，原來，這次 stress 進程的 PID 跟
前⾯不⼀樣了，原來的 PID 24344 不⻅了，現在的是 6779。
進程的 PID 在變，這說明什麼呢？在我看來，要麼是這些進程在不停地重啟，要麼就是全新的進程，這⽆⾮也就兩個原因：
第⼀個原因，進程在不停地崩潰重啟，⽐如因為段錯誤、配置錯誤等等，這時，進程在退出後可能⼜被監控系統⾃動重啟了。
第⼆個原因，這些進程都是短時進程，也就是在其他應⽤內部通過 exec 調⽤的外⾯命令。這些命令⼀般都只運⾏很短的時
間就會結束，你很難⽤ top 這種間隔時間⽐較⻓的⼯具發現（上⾯的案例，我們碰巧發現了）。
⾄於 stress，我們前⾯提到過，它是⼀個常⽤的壓⼒測試⼯具。它的 PID 在不斷變化中，看起來像是被其他進程調⽤的短時
進程。要想繼續分析下去，還得找到它們的⽗進程。
要怎麼查找⼀個進程的⽗進程呢？沒錯，⽤ pstree 就可以⽤樹狀形式顯示所有進程之間的關係：
$ pstree | grep stress
|-docker-containe-+-php-fpm-+-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 命令。
再來看看 app/index.php 的源代碼：
$ cat app/index.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 的輸出。你先試試看，在第⼆個終端運⾏：$ curl http://192.168.0.10: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)
[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：沒有權限創建臨時⽂件。
從這⾥我們可以猜測，正是由於權限錯誤，⼤量的 stress 進程在啟動時初始化失敗，進⽽導致⽤戶 CPU 使⽤率的升⾼。
分析出問題來源，下⼀步是不是就要開始優化了呢？當然不是！既然只是猜測，那就需要再確認⼀下，這個猜測到底對不對，是不是真的有⼤量的 stress 進程。該⽤什麼⼯具或指標呢？
我們前⾯已經⽤了 top、pidstat、pstree 等⼯具，沒有發現⼤量的 stress 進程。那麼，還有什麼其他的⼯具可以⽤嗎？
還記得上⼀期提到的 perf 嗎？它可以⽤來分析 CPU 性能事件，⽤在這⾥就很合適。依舊在第⼀個終端中運⾏ perf record -g
命令 ，並等待⼀會⼉（⽐如15秒）後按 Ctrl+C 退出。然後再運⾏ perf report 查看報告：
# 記錄性能事件，等待⼤約15秒後按 Ctrl+C 退出
$ perf record -g
# 查看報告
$ perf report
這樣，你就可以看到下圖這個性能報告：你看，stress 佔了所有CPU時鐘事件的 77%，⽽ stress 調⽤調⽤棧中⽐例最⾼的，是隨機數⽣成函數 random()，看來它的確
就是 CPU 使⽤率升⾼的元兇了。隨後的優化就很簡單了，只要修復權限問題，並減少或刪除 stress 的調⽤，就可以減輕系統的 CPU 壓⼒。
當然，實際⽣產環境中的問題⼀般都要⽐這個案例複雜，在你找到觸發瓶頸的命令⾏後，卻可能發現，這個外部命令的調⽤過程是應⽤核⼼邏輯的⼀部分，並不能輕易減少或者刪除。
這時，你就得繼續排查，為什麼被調⽤的命令，會導致 CPU 使⽤率升⾼或 I/O 升⾼等問題。這些複雜場景的案例，我會在後⾯的綜合實戰⾥詳細分析。
最後，在案例結束時，不要忘了清理環境，執⾏下⾯的 Docker 命令，停⽌案例中⽤到的 Nginx 進程：
$ docker rm -f nginx phpfpm
execsnoop
在這個案例中，我們使⽤了 top、pidstat、pstree 等⼯具分析了系統 CPU 使⽤率⾼的問題，並發現 CPU 升⾼是短時進程
stress 導致的，但是整個分析過程還是⽐較複雜的。對於這類問題，有沒有更好的⽅法監控呢？
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 內核的運⾏時⾏為，後⾯課程我也會詳細介紹並
帶你使⽤。
⼩結
碰到常規問題⽆法解釋的 CPU 使⽤率情況時，⾸先要想到有可能是短時應⽤導致的問題，⽐如有可能是下⾯這兩種情況。
第⼀，應⽤⾥直接調⽤了其他⼆進製程序，這些程序通常運⾏時間⽐較短，通過 top 等⼯具也不容易發現。
第⼆，應⽤本身在不停地崩潰重啟，⽽啟動過程的資源初始化，很可能會佔⽤相當多的 CPU。
對於這類進程，我們可以⽤ pstree 或者 execsnoop 找到它們的⽗進程，再從⽗進程所在的應⽤⼊⼿，排查問題的根源
閱讀更多 青峰科技 的文章
