上一節我講了 CPU 使用率是什麼，並通過一個案例教你使用 top、vmstat、pidstat 等工具，排查高 CPU 使用率的程序，然後再使用 perf top 工具，定位應用內部函式的問題。不過就有人留言了，說似乎感覺高 CPU 使用率的問題，還是挺容易排查的。

那是不是所有 CPU 使用率高的問題，都可以這麼分析呢？我想，你的答案應該是否定的。

回顧前面的內容，我們知道，系統的 CPU 使用率，不僅包括程序使用者態和核心態的執行，還包括中斷處理、等待 I/O 以及核心執行緒等。所以，當你發現系統的 CPU 使用率很高的時候，不一定能找到相對應的高 CPU 使用率的程序。

今天，我就用一個 Nginx + PHP 的 Web 服務的案例，帶你來分析這種情況。

案例分析

你的準備

今天依舊探究系統CPU使用率高的情況，所以這次實驗的準備工作，與上節課的準備工作基本相同，差別在於案例所用的 Docker 映象不同。

本次案例還是基於 Ubuntu 18.04，同樣適用於其他的 Linux 系統。我使用的案例環境如下所示：

• 機器配置：2 CPU，8GB 記憶體

• 預先安裝 docker、sysstat、perf、ab 等工具，如 apt install docker.io sysstat linux-tools-common apache2-utils

前面我們講到過，ab（apache bench）是一個常用的 HTTP 服務效能測試工具，這裡同樣用來模擬 Nginx 的客戶端。由於 Nginx 和 PHP 的配置比較麻煩，我把它們打包成了兩個

注意，這個案例要用到兩臺虛擬機器，如下圖所示：

你可以看到，其中一臺用作 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個請求
$ ab -c 100 -n 1000 http://192.168.0.10: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)
...

從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
...
%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
...

觀察 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
<?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) <-- 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：沒有許可權建立臨時檔案。

從這裡我們可以猜測，正是由於許可權錯誤，大量的 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 核心的執行時行為，後面課程我也會詳細介紹並帶你使用。