初探Linux核心態——透過proc檔案系統作快速問題定位

本文是對一篇blog的翻譯，感謝譯者Hualet Wang。原文透過一個例子為我們展示了，在分析行程執行緩慢的問題時，strace和pstack都束手無策的情況下，不要忘了還有proc。

簡介

文章翻譯自 Peeking into Linux kernel-land using /proc filesystem for quick’n’dirty troubleshooting

這篇部落格的內容完全是關於現代Linux內核的。換句話說，指的是與RHEL6一樣使用的2.6.3x系列核心，而不是古老的RHEL5所使用的2.6.18核心，雖然大部分企業都還在使用RHEL5。另外，這篇文章也不會涉及核心除錯器或者SystemTap指令碼之類的東西，完全是最最簡單地在有用的proc檔案系統節點上執行“cat /proc/PID/xyz”這樣的命令。

定位一個程式“執行緩慢”的問題

下麵要舉的這個例子是這樣的：一個DBA反映說他們的find命令一直執行緩慢，半天都沒有什麼輸出，他們想知道這是為什麼。聽到這個問題的時候我就大概有直覺造成這個問題的原因，但是他們還是想知道怎麼系統地追蹤這類問題，並找到解決方案。剛好出問題的現場還在……

還好，系統是執行在OEL6上的，核心比較新，確切地說是2.6.39 UEK2。

首先，讓我們看看find行程是否還在：

[root@oel6 ~]# ps -ef | grep find
root     27288 27245  4 11:57 pts/0    00:00:01 find . -type f
root     27334 27315  0 11:57 pts/1    00:00:00 grep find

跑的好好的，PID是27288（請記好這個將會伴隨整篇部落格的數字）。

那麼，我們就從最基礎的開始分析它的瓶頸：如果它不是被什麼操作卡住了（例如從cache中載入它所需要的內容），它應該是100%的CPU佔用率；如果它的瓶頸在IO或者資源競爭，那麼它應該是很低的CPU佔用率，或者是%0。

我們先看下top：

[root@oel6 ~]# top -cbp 27288
top - 11:58:15 up 7 days,  3:38,  2 users,  load average: 1.21, 0.65, 0.47
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us,  0.1%sy,  0.0%ni, 99.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   2026460k total,  1935780k used,    90680k free,    64416k buffers
Swap:  4128764k total,   251004k used,  3877760k free,   662280k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
27288 root      20   0  109m 1160  844 D  0.0  0.1   0:01.11 find . -type f

結果很清楚：這個行程的CPU佔用率很低，幾乎為零。但是CPU佔用低也分情況：一種是行程完全卡住了，根本沒有機會獲得時間片；另一種是行程在不停進入等待的狀態（例如poll動作就是時不時超時後，行程進入休眠狀態）。雖然這剩下的細節top還不足以完全給我們展示，但是至少我們知道了這個行程沒有在燒CPU時間。

通常情況下，如果行程處於這種狀態（%0的CPU佔用一般說明行程是卡在了某個系統呼叫，因為這個系統呼叫阻塞了，核心需要把行程放到休眠狀態），我都會用strace跟蹤一下這個行程具體卡在了哪個系統呼叫。而且，如果行程不是完全卡住了，那行程中的系統呼叫情況也會在strace的輸出中有所展示（因為一般阻塞的系統呼叫會在超時傳回後，過一段時間再進入阻塞等待的狀態）。

讓我們試試strace：

[root@oel6 ~]# strace -cp 27288
Process 27288 attached - interrupt to quit

^C
^Z
[1]+  Stopped                 strace -cp 27288

[root@oel6 ~]# kill -9 %%
[1]+  Stopped                 strace -cp 27288
[root@oel6 ~]# 
[1]+  Killed                  strace -cp 27288

尷尬，strace自己也卡住了！半天沒有輸出，也不響應Ctrl-C，我不得不透過Ctrl-Z把它扔到後臺再殺掉它。想簡單處理還真是不容易啊。

那隻好再試試pstack了（Linux上的pstack只是用shell指令碼包了一下GDB）。儘管pstack看不到核心態的內容，但是至少它能告訴我們是哪個系統呼叫最後執行的（通常pstack輸出的使用者態呼叫棧最頂部是一個libc庫的系統呼叫）：

[root@oel6 ~]# pstack 27288

^C
^Z
[1]+  Stopped                 pstack 27288

[root@oel6 ~]# kill %%
[1]+  Stopped                 pstack 27288
[root@oel6 ~]# 
[1]+  Terminated              pstack 27288

呵呵，pstack也卡住了，什麼輸出都沒有！

至此，我們還是不知道我們的程式是怎麼卡住了，卡在哪裡了。

