06-案例篇:系統的CPU使用率很高,但為啥卻找不到高CPU的應用?
阿新 • • 發佈:2021-11-11
引子
上一節講了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