上一篇, Linux 進程狀態的含義,以及不可中斷進程和僵屍進程產生的原因。 使用 ps 或者 top 可以查看進程的狀態,這些狀態包括運行、空閑、不可中斷睡眠、可中斷睡 眠、僵屍以及暫停等。 其中,重點是不可中斷狀態和僵屍進程: 不可中斷狀態,一般表示進程正在跟硬體交互,為了保護進程數據與硬體一致 ...
上一篇, Linux 進程狀態的含義,以及不可中斷進程和僵屍進程產生的原因。 使用 ps 或者 top 可以查看進程的狀態,這些狀態包括運行、空閑、不可中斷睡眠、可中斷睡 眠、僵屍以及暫停等。
其中,重點是不可中斷狀態和僵屍進程:
- 不可中斷狀態,一般表示進程正在跟硬體交互,為了保護進程數據與硬體一致,系統不允許 其他進程或中斷打斷該進程。
- 僵屍進程表示進程已經退出,但它的父進程沒有回收該進程所占用的資源。
上一篇的最後,用一個案例展示了處於這兩種狀態的進程。通過分析 top 命令的輸出,發現了兩個問題:
- 第一,iowait 太高了,導致系統平均負載升高,並且已經達到了系統 CPU 的個數。
- 第二,僵屍進程在不斷增多,看起來是應用程式沒有正確清理子進程的資源。
思考這兩個問題,那麼,真相到底是什麼呢?順著這兩個問 題繼續分析,找出根源。
首先,請你打開一個終端,登錄到上次的機器中。然後執行下麵的命令,重新運行這個案例:
# 先刪除上次啟動的案例 $ docker rm -f app # 重新運行案例 $ docker run --privileged --name=app -itd feisky/app:iowait
iowait 分析
先來看一下 iowait 升高的問題。
一提到 iowait 升高,你首先會想要查詢系統的 I/O 情況。我一般也是這種思路,那麼什麼工具可以查詢系統的 I/O 情況呢?
這裡,推薦的正是上節課要求安裝的 dstat ,它的好處是,可以同時查看 CPU 和 I/O 這兩種 資源的使用情況,便於對比分析。
那麼,我們在終端中運行 dstat 命令,觀察 CPU 和 I/O 的使用情況:
# 間隔 1 秒輸出 10 組數據 $ dstat 1 10 You did not select any stats, using -cdngy by default. --total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai stl| read writ| recv send| in out | int csw 0 0 96 4 0|1219k 408k| 0 0 | 0 0 | 42 885 0 0 2 98 0| 34M 0 | 198B 790B| 0 0 | 42 138 0 0 0 100 0| 34M 0 | 66B 342B| 0 0 | 42 135 0 0 84 16 0|5633k 0 | 66B 342B| 0 0 | 52 177 0 3 39 58 0| 22M 0 | 66B 342B| 0 0 | 43 144 0 0 0 100 0| 34M 0 | 200B 450B| 0 0 | 46 147 0 0 2 98 0| 34M 0 | 66B 342B| 0 0 | 45 134 0 0 0 100 0| 34M 0 | 66B 342B| 0 0 | 39 131 0 0 83 17 0|5633k 0 | 66B 342B| 0 0 | 46 168 0 3 39 59 0| 22M 0 | 66B 342B| 0 0 | 37 134
從 dstat 的輸出,我們可以看到,每當 iowait 升高(wai)時,磁碟的讀請求(read)都會很 大。
這說明 iowait 的升高跟磁碟的讀請求有關,很可能就是磁碟讀導致的。
那到底是哪個進程在讀磁碟呢?不知道你還記不記得,上節在 top 里看到的不可中斷狀態進 程,我覺得它就很可疑,我們試著來分析下。
我們繼續在剛纔的終端中,運行 top 命令,觀察 D 狀態的進程:
# 觀察一會兒按 Ctrl+C 結束 $ top ... PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 4340 root 20 0 44676 4048 3432 R 0.3 0.0 0:00.05 top 4345 root 20 0 37280 33624 860 D 0.3 0.0 0:00.01 app 4344 root 20 0 37280 33624 860 D 0.3 0.4 0:00.01 app ...
我們從 top 的輸出找到 D 狀態進程的 PID,你可以發現,這個界面里有兩個 D 狀態的進程, PID 分別是 4344 和 4345。
接著,我們查看這些進程的磁碟讀寫情況。對了,別忘了工具是什麼。一般要查看某一個進程的 資源使用情況,都可以用我們的老朋友 pidstat,不過這次記得加上 -d 參數,以便輸出 I/O 使 用情況。
比如,以 4344 為例,我們在終端里運行下麵的 pidstat 命令,並用 -p 4344 參數指定進程 號:
# -d 展示 I/O 統計數據,-p 指定進程號,間隔 1 秒輸出 3 組數據 $ pidstat -d -p 4344 1 3 06:38:50 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:38:51 0 4344 0.00 0.00 0.00 0 app 06:38:52 0 4344 0.00 0.00 0.00 0 app 06:38:53 0 4344 0.00 0.00 0.00 0 app
在這個輸出中, kB_rd 表示每秒讀的 KB 數, kB_wr 表示每秒寫的 KB 數,iodelay 表示 I/O 的延遲(單位是時鐘周期)。它們都是 0,那就表示此時沒有任何的讀寫,說明問題不是 4344 進程導致的。
可是,用同樣的方法分析進程 4345,你會發現,它也沒有任何磁碟讀寫。
那要怎麼知道,到底是哪個進程在進行磁碟讀寫呢?我們繼續使用 pidstat,但這次去掉進程 號,乾脆就來觀察所有進程的 I/O 使用情況。
在終端中運行下麵的 pidstat 命令:
# 間隔 1 秒輸出多組數據 (這裡是 20 組) $ pidstat -d 1 20 ... 06:48:46 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:48:47 0 4615 0.00 0.00 0.00 1 kworker/u4:1 06:48:47 0 6080 32768.00 0.00 0.00 170 app 06:48:47 0 6081 32768.00 0.00 0.00 184 app 06:48:47 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:48:48 0 6080 0.00 0.00 0.00 110 app 06:48:48 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:48:49 0 6081 0.00 0.00 0.00 191 app 06:48:49 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:48:50 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:48:51 0 6082 32768.00 0.00 0.00 0 app 06:48:51 0 6083 32768.00 0.00 0.00 0 app 06:48:51 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:48:52 0 6082 32768.00 0.00 0.00 184 app 06:48:52 0 6083 32768.00 0.00 0.00 175 app 06:48:52 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 06:48:53 0 6083 0.00 0.00 0.00 105 app ...
觀察一會兒可以發現,的確是 app 進程在進行磁碟讀,並且每秒讀的數據有 32 MB,看來就是 app 的問題。不過,app 進程到底在執行啥 I/O 操作呢?
這裡,我們需要回顧一下進程用戶態和內核態的區別。進程想要訪問磁碟,就必須使用系統調 用,所以接下來,重點就是找出 app 進程的系統調用了。
strace 正是最常用的跟蹤進程系統調用的工具。所以,我們從 pidstat 的輸出中拿到進程的 PID 號,比如 6082,然後在終端中運行 strace 命令,並用 -p 參數指定 PID 號:
$ strace -p 6082 strace: attach: ptrace(PTRACE_SEIZE, 6082): Operation not permitted
這兒出現了一個奇怪的錯誤,strace 命令居然失敗了,並且命令報出的錯誤是沒有許可權。按理 來說,我們所有操作都已經是以 root 用戶運行了,為什麼還會沒有許可權呢?你也可以先想一 下,碰到這種情況,你會怎麼處理呢?
一般遇到這種問題時,我會先檢查一下進程的狀態是否正常。比如,繼續在終端中運行 ps 命 令,並使用 grep 找出剛纔的 6082 號進程:
$ ps aux | grep 6082 root 6082 0.0 0.0 0 0 pts/0 Z+ 13:43 0:00 [app] <defunct>
果然,進程 6082 已經變成了 Z 狀態,也就是僵屍進程。僵屍進程都是已經退出的進程,所以 就沒法兒繼續分析它的系統調用。關於僵屍進程的處理方法,我們一會兒再說,現在還是繼續分 析 iowait 的問題。
到這一步,你應該註意到了,系統 iowait 的問題還在繼續,但是 top、pidstat 這類工具已經不 能給出更多的信息了。這時,我們就應該求助那些基於事件記錄的動態追蹤工具了。
你可以用 perf top 看看有沒有新發現。再或者,可以像我一樣,在終端中運行 perf record, 持續一會兒(例如 15 秒),然後按 Ctrl+C 退出,再運行 perf report 查看報告:
$ perf record -g
$ perf report
接著,找到我們關註的 app 進程,按回車鍵展開調用棧,你就會得到下麵這張調用關係圖:
這個圖裡的 swapper 是內核中的調度進程,你可以先忽略掉。
我們來看其他信息,你可以發現, app 的確在通過系統調用 sys_read() 讀取數據。並且從 new_sync_read 和 blkdev_direct_IO 能看出,進程正在對磁碟進行直接讀,也就是繞過了系統 緩存,每個讀請求都會從磁碟直接讀,這就可以解釋我們觀察到的 iowait 升高了。
看來,罪魁禍首是 app 內部進行了磁碟的直接 I/O 啊!
下麵的問題就容易解決了。我們接下來應該從代碼層面分析,究竟是哪裡出現了直接讀請求。查 看源碼文件 app.c,你會發現它果然使用了 O_DIRECT 選項打開磁碟,於是繞過了系統緩存, 直接對磁碟進行讀寫。
open(disk, O_RDONLY|O_DIRECT|O_LARGEFILE, 0755)
直接讀寫磁碟,對 I/O 敏感型應用(比如資料庫系統)是很友好的,因為你可以在應用中,直 接控制磁碟的讀寫。但在大部分情況下,我們最好還是通過系統緩存來優化磁碟 I/O,換句話 說,刪除 O_DIRECT 這個選項就是了。
app-fix1.c 就是修改後的文件,我也打包成了一個鏡像文件,運行下麵的命令,你就可以啟動它了:
# 首先刪除原來的應用 $ docker rm -f app # 運行新的應用 $ docker run --privileged --name=app -itd feisky/app:iowait-fix1
最後,再用 top 檢查一下:
$ top top - 14:59:32 up 19 min, 1 user, load average: 0.15, 0.07, 0.05 Tasks: 137 total, 1 running, 72 sleeping, 0 stopped, 12 zombie %Cpu0 : 0.0 us, 1.7 sy, 0.0 ni, 98.0 id, 0.3 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu1 : 0.0 us, 1.3 sy, 0.0 ni, 98.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st ... PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3084 root 20 0 0 0 0 Z 1.3 0.0 0:00.04 app 3085 root 20 0 0 0 0 Z 1.3 0.0 0:00.04 app 1 root 20 0 159848 9120 6724 S 0.0 0.1 0:09.03 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 3 root 20 0 0 0 0 I 0.0 0.0 0:00.40 kworker/0:0 ...
你會發現, iowait 已經非常低了,只有 0.3%,說明剛纔的改動已經成功修複了 iowait 高的問 題,大功告成!不過,別忘了,僵屍進程還在等著你。仔細觀察僵屍進程的數量,你會鬱悶地發 現,僵屍進程還在不斷的增長中。
僵屍進程
接下來,我們就來處理僵屍進程的問題。既然僵屍進程是因為父進程沒有回收子進程的資源而出 現的,那麼,要解決掉它們,就要找到它們的根兒,也就是找出父進程,然後在父進程里解決。
父進程的找法我們前面講過,最簡單的就是運行 pstree 命令:
# -a 表示輸出命令行選項 # p 表 PID # s 表示指定進程的父進程 $ pstree -aps 3084 systemd,1 └─dockerd,15006 -H fd:// └─docker-containe,15024 --config /var/run/docker/containerd/containerd.toml └─docker-containe,3991 -namespace moby -workdir... └─app,4009 └─(app,3084)
運行完,你會發現 3084 號進程的父進程是 4009,也就是 app 應用。
所以,我們接著查看 app 應用程式的代碼,看看子進程結束的處理是否正確,比如有沒有調用 wait() 或 waitpid() ,抑或是,有沒有註冊 SIGCHLD 信號的處理函數。
現在我們查看修複 iowait 後的源碼文件 app-fix1.c ,找到子進程的創建和清理的地方:
int status = 0; for (;;) { for (int i = 0; i < 2; i++) { if(fork()== 0) { sub_process(); } } sleep(5); }
while(wait(&status)>0);
迴圈語句本來就容易出錯,你能找到這裡的問題嗎?這段代碼雖然看起來調用了 wait() 函數等 待子進程結束,但卻錯誤地把 wait() 放到了 for 死迴圈的外面,也就是說,wait() 函數實際上 並沒被調用到,我們把它挪到 for 迴圈的裡面就可以了。
修改後的文件我放到了 app-fix2.c 中,也打包成了一個 Docker 鏡像,運行下麵的命令,你就 可以啟動它:
# 先停止產生僵屍進程的 app $ docker rm -f app # 然後啟動新的 app $ docker run --privileged --name=app -itd feisky/app:iowait-fix2
啟動後,再用 top 最後來檢查一遍:
$ top top - 15:00:44 up 20 min, 1 user, load average: 0.05, 0.05, 0.04 Tasks: 125 total, 1 running, 72 sleeping, 0 stopped, 0 zombie %Cpu0 : 0.0 us, 1.7 sy, 0.0 ni, 98.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu1 : 0.0 us, 1.3 sy, 0.0 ni, 98.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st ... PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3198 root 20 0 4376 840 780 S 0.3 0.0 0:00.01 app 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 3 root 20 0 0 0 0 I 0.0 0.0 0:00.41 kworker/0:0 ...
好了,僵屍進程(Z 狀態)沒有了, iowait 也是 0,問題終於全部解決了。
小結
今天我用一個多進程的案例,帶你分析系統等待 I/O 的 CPU 使用率(也就是 iowait%)升高的 情況。
雖然這個案例是磁碟 I/O 導致了 iowait 升高,不過, iowait 高不一定代表 I/O 有性能瓶頸。 當系統中只有 I/O 類型的進程在運行時,iowait 也會很高,但實際上,磁碟的讀寫遠沒有達到 性能瓶頸的程度。
因此,碰到 iowait 升高時,需要先用 dstat、pidstat 等工具,確認是不是磁碟 I/O 的問題,然 後再找是哪些進程導致了 I/O。
等待 I/O 的進程一般是不可中斷狀態,所以用 ps 命令找到的 D 狀態(即不可中斷狀態)的進 程,多為可疑進程。但這個案例中,在 I/O 操作後,進程又變成了僵屍進程,所以不能用 strace 直接分析這個進程的系統調用。 這
種情況下,我們用了 perf 工具,來分析系統的 CPU 時鐘事件,最終發現是直接 I/O 導致的 問題。這時,再檢查源碼中對應位置的問題,就很輕鬆了。
而僵屍進程的問題相對容易排查,使用 pstree 找出父進程後,去查看父進程的代碼,檢查 wait() / waitpid() 的調用,或是 SIGCHLD 信號處理函數的註冊就行了。