好吧，還怎麼進行下去呢？還有一些常用的資訊可以蒐集——行程的status欄位和WCHAN欄位，這些使用古老的ps就能檢視（或許最開始就應該用ps看看這個行程是不是已經成僵屍行程了）：

[root@oel6 ~]# ps -flp 27288
F S UID        PID  PPID  C PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD
0 D root     27288 27245  0  80   0 - 28070 rpc_wa 11:57 pts/0    00:00:01 find . -type f

需要註意的是，你要多執行幾次ps以確保行程還在同一個狀態（不然在不湊巧的時候獲取了一個錯誤的狀態就麻煩了），我這裡為了簡短就只貼一次輸出了。

行程此時正處於D狀態，按照man手冊的說法，這通常是因為磁碟IO導致的。而WCHAN欄位（表示導致程式處於休眠/等待狀態的函式呼叫）則有點兒被切掉了。顯然我可以翻一下ps的man手冊，看看怎麼把這個欄位調寬一點好完整打印出來，不過既然我都知道了這個資訊來自於proc檔案系統，就沒這個必要了。

直接從它的源頭讀一下看看（再次說明一下，多試幾次看看，畢竟我們還不知道這個行程到底是不是完全卡死了呢）：

[root@oel6 ~]# cat /proc/27288/wchan
rpc_wait_bit_killable

額……這個行程居然在等待某些RPC呼叫。RPC呼叫通常意味著這個程式在跟其他行程通訊（不管是本地還是遠端）。總歸，我們還是不知道為什麼會卡住。

到底是不是完全卡住了？

在我們揭開這篇文章最後的謎底之前，我們還是先搞清楚這個行程到底是不是完全卡住了。

其實，在新一點的Linux核心中，/proc/PID/status 這個檔案可以告訴我們這點：

[root@oel6 ~]# cat /proc/27288/status 
Name:	find
State:	D (disk sleep)
Tgid:	27288
Pid:	27288
PPid:	27245
TracerPid:	0
Uid:	0	0	0	0
Gid:	0	0	0	0
FDSize:	256
Groups:	0 1 2 3 4 6 10 
VmPeak:	  112628 kB
VmSize:	  112280 kB
VmLck:	       0 kB
VmHWM:	    1508 kB
VmRSS:	    1160 kB
VmData:	     260 kB
VmStk:	     136 kB
VmExe:	     224 kB
VmLib:	    2468 kB
VmPTE:	      88 kB
VmSwap:	       0 kB
Threads:	1
SigQ:	4/15831
SigPnd:	0000000000040000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000000000000
SigCgt:	0000000180000000
CapInh:	0000000000000000
CapPrm:	ffffffffffffffff
CapEff:	ffffffffffffffff
CapBnd:	ffffffffffffffff
Cpus_allowed:	ffffffff,ffffffff
Cpus_allowed_list:	0-63
Mems_allowed:	00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	9950
nonvoluntary_ctxt_switches:	17104

(主要看State欄位和最後兩行：voluntary_ctxt_switches和 nonvoluntary_ctxt_switches)

行程處於D——Disk Sleep（不可打斷休眠狀態），voluntary_ctxt_switches 和 nonvoluntary_ctxt_switches的數量則能告訴我們這個行程被分給時間片的次數。過幾秒再看看這些數字有沒有增加，如果沒有增加，則說明這個行程是完全卡死的，目前我在追蹤的例子就是這個情況，反之，則說明行程不是完全卡住的狀態。

順便提一下，還有兩種辦法也可以獲取行程的背景關係切換數量（第二種在老舊的核心上也能工作）：

