1. 程式人生 > 其它 >06-案例篇:系統的CPU使用率很高,但為啥卻找不到高CPU的應用?

06-案例篇:系統的CPU使用率很高,但為啥卻找不到高CPU的應用?





引子

上一節講了CPU使用率是什麼,並通過一個案例使用top、vmstat、pidstat等工具
排查高CPU使用率的程序,然後再使用perf top工具定位應用內部函式的問題


似乎感覺高CPU使用率的問題,還是挺容易排查的,那是不是所有CPU使用率高的問題,都可以這麼分析呢?
答案是否定的,系統的CPU使用率,不僅包括程序使用者態和核心態的執行
還包括中斷處理、等待I/O以及核心執行緒等
所以,當發現系統的CPU使用率很高的時候,不一定能找到相對應的高CPU使用率的程序



案例分析

實驗環境
#服務端(192.168.1.6)
配置:2CPU,4G記憶體,centos7.6_64     
預先安裝docker、sysstat、perf、ab 等工具(yum install perf httpd-tools sysstat -y)


#客戶端(192.168.1.5)
配置:1CPU,2G記憶體,centos7.6_64 
預先安裝ab工具(yum install httpd-tools -y)

1.在服務端,第一個終端啟動nginx和php應用

[root@local_sa_192-168-1-6 ~]# docker run --name nginx -p 10000:80 -itd feisky/nginx:sp
[root@local_sa_192-168-1-6 ~]# docker run --name phpfpm -itd --network container:nginx feisky/php-fpm:sp

#檢視docker應用是否啟動
[root@local_sa_192-168-1-6 ~]# docker ps
CONTAINER ID   IMAGE               COMMAND                  CREATED        STATUS        PORTS                                     NAMES
25b4ee281264   feisky/php-fpm:sp   "php-fpm -F --pid /o…"   16 hours ago   Up 16 hours 
....


2.在客戶端,使用curl訪問,出現it works證明環境搭建成功

