文章翻譯自 Peeking into Linux kernel-land using /proc filesystem for quick’n’dirty troubleshooting
這篇博客的內(nèi)容完全是關(guān)于現(xiàn)代Linux內(nèi)核的。換句話說，指的是與RHEL6一樣使用的2.6.3x系列內(nèi)核，而不是古老的RHEL5所使用的2.6.18內(nèi)核（都什么鬼了？?。?，雖然大部分企業(yè)都還在使用RHEL5。另外，這篇文章也不會(huì)涉及內(nèi)核調(diào)試器或者SystemTap腳本之類的東西，完全是最最簡單地在有用的proc文件系統(tǒng)節(jié)點(diǎn)上執(zhí)行“cat /proc/PID/xyz”這樣的命令。
定位一個(gè)程序“運(yùn)行緩慢”的問題
下面要舉的這個(gè)例子是這樣的：一個(gè)DBA反映說他們的find命令一直運(yùn)行緩慢，半天都沒有什么輸出，他們想知道這是為什么。聽到這個(gè)問題的時(shí)候我就大概有直覺造成這個(gè)問題的原因，但是他們還是想知道怎么系統(tǒng)地追蹤這類問題，并找到解決方案。剛好出問題的現(xiàn)場還在……
還好，系統(tǒng)是運(yùn)行在OEL6上的，內(nèi)核比較新，確切地說是2.6.39 UEK2。
首先，讓我們看看find進(jìn)程是否還在：
[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（請記好這個(gè)將會(huì)伴隨整篇博客的數(shù)字）。
那么，我們就從最基礎(chǔ)的開始分析它的瓶頸：如果它不是被什么操作卡住了（例如從cache中加載它所需要的內(nèi)容），它應(yīng)該是100%的CPU占用率；如果它的瓶頸在IO或者資源競爭，那么它應(yīng)該是很低的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
結(jié)果很清楚：這個(gè)進(jìn)程的CPU占用率很低，幾乎為零。但是CPU占用低也分情況：一種是進(jìn)程完全卡住了，根本沒有機(jī)會(huì)獲得時(shí)間片；另一種是進(jìn)程在不停進(jìn)入等待的狀態(tài)（例如poll動(dòng)作就是時(shí)不時(shí)超時(shí)后，進(jìn)程進(jìn)入休眠狀態(tài)）。雖然這剩下的細(xì)節(jié)top還不足以完全給我們展示，但是至少我們知道了這個(gè)進(jìn)程沒有在燒CPU時(shí)間。
通常情況下，如果進(jìn)程處于這種狀態(tài)（%0的CPU占用一般說明進(jìn)程是卡在了某個(gè)系統(tǒng)調(diào)用，因?yàn)檫@個(gè)系統(tǒng)調(diào)用阻塞了，內(nèi)核需要把進(jìn)程放到休眠狀態(tài)），我都會(huì)用strace跟蹤一下這個(gè)進(jìn)程具體卡在了哪個(gè)系統(tǒng)調(diào)用。而且，如果進(jìn)程不是完全卡住了，那進(jìn)程中的系統(tǒng)調(diào)用情況也會(huì)在strace的輸出中有所展示（因?yàn)橐话阕枞南到y(tǒng)調(diào)用會(huì)在超時(shí)返回后，過一段時(shí)間再進(jìn)入阻塞等待的狀態(tài)）。
讓我們試試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自己也卡住了！半天沒有輸出，也不響應(yīng)Ctrl-C，我不得不通過Ctrl-Z把它扔到后臺再殺掉它。想簡單處理還真是不容易啊。
那只好再試試pstack了（Linux上的pstack只是用shell腳本包了一下GDB）。盡管pstack看不到內(nèi)核態(tài)的內(nèi)容，但是至少它能告訴我們是哪個(gè)系統(tǒng)調(diào)用最后執(zhí)行的（通常pstack輸出的用戶態(tài)調(diào)用棧最頂部是一個(gè)libc庫的系統(tǒng)調(diào)用）：
[root@oel6 ~]# pstack 27288
^C
^Z
[1]+ Stopped pstack 27288
[root@oel6 ~]# kill %%
[1]+ Stopped pstack 27288
[root@oel6 ~]#
[1]+ Terminated pstack 27288
呵呵，pstack也卡住了，什么輸出都沒有！
至此，我們還是不知道我們的程序是怎么卡住了，卡在哪里了。
好吧，還怎么進(jìn)行下去呢？還有一些常用的信息可以搜集——進(jìn)程的status字段和WCHAN字段，這些使用古老的ps就能查看（或許最開始就應(yīng)該用ps看看這個(gè)進(jìn)程是不是已經(jīng)成僵尸進(jìn)程了）：
[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
需要注意的是，你要多運(yùn)行幾次ps以確保進(jìn)程還在同一個(gè)狀態(tài)（不然在不湊巧的時(shí)候獲取了一個(gè)錯(cuò)誤的狀態(tài)就麻煩了），我這里為了簡短就只貼一次輸出了。
進(jìn)程此時(shí)正處于D狀態(tài)，按照man手冊的說法，這通常是因?yàn)榇疟PIO導(dǎo)致的。而WCHAN字段（表示導(dǎo)致程序處于休眠/等待狀態(tài)的函數(shù)調(diào)用）則有點(diǎn)兒被切掉了。顯然我可以翻一下ps的man手冊，看看怎么把這個(gè)字段調(diào)寬一點(diǎn)好完整打印出來，不過既然我都知道了這個(gè)信息來自于proc文件系統(tǒng)，就沒這個(gè)必要了。
直接從它的源頭讀一下看看（再次說明一下，多試幾次看看，畢竟我們還不知道這個(gè)進(jìn)程到底是不是完全卡死了呢）：
[root@oel6 ~]# cat /proc/27288/wchan
rpc_wait_bit_killable
額……這個(gè)進(jìn)程居然在等待某些RPC調(diào)用。RPC調(diào)用通常意味著這個(gè)程序在跟其他進(jìn)程通信（不管是本地還是遠(yuǎn)程）?？倸w，我們還是不知道為什么會(huì)卡住。
到底是不是完全卡住了？
在我們揭開這篇文章最后的謎底之前，我們還是先搞清楚這個(gè)進(jìn)程到底是不是完全卡住了。
其實(shí)，在新一點(diǎn)的Linux內(nèi)核中，/proc/PID/status 這個(gè)文件可以告訴我們這點(diǎn)：
[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)
進(jìn)程處于D——Disk Sleep（不可打斷休眠狀態(tài)），voluntary_ctxt_switches 和 nonvoluntary_ctxt_switches的數(shù)量則能告訴我們這個(gè)進(jìn)程被分給時(shí)間片的次數(shù)。過幾秒再看看這些數(shù)字有沒有增加，如果沒有增加，則說明這個(gè)進(jìn)程是完全卡死的，目前我在追蹤的例子就是這個(gè)情況，反之，則說明進(jìn)程不是完全卡住的狀態(tài)。
順便提一下，還有兩種辦法也可以獲取進(jìn)程的上下文切換數(shù)量（第二種在老舊的內(nèi)核上也能工作）：
[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 中的第三個(gè)字段是一致的：
[root@oel6 ~]# cat /proc/27288/schedstat
1119480311 724745506 27054
等一段時(shí)間，也是一樣的結(jié)果，數(shù)量沒有增長……
通過/proc文件系統(tǒng)初探Linux內(nèi)核態(tài)世界
看情況我們的程序是卡死無疑了，strace和pstack這些使用ptrace系統(tǒng)調(diào)用來attach到進(jìn)程上來進(jìn)行跟蹤的調(diào)試器也沒啥用，因?yàn)檫M(jìn)程已經(jīng)完全卡住了，那么ptrace這種系統(tǒng)調(diào)用估計(jì)也會(huì)把自己卡住。（順便說一下，我曾經(jīng)用strace來跟蹤attach到其他進(jìn)程上的strace，結(jié)果strace把那個(gè)進(jìn)程搞掛了。別說我沒警告過你）！
沒了strace和pstack，我們還能怎么查程序卡在了哪個(gè)系統(tǒng)調(diào)用呢？當(dāng)然是 /proc/PID/syscall 了！
[root@oel6 ~]# cat /proc/27288/syscall
262 0xffffffffffffff9c 0x20cf6c8 0x7fff97c52710 0x100 0x100 0x676e776f645f616d 0x7fff97c52658 0x390e2da8ea
這鬼輸出怎么看呢？很簡單，0x加很大的數(shù)字一般就是內(nèi)存地址（使用pmap類似的工具可以看具體他們指向了什么內(nèi)容），如果是很小的數(shù)字的話，很可能就是一些索引號（例如打開的文件描述符，就像/proc/PID/fd的內(nèi)容一樣）。在這個(gè)例子中，因?yàn)槭莝yscall文件，你可以”合理猜測“這是一個(gè)系統(tǒng)調(diào)用號：進(jìn)程卡在了262號系統(tǒng)調(diào)用！
需要注意的是系統(tǒng)調(diào)用號在不同的系統(tǒng)上可能是不一致的，所以你必須從一個(gè)合適的.h文件中去查看它具體指向了哪個(gè)調(diào)用。通常情況下，在/usr/include中搜索 syscall* 是個(gè)很好的切入點(diǎn)。在我的系統(tǒng)上，這個(gè)系統(tǒng)調(diào)用是在 /usr/include/asm/unistd_64.h中定義的：
[root@oel6 ~]# grep 262 /usr/include/asm/unistd_64.h
#define __NR_newfstatat 262
根據(jù)上面顯示的結(jié)果可以看到這個(gè)系統(tǒng)調(diào)用叫 newfstatat，我們只需要man newfstatat就可以知道這是干啥的了。針對系統(tǒng)調(diào)用有一個(gè)實(shí)用小技巧分享：如果man手冊中沒有發(fā)現(xiàn)一個(gè)系統(tǒng)調(diào)用，那么請嘗試刪除一些特定的前綴或者后綴（例如man pread64不行就嘗試man pread）。還或者，干脆google之……
總之，這個(gè)叫“new-fstat-at”的系統(tǒng)調(diào)用的作用就是讓你可以像 stat 系統(tǒng)調(diào)用一樣讀取文件的屬性，我們的程序就是卡在這個(gè)操作上，終于在調(diào)試這個(gè)程序的道路上邁出了一大步，不容易！但是為啥會(huì)卡在這個(gè)調(diào)用呢？
好吧，終于要亮真本事了。隆重介紹：/proc/PID/stack，能讓你看到一個(gè)進(jìn)程內(nèi)核態(tài)的調(diào)用棧信息的神器，而且只是通過cat一個(gè)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
可以看到最頂部的函數(shù)就是我們現(xiàn)在卡在的地方，正是上面WCHAN字段顯示的內(nèi)容：rpc_wait_bit_killable。（注意：實(shí)際上不一定最頂部的函數(shù)就是我們想要的，因?yàn)閮?nèi)核可能也執(zhí)行了 schedule 之類的函數(shù)來讓程序進(jìn)入休眠或者運(yùn)行。這里沒有顯示可能是因?yàn)榭ㄖ魇且驗(yàn)槠渌{(diào)用卡主了才進(jìn)入睡眠狀態(tài)，而不是相反的邏輯）。
多虧了這個(gè)神器，我們現(xiàn)在可以從頭到尾推導(dǎo)出程序卡主的整個(gè)過程和造成最終 rpc_wait_bit_killable 函數(shù)卡主的原因了：
? 最底部的 system_call_fastpath 是一個(gè)非常常見的系統(tǒng)調(diào)用處理函數(shù)，正是它調(diào)用了我們剛才一直有疑問的 newfstatat 系統(tǒng)調(diào)用。然后，再往上可以看到一堆nfs相關(guān)的子函數(shù)調(diào)用，這樣我們基本可以斷定正nfs相關(guān)的下層代碼導(dǎo)致了程序卡住。我沒有推斷說問題是出在nfs的代碼里是因?yàn)槔^續(xù)往上可以看到rpc相關(guān)的函數(shù)，可以推斷是nfs為了跟其他進(jìn)程進(jìn)行通信又調(diào)用了rpc相關(guān)的函數(shù)——在這個(gè)例子中，可能是[kworker/N:N], [nfsiod], [lockd] or [rpciod]等內(nèi)核的IO線程，但是這個(gè)進(jìn)程因?yàn)槟承┰颍ú聹y是網(wǎng)絡(luò)鏈接斷開之類的問題）再也沒有收到響應(yīng)的回復(fù)。
同樣的，我們可以利用以上的方法來查看哪些輔助IO的內(nèi)核線程為什么會(huì)卡在網(wǎng)絡(luò)相關(guān)的操作上，盡管kworkers就不簡簡單單是NFS的RPC通信了。在另外一次問題重現(xiàn)的嘗試（通過NFS拷貝大文件）中，我剛好捕捉到一次kwrokers等待網(wǎng)絡(luò)的情況：
[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
通過開啟內(nèi)核的tracing肯定可以確切找到是內(nèi)核的哪兩個(gè)線程之間再通信，不過限于文章篇幅，這里就不展開了，畢竟這只是一個(gè)實(shí)用（且簡單）的問題追蹤定位練習(xí)。
診斷和“修復(fù)”
多虧了現(xiàn)代內(nèi)核提供的棧信息存樣，我們得以系統(tǒng)地追蹤到我們的find命令卡在了哪里——內(nèi)核中的NFS代碼。而且一般情況下，NFS相關(guān)卡死，最需要懷疑的就是網(wǎng)絡(luò)問題。你猜我是怎么重現(xiàn)上面的這個(gè)問題的？其實(shí)就是在功過NFS掛在虛擬中的一塊磁盤，執(zhí)行find命令，然后讓虛擬機(jī)休眠……這樣就可以重現(xiàn)類似網(wǎng)絡(luò)（配置或者防火墻）導(dǎo)致的鏈接默默斷掉但是并沒有通知TCP另一端的進(jìn)程的情況。
因?yàn)?rpc_wait_bit_killable 是可以直接被安全干掉的函數(shù)，這里我們選擇通過 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 ~]#
進(jìn)程被殺掉了，好了，問題解決 :)
注：文章沒有翻譯完，下面還有一段不是那么有意思的小工具和廣告，沒動(dòng)力翻下去了 :P