[root@oel6 ~]# cat /proc/27288/sched
find (27288, #threads: 1)
---------------------------------------------------------
se.exec_start                      :     617547410.689282
se.vruntime                        :       2471987.542895
se.sum_exec_runtime                :          1119.480311
se.statistics.wait_start           :             0.000000
se.statistics.sleep_start          :             0.000000
se.statistics.block_start          :     617547410.689282
se.statistics.sleep_max            :             0.089192
se.statistics.block_max            :         60082.951331
se.statistics.exec_max             :             1.110465
se.statistics.slice_max            :             0.334211
se.statistics.wait_max             :             0.812834
se.statistics.wait_sum             :           724.745506
se.statistics.wait_count           :                27211
se.statistics.iowait_sum           :             0.000000
se.statistics.iowait_count         :                    0
se.nr_migrations                   :                  312
se.statistics.nr_migrations_cold   :                    0
se.statistics.nr_failed_migrations_affine:                    0
se.statistics.nr_failed_migrations_running:                   96
se.statistics.nr_failed_migrations_hot:                 1794
se.statistics.nr_forced_migrations :                  150
se.statistics.nr_wakeups           :                18507
se.statistics.nr_wakeups_sync      :                    1
se.statistics.nr_wakeups_migrate   :                  155
se.statistics.nr_wakeups_local     :                18504
se.statistics.nr_wakeups_remote    :                    3
se.statistics.nr_wakeups_affine    :                  155
se.statistics.nr_wakeups_affine_attempts:                  158
se.statistics.nr_wakeups_passive   :                    0
se.statistics.nr_wakeups_idle      :                    0
avg_atom                           :             0.041379
avg_per_cpu                        :             3.588077
nr_switches                        :                27054
nr_voluntary_switches              :                 9950
nr_involuntary_switches            :                17104
se.load.weight                     :                 1024
policy                             :                    0
prio                               :                  120
clock-delta                        :                   72

我們要的就是輸出中的nr_switches欄位（等於 nr_voluntary_switches + nr_involuntary_switches），值是27054，跟/proc/PID/schedstat 中的第三個欄位是一致的：

[root@oel6 ~]# cat /proc/27288/schedstat 
1119480311 724745506 27054

等一段時間，也是一樣的結果，數量沒有增長……

透過/proc檔案系統初探Linux核心態世界

看情況我們的程式是卡死無疑了，strace和pstack這些使用ptrace系統呼叫來attach到行程上來進行跟蹤的除錯器也沒啥用，因為行程已經完全卡住了，那麼ptrace這種系統呼叫估計也會把自己卡住。（順便說一下，我曾經用strace來跟蹤attach到其他行程上的strace，結果strace把那個行程搞掛了。別說我沒警告過你）！

沒了strace和pstack，我們還能怎麼查程式卡在了哪個系統呼叫呢？當然是 /proc/PID/syscall 了！

[root@oel6 ~]# cat /proc/27288/syscall 
262 0xffffffffffffff9c 0x20cf6c8 0x7fff97c52710 0x100 0x100 0x676e776f645f616d 0x7fff97c52658 0x390e2da8ea

這鬼輸出怎麼看呢？很簡單，0x加很大的數字一般就是記憶體地址（使用pmap類似的工具可以看具體他們指向了什麼內容），如果是很小的數字的話，很可能就是一些索引號（例如開啟的檔案描述符，就像/proc/PID/fd的內容一樣）。在這個例子中，因為是syscall檔案，你可以”合理猜測“這是一個系統呼叫號：行程卡在了262號系統呼叫！

需要註意的是系統呼叫號在不同的系統上可能是不一致的，所以你必須從一個合適的.h檔案中去檢視它具體指向了哪個呼叫。通常情況下，在/usr/include中搜索 syscall* 是個很好的切入點。在我的系統上，這個系統呼叫是在 /usr/include/asm/unistd_64.h中定義的：

[root@oel6 ~]# grep 262 /usr/include/asm/unistd_64.h 
#define __NR_newfstatat				262

根據上面顯示的結果可以看到這個系統呼叫叫 newfstatat，我們只需要man newfstatat就可以知道這是乾啥的了。針對系統呼叫有一個實用小技巧分享：如果man手冊中沒有發現一個系統呼叫，那麼請嘗試刪除一些特定的字首或者字尾（例如man pread64不行就嘗試man pread）。還或者，乾脆google之……

總之，這個叫“new-fstat-at”的系統呼叫的作用就是讓你可以像 stat 系統呼叫一樣讀取檔案的屬性，我們的程式就是卡在這個操作上，終於在除錯這個程式的道路上邁出了一大步，不容易！但是為啥會卡在這個呼叫呢？

好吧，終於要亮真本事了。隆重介紹：/proc/PID/stack，能讓你看到一個行程核心態的呼叫棧資訊的神器，而且只是透過cat一個proc檔案！！！

[root@oel6 ~]# cat /proc/27288/stack
[] rpc_wait_bit_killable+0x24/0x40 [sunrpc]
[] __rpc_execute+0xf5/0x1d0 [sunrpc]
[] rpc_execute+0x43/0x50 [sunrpc]
[] rpc_run_task+0x75/0x90 [sunrpc]
[] rpc_call_sync+0x42/0x70 [sunrpc]
[] nfs3_rpc_wrapper.clone.0+0x35/0x80 [nfs]
[] nfs3_proc_getattr+0x47/0x90 [nfs]
[] __nfs_revalidate_inode+0xcc/0x1f0 [nfs]
[] nfs_revalidate_inode+0x36/0x60 [nfs]
[] nfs_getattr+0x5f/0x110 [nfs]
[] vfs_getattr+0x4e/0x80
[] vfs_fstatat+0x70/0x90
[] sys_newfstatat+0x24/0x50
[] system_call_fastpath+0x16/0x1b
[] 0xffffffffffffffff

可以看到最頂部的函式就是我們現在卡在的地方，正是上面WCHAN欄位顯示的內容：rpc_wait_bit_killable。（註意：實際上不一定最頂部的函式就是我們想要的，因為內核可能也執行了 schedule 之類的函式來讓程式進入休眠或者執行。這裡沒有顯示可能是因為卡主是因為其他呼叫卡主了才進入睡眠狀態，而不是相反的邏輯）。

多虧了這個神器，我們現在可以從頭到尾推匯出程式卡主的整個過程和造成最終 rpc_wait_bit_killable 函式卡主的原因了：

最底部的 system_call_fastpath 是一個非常常見的系統呼叫處理函式，正是它呼叫了我們剛才一直有疑問的 newfstatat 系統呼叫。然後，再往上可以看到一堆nfs相關的子函式呼叫，這樣我們基本可以斷定正nfs相關的下層程式碼導致了程式卡住。我沒有推斷說問題是出在nfs的程式碼裡是因為繼續往上可以看到rpc相關的函式，可以推斷是nfs為了跟其他行程進行通訊又呼叫了rpc相關的函式——在這個例子中，可能是[kworker/N:N]，[nfsiod]， [lockd] or[rpciod]

等內核的IO執行緒，但是這個行程因為某些原因（猜測是網路連結斷開之類的問題）再也沒有收到響應的回覆。

同樣的，我們可以利用以上的方法來檢視哪些輔助IO的核心執行緒為什麼會卡在網路相關的操作上，儘管kworkers就不簡簡單單是NFS的RPC通訊了。在另外一次問題重現的嘗試（透過NFS複製大檔案）中，我剛好捕捉到一次kwrokers等待網路的情況：

[root@oel6 proc]# for i in `pgrep worker` ; do ps -fp $i ; cat /proc/$i/stack ; done
UID        PID  PPID  C STIME TTY          TIME CMD
root        53     2  0 Feb14 ?        00:04:34 [kworker/1:1]

[] __cond_resched+0x2a/0x40
[] lock_sock_nested+0x35/0x70
[] tcp_sendmsg+0x29/0xbe0
[] inet_sendmsg+0x48/0xb0
[] sock_sendmsg+0xef/0x120
[] kernel_sendmsg+0x41/0x60
[] xs_send_kvec+0x8e/0xa0 [sunrpc]
[] xs_sendpages+0x173/0x220 [sunrpc]
[] xs_tcp_send_request+0x5d/0x160 [sunrpc]
[] xprt_transmit+0x83/0x2e0 [sunrpc]
[] call_transmit+0xa8/0x130 [sunrpc]
[] __rpc_execute+0x66/0x1d0 [sunrpc]
[] rpc_async_schedule+0x15/0x20 [sunrpc]
[] process_one_work+0x13e/0x460
[] worker_thread+0x17c/0x3b0
[] kthread+0x96/0xa0
[] kernel_thread_helper+0x4/0x10

透過開啟內核的tracing肯定可以確切找到是內核的哪兩個執行緒之間再通訊，不過限於文章篇幅，這裡就不展開了，畢竟這隻是一個實用（且簡單）的問題追蹤定位練習。

診斷和“修複”

多虧了現代核心提供的棧資訊存樣，我們得以系統地追蹤到我們的find命令卡在了哪裡——核心中的NFS程式碼。而且一般情況下，NFS相關卡死，最需要懷疑的就是網路問題。你猜我是怎麼重現上面的這個問題的？其實就是在功過NFS掛在虛擬中的一塊磁碟，執行find命令，然後讓虛擬機器休眠……這樣就可以重現類似網路（配置或者防火牆）導致的連結默默斷掉但是並沒有通知TCP另一端的行程的情況。

因為 rpc_wait_bit_killable 是可以直接被安全幹掉的函式，這裡我們選擇透過 kill -9直接幹掉它：

[root@oel6 ~]# ps -fp 27288
UID        PID  PPID  C STIME TTY          TIME CMD
root     27288 27245  0 11:57 pts/0    00:00:01 find . -type f
[root@oel6 ~]# kill -9 27288

[root@oel6 ~]# ls -l /proc/27288/stack
ls: cannot access /proc/27288/stack: No such file or directory

[root@oel6 ~]# ps -fp 27288
UID        PID  PPID  C STIME TTY          TIME CMD
[root@oel6 ~]#

行程被殺掉了，好了，問題解決 🙂

註：文章沒有翻譯完，下麵還有一段不是那麼有意思的小工具和廣告，沒動力翻下去了 😛