[root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/
It works!

3.在客戶端,測試一下nginx的效能

# 併發100個請求測試Nginx效能,總共測試1000個請求
[root@local_deploy_192-168-1-5 ~]# ab -c 100 -n 1000 http://192.168.1.6:10000/
......
Requests per second:    147.84 [#/sec] (mean)
Time per request:       676.413 [ms] (mean)
......

# 從ab的輸出結果可以看到Nginx能承受的每秒平均請求數,只有147多一點,感覺它的效能有點差
# 那麼,到底是哪裡出了問題呢?我們再用top和pidstat來觀察一下


4.在客戶端,將測試的併發請求數改成 5,同時把請求時長設定為10分鐘,以便分析

[root@local_deploy_192-168-1-5 ~]# ab -c 5 -t 600 http://192.168.1.6:10000/

5.在服務端,第一個終端執行top命令,觀察cpu的使用情況

[root@local_sa_192-168-1-6 ~]# top
......
%Cpu(s): 75.2 us, 20.6 sy,  0.0 ni,  3.0 id,  0.0 wa,  0.0 hi,  1.2 si,  0.0 st
......

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
16841 101       20   0   33092   2180    756 S   4.0  0.1   0:52.43 nginx
25355 bin       20   0  336684   9540   1880 S   3.0  0.2   0:02.05 php-fpm
25360 bin       20   0  336684   9544   1880 S   3.0  0.2   0:02.02 php-fpm
25367 bin       20   0  336684   9532   1868 R   3.0  0.2   0:01.99 php-fpm
25380 bin       20   0  336684   9536   1868 S   3.0  0.2   0:01.99 php-fpm
25372 bin       20   0  336684   9548   1880 R   2.7  0.2   0:01.97 php-fpm
16792 root      20   0  713312  14736   4036 S   1.3  0.4   0:23.24 containerd-shim
 3143 root      20   0 1311848  77552  30452 S   1.0  2.0   1:23.38 dockerd
 
#觀察top輸出的程序列表可以發現,CPU使用率最高的程序也只不過才4.0%,看起來並不高
#再看系統CPU使用率(%Cpu)這一行,系統的整體CPU使用率是比較高的:使用者CPU使用率us已經到了75%,系統CPU為20%,而空閒CPU(id)則只有3%
#明明使用者CPU使用率都75%了,可是找不到高CPU使用率的程序
#看來top是不管用了,使用pidstat工具可以檢視程序CPU使用情況


6.在服務端,第二個終端執行pidstat命令

# 間隔1秒輸出一組資料(按Ctrl+C結束)
[root@local_sa_192-168-1-6 ~]# pidstat 1
Linux 3.10.0-1160.31.1.el7.x86_64 (local_sa_192-168-1-6) 	2021年11月11日 	_x86_64_	(2 CPU)

10時35分33秒   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
10時35分34秒     0      3143    0.00    0.99    0.00    0.00    0.99     1  dockerd
10時35分34秒     0     16792    0.00    1.98    0.00    0.00    1.98     0  containerd-shim
10時35分34秒   101     16841    0.00    2.97    0.00   17.82    2.97     0  nginx
10時35分34秒     1     25355    0.99    2.97    0.00    7.92    3.96     1  php-fpm
10時35分34秒     1     25360    0.00    2.97    0.00    7.92    2.97     1  php-fpm
10時35分34秒     1     25367    0.99    2.97    0.00   11.88    3.96     0  php-fpm
10時35分34秒     1     25372    0.00    2.97    0.00    6.93    2.97     1  php-fpm
10時35分34秒     1     25380    0.99    1.98    0.00    5.94    2.97     0  php-fpm
10時35分34秒     0     31616    0.00    0.99    0.00    0.00    0.99     1  pidstat

平均時間:   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
平均時間:     0       303    0.00    0.33    0.00    0.00    0.33     -  kworker/1:1H
平均時間:     0      3143    0.33    0.66    0.00    0.00    0.99     -  dockerd
平均時間:     0     16792    0.33    0.99    0.00    0.00    1.32     -  containerd-shim
平均時間:   101     16841    0.66    3.31    0.00   18.21    3.97     -  nginx
平均時間:     0     16893    0.33    0.00    0.00    0.00    0.33     -  containerd-shim
平均時間:     1     25355    0.66    2.32    0.00    8.94    2.98     -  php-fpm
平均時間:     1     25360    0.00    2.65    0.00    7.95    2.65     -  php-fpm
平均時間:     1     25367    0.33    2.32    0.00    9.27    2.65     -  php-fpm
平均時間:     1     25372    0.00    2.65    0.00    7.62    2.65     -  php-fpm
平均時間:     1     25380    0.33    2.32    0.00    7.62    2.65     -  php-fpm
平均時間:     0     31616    0.33    0.99    0.00    0.00    1.32     -  pidstat

#發現,所有程序的CPU使用率也都不高,最高的Nginx也只有5%,即使所有程序的CPU使用率都加起來,離80%還差得遠


#會出現這種情況,很可能是因為前面的分析漏了一些關鍵資訊
#返回去分析top的輸出,看看能不能有新發現

7.在服務端,第一個終端執行top命令

[root@local_sa_192-168-1-6 ~]# top
top - 10:39:26 up 2 days, 18:45,  2 users,  load average: 1.07, 2.36, 1.70
Tasks: 196 total,   6 running, 189 sleeping,   0 stopped,   0 zombie
%Cpu(s): 75.8 us, 20.3 sy,  0.0 ni,  2.9 id,  0.0 wa,  0.0 hi,  1.0 si,  0.0 st
KiB Mem :  3880292 total,   860952 free,   584392 used,  2434948 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  2907388 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
16841 101       20   0   33092   2180    756 S   4.0  0.1   1:02.98 nginx
14974 bin       20   0  336684   9536   1876 S   3.0  0.2   0:00.20 php-fpm
14987 bin       20   0  336684   9536   1872 S   3.0  0.2   0:00.19 php-fpm
14979 bin       20   0  336684   9536   1872 S   2.7  0.2   0:00.19 php-fpm
14996 bin       20   0  336684   9536   1868 S   2.7  0.2   0:00.19 php-fpm
14998 bin       20   0  336684   9536   1868 R   2.7  0.2   0:00.19 php-fpm


#Tasks這一行看起來有點奇怪,就緒佇列中居然有6 Running狀態的程序(6 running)

ab測試的引數,併發請求數是5。
再看程序列表裡,php-fpm的數量也是5,再加上Nginx,好像同時有6個程序也並不奇怪
但真的是這樣嗎?
再仔細看程序列表,這次主要看Running(R)狀態的程序
發現,Nginx和所有的php-fpm都處於Sleep(S)狀態


# 對top命令進行排序,選擇程序狀態排序。
#1. shift + f
#2.然後選擇這一行 S = Process Status 按s鍵設定確認,然後按q鍵退回到主介面
#3.在主介面就會以程序狀態排序,按R倒序
[root@local_sa_192-168-1-6 ~]# top
op - 10:45:29 up 2 days, 18:51,  2 users,  load average: 3.48, 4.38, 2.93
Tasks: 201 total,   6 running, 195 sleeping,   0 stopped,   0 zombie
%Cpu(s): 75.9 us, 19.5 sy,  0.0 ni,  3.5 id,  0.0 wa,  0.0 hi,  1.0 si,  0.0 st
KiB Mem :  3880292 total,   798932 free,   583840 used,  2497520 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  2882684 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 7364 bin       20   0    8172   1120    104 R   0.0  0.0   0:00.00 stress
 7365 bin       20   0    8168    860    104 R   0.0  0.0   0:00.00 stress
 7368 bin       20   0    8172    600    104 R   0.0  0.0   0:00.00 stress
 7371 bin       20   0    8172    860    104 R   0.0  0.0   0:00.00 stress
 7373 bin       20   0    7272    100      0 R   0.0  0.0   0:00.00 stress
 
 
# 可以發現,真正處於Running(R)狀態的,是幾個stress程序。
# 這幾個stress程序就比較奇怪了


# 使用pidstat來分析這幾個程序
[root@local_sa_192-168-1-6 ~]# pidstat -p 7364
Linux 3.10.0-1160.31.1.el7.x86_64 (local_sa_192-168-1-6) 	2021年11月11日 	_x86_64_	(2 CPU)

10時47分55秒   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command

#居然沒有任何輸出。
#難道是pidstat命令出問題了嗎?
#在懷疑效能工具出問題前,最好還是先用其他工具交叉確認一下
#ps應該是最簡單易用的
#在終端裡執行下面的命令,看看7364程序的狀態
[root@local_sa_192-168-1-6 ~]# ps aux|grep 7364
root     12794  0.0  0.0 112724   956 pts/1    R+   10:49   0:00 grep --color=auto 7364

#還是沒有輸出。
#現在終於發現問題,原來這個程序已經不存在了,所以 pidstat 就沒有任何輸出。
#既然程序都沒了,那效能問題應該也跟著沒了吧


8.在服務端,第一個終端再次觀察top命令

[root@local_sa_192-168-1-6 ~]# top
top - 10:50:11 up 2 days, 18:55,  2 users,  load average: 6.54, 5.58, 3.82
Tasks: 196 total,   5 running, 191 sleeping,   0 stopped,   0 zombie
%Cpu(s): 75.8 us, 20.0 sy,  0.0 ni,  3.2 id,  0.0 wa,  0.0 hi,  1.0 si,  0.0 st
KiB Mem :  3880292 total,   763724 free,   582748 used,  2533820 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  2879892 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
    9 root      20   0       0      0      0 R   0.3  0.0   0:14.45 rcu_sched
 9306 bin       20   0    7272    100      0 R   0.0  0.0   0:00.00 stress
 9307 bin       20   0    8168     96      0 R   0.0  0.0   0:00.00 stress
 9310 bin       20   0    7272     96      0 R   0.0  0.0   0:00.00 stress
 
# 使用者CPU使用率還是高達75.8%
# 細看一下top的輸出,發現stress程序的PID一直在改變
# 程序的PID在變,這說明什麼呢?要麼是這些程序在不停地重啟,要麼就是全新的程序
# 1.第一個原因,程序在不停地崩潰重啟,比如因為段錯誤、配置錯誤等等,這時,程序在退出後可能又被監控系統自動重啟了
# 2.第二個原因,這些程序都是短時程序,也就是在其他應用內部通過exec呼叫的外面命令。
# 這些命令一般都只執行很短的時間就會結束,很難用top這種間隔時間比較長的工具發現

要怎麼查詢一個程序的父程序呢?
pstree


9.在服務端,第二個終端使用pstree命令

# 多執行幾次
[root@local_sa_192-168-1-6 ~]# pstree |grep stress
        |-containerd-shim-+-php-fpm-+-3*[php-fpm---sh---stress---stress]
[root@local_sa_192-168-1-6 ~]# pstree |grep stress
        |                 |         `-2*[php-fpm---sh---stress---stress]
[root@local_sa_192-168-1-6 ~]# pstree |grep stress
        |-containerd-shim-+-php-fpm-+-3*[php-fpm---sh---stress---stress]
[root@local_sa_192-168-1-6 ~]# pstree |grep stress
        |-containerd-shim-+-php-fpm-+-2*[php-fpm---sh---stress---stress]

#stress是被php-fpm呼叫的子程序,並且程序數量不止一個(這裡是 3 個)
# 找到父程序後,我們能進入app的內部分析了

10.在服務端,第二個終端

# 拷貝原始碼到本地
[root@local_sa_192-168-1-6 ~]# docker cp phpfpm:/app .

# grep 查詢看看是不是有程式碼在呼叫stress命令
[root@local_sa_192-168-1-6 ~]# 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 的原始碼
[root@local_sa_192-168-1-6 ~]# 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@local_sa_192-168-1-6 ~]# curl http://192.168.1.6:10000?verbose=1
Server internal error: Array
(
    [0] => stress: info: [21931] dispatching hogs: 0 cpu, 0 io, 0 vm, 1 hdd
    [1] => stress: FAIL: [21934] (563) mkstemp failed: Permission denied
    [2] => stress: FAIL: [21931] (394) <-- worker 21934 returned error 1
    [3] => stress: WARN: [21931] (396) now reaping child worker processes
    [4] => stress: FAIL: [21931] (400) kill error: No such process
    [5] => stress: FAIL: [21931] (451) failed run completed in 0s
)

# 看錯誤訊息mkstemp failed: Permission denied
# 以及failed run completed in 0s
# 原來stress命令並沒有成功,它因為許可權問題失敗退出了
# 看來,我們發現了一個PHP呼叫外部stress命令的bug沒有許可權建立臨時檔案
# 從這裡我們可以猜測,正是由於許可權錯誤,大量的stress程序在啟動時初始化失敗,進而導致使用者CPU使用率的升高

# 分析出問題來源,下一步是不是就要開始優化了呢?
# 當然不是!既然只是猜測,那就需要再確認一下,這個猜測到底對不對,是不是真的有大量的stress程序

# 該用什麼工具或指標呢?
# perf


11.在服務端,第三個終端

# perf它可以用來分析CPU效能事件,用在這裡就很合適
# 執行perf record -g命令 ,並等待一會兒(比如 15 秒)後按 Ctrl+C 退出
# 然後再執行perf report檢視報告

### 注意,centos7中由於使用了容器環境,需要把報告拷貝到容器中去分析
# 在宿主機上生成perf.data資料
[root@local_sa_192-168-1-6 ~]# perf recode -g
perf: 'recode' is not a perf-command. See 'perf --help'.
[root@local_sa_192-168-1-6 ~]# perf record -g
^C[ perf record: Woken up 30 times to write data ]
[ perf record: Captured and wrote 8.558 MB perf.data (62670 samples) ]

# 拷貝資料到容器中
[root@local_sa_192-168-1-6 ~]# docker cp perf.data phpfpm:/tmp
[root@local_sa_192-168-1-6 ~]# docker exec -i -t phpfpm bash
root@2e2f18f5ba75:/app# cd /tmp/
root@2e2f18f5ba75:/tmp# apt-get update && apt-get install -y linux-perf linux-tools procps
root@2e2f18f5ba75:/tmp# chown root.root perf.data
root@2e2f18f5ba75:/tmp# perf_4.9 report
stress佔了所有CPU時鐘事件的71%,看來它的確就是CPU使用率升高的元凶了
隨後的優化就很簡單了,只要修復許可權問題,並減少或刪除stress的呼叫,就可以減輕系統的CPU壓力


當然,實際生產環境中的問題一般都要比這個案例複雜
在找到觸發瓶頸的命令列後,卻可能發現,這個外部命令的呼叫過程是應用核心邏輯的一部分,並不能輕易減少或者刪除
這時,就得繼續排查,為什麼被呼叫的命令,會導致CPU使用率升高或I/O升高等問題



execsnoop工具

在這個案例中,使用了top、pidstat、pstree等工具分析了系統CPU使用率高的問題
並發現CPU升高是短時程序stress導致的,但是整個分析過程還是比較複雜的

對於這類問題,有沒有更好的方法監控呢?
execsnoop就是一個專為短時程序設計的工具
它通過ftrace實時監控程序的exec()行為,並輸出短時程序的基本資訊
包括程序PID、父程序 PID、命令列引數以及執行的結果

execsnoop所用的ftrace是一種常用的動態追蹤技術,一般用於分析Linux核心的執行時行為


execsnoop安裝(其實就是一個shell指令碼)
下載連結:https://alnk-blog-pictures.oss-cn-shenzhen.aliyuncs.com/blog-pictures/execsnoop
指令碼直接放到 /usr/bin/ 目錄下即可


# 按Ctrl+C結束
[root@local_sa_192-168-1-6 ~]# execsnoop
Tracing exec()s. Ctrl-C to end.
Instrumenting sys_execve
   PID   PPID ARGS
 13665  13642 gawk -v o=1 -v opt_name=0 -v name= -v opt_duration=0 [...]
 13666  13663 cat -v trace_pipe
 13667   5460               sh-13667 [000] d... 242729.963605: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 13668  13667 /usr/local/bin/stress -t 1 -d 1
 13670   5464               sh-13670 [000] d... 242729.966825: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 13671   5472               sh-13671 [000] d... 242729.967127: execsnoop_sys_execve: (SyS_execve+0x0/0x30)
 13672  13671 /usr/local/bin/stress -t 1 -d 1
 13673  13670 /usr/local/bin/stress -t 1 -d 1
......
發現大量stress程序




小結

碰到常規問題無法解釋的CPU使用率情況時,首先要想到有可能是短時應用導致的問題,比如有可能是下面這兩種情況
1.應用裡直接呼叫了其他二進位制程式,這些程式通常執行時間比較短,通過top等工具也不容易發現
2.應用本身在不停地崩潰重啟,而啟動過程的資源初始化,很可能會佔用相當多的CPU

對於這類程序,我們可以用pstree或者execsnoop找到它們的父程序,再從父程序所在的應用入手,排查問題的根源

轉載請註明出處喲~ https://www.cnblogs.com/lichengguo