通过proc 查看Linux 内核态调⽤栈来定位卡死问题
前⼏天碰到⼀个问题：⼀个进程运⾏过程中挂死了，把gdb 挂上去之后bt 打印的内容为空，后来通过查看 /proc ⽂件系统，查看程的调⽤栈，才发现是发消息给内核态程序时，内核态⼀直没有响应，导致⽤户态进程挂死。刚好在⽹上看到⼀篇描述通过 /proc ⽂件系统来定位问题的⽂章，这篇⽂章讲解得⽐较清楚，因此尝试翻译出来。原⽂地址：
这篇博客是基于现代的。换句话说，是RHEL6所对应的2.6.3x 内核版本，⽽不是古⽼的RHEL5所对应的2.6.18内核版本(神马玩意⼉?!)，很不幸是后者才是企业中最常见的版本。并且，在这⾥我不打算使⽤内核调试器或者SystemTap 脚本，只使⽤平凡⽽古⽼的cat /proc/PID/xyz ，⽽不是那些便捷的/proc ⽂件系统⼯具。
定位⼀个“运⾏慢”的进程
我打算介绍⼀个系统性定位问题的例⼦，我在⼿提电脑上重现了这个例⼦。⼀个DBA 想知道为什么他的find 命令运⾏起来"⾮常慢"，并且很长时间都没有返回任何结果。了解环境之后，我对这个问题的起因有⼀个直觉的答案，但是他问我，对于这种正在发⽣中的问题，有没有系统性的⽅法⽴刻进⾏定位。
幸运的是，这个系统运⾏的是OEL6，因此刚好有⼀个新内核。确切的说2.6.39 UEK2。
那么，让我们试着定位⼀下。⾸先，看看find 进程是否还活着：
是的，他还在 —— PID 27288 （在整个定位问题的过程中我将会⼀直使⽤这个pid ）。
让我们从最基本的开始，先看下这个进程的瓶颈在什么地⽅ —— 如果不是被什么操作阻塞的话（例如从缓存中读取需要的数据），CPU 占⽤率应该是100%。如果瓶颈是IO 或者连接问题，CPU 占⽤率应该很低，或者就是0%。top 的结果显⽰这个进程的CPU 占⽤率是0%，或者⾮常接近0%（因此输出被四舍五⼊为0%）。这两种情况实际上有着重要的差别，⼀种情况是进程完全挂死，根本没有机会获得CPU ，另⼀种情况是进程不时的退出等待状态（例如，某些轮询操作不时的超时，⽽进程选择继续sleep ）。因此，Linux 上的top 并不是⼀个适合显⽰这种差别的⼯具 —— 但是⾄少我们知道了进程并不是占⽤了⼤量的CPU 。
让我们⽤其他命令试试。通常当⼀个进程看起来好像挂死时（0%的CPU 占⽤率通常意味着进程挂在某些阻塞性的系统调⽤上 —— 这会导致内核让进程进⼊休眠状态），我会在这个进程上运⾏strace 来跟踪进程挂在哪个系统调⽤上。同样的，如果进程并没有完全挂死，⽽是不时的从系统调⽤中返回并且被短暂的唤醒，这种情况也会呈现在strace 中（阻塞性的系统调⽤将会完成并很快的再次进⼊）：
1
[root@oel6 ~]# ps -ef | grep find 2
root    27288 27245  4 11:57 pts/0 00:00:01 find . -type f 3root    27334 27315  0 11:57 pts/1 00:00:00 grep find
41
[root@oel6 ~]# top -cbp 272882
top - 11:58:15 up 7 days,  3:38,  2 users,  load average: 1.21, 0.65, 0.473
Tasks:  1 total,  0 running,  1 sleeping,  0 stopped,  0 zombie 4
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 5
Mem:  2026460k total,  1935780k used,  90680k free,    64416k buffers 6
Swap:  4128764k total,  251004k used,  3877760k free,  662280k cached 7
8
PID USER    PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND 927288 root    20  0  109m 1160  844 D  0.0  0.1  0:01.11 find . -type f
10
天啊，strace 命令也挂住了！strace 很长时间都没有打印任何东西，并也不能响应CTRL+C ，因此我不得不⽤CTRL+Z ，并杀死它。简单的诊断⼿段就这些了。
让我们再试试pstack （在Linux 上，pstack 就是GDB 调试器的⼀个shell 包装）。尽管pstack 并不能查看内核态信息，它仍然能够告诉我们是哪个系统调⽤被执⾏了（通常，有⼀个相应的libc 库调⽤显⽰在⽤户态堆栈的顶端上）：
pstatck 也挂死了，什么都没返回！
因此，我们还是不知道我们的进程是100%（⽆可救药的）挂死了还是99.99%的挂住了（进程还在运⾏只是在睡眠） ——以及在哪⼉挂住了。
好了，还有别的可以看吗？还有⼀个更普通的东西可以坚持 —— 进程状态和WCHAN 字段，可以通过古⽼⽽美好的ps （也许我早就应该运⾏这个命令，以确认进程到底是不是僵死了）：
你应该多运⾏⼏次ps 命令，以确保进程⼀直是同⼀个状态（你肯定不想被⼀个偶然的单独采样所误导），为了简洁⼀点这⾥只显⽰⼀次结果。
进程状态是D （不可中断睡眠状态，也就是不会被任何外部信号唤醒），这个状态通常与磁盘IO 相关（ps 帮助上也这样
说）。并且WCHAN 字段（表⽰导致进程睡眠或者等待的函数）被截断了⼀点。我可以⽤ps 选项（参考帮助）把这个字段打印得跟宽⼀点，但是既然这个信息是来⾃proc ⽂件系统，就让我们直接到源头去查询吧（再强调⼀次，既然我们不确定我们的进程到底是完全挂死了还是仅仅只是经常处于睡眠状态，那么最好把这个命令多执⾏⼏次以获取多次采样结果）：
1
[root@oel6 ~]# strace -cp 272882
Process 27288 attached - interrupt to quit 3
4
^C 5
^Z 6
[1]+  Stopped                strace -cp 272887
8
[root@oel6 ~]# kill -9 %%9
[1]+  Stopped                strace -cp 2728810
[root@oel6 ~]# 11[1]+  Killed                  strace -cp 27288
121
[root@oel6 ~]# pstack 272882
3
^C 4
^Z 5
[1]+  Stopped                pstack 272886
7
[root@oel6 ~]# kill %%8
[1]+  Stopped                pstack 272889
[root@oel6 ~]# 10[1]+  Terminated              pstack 27288
111
[root@oel6 ~]# ps -flp 272882
F S UID    PID  PPID  C PRI  NI ADDR SZ **WCHAN**  STIME TTY        TIME CMD 30 D root    27288 27245  0  80  0 - 28070 **rpc_wa** 11:57 pts/0  00:00:01 find . -type f
41
[root@oel6 ~]# cat /proc/27288/wchan 2rpc_wait_bit_killable
3
嗯，进程是在等待某个RPC 调⽤。RPC 通常意味着进程是在和其它进程通信（可能是本地服务进程或者远程服务进程）。但是我们还是不知道为什么挂住。
进程有什么活动或者完全挂死了？
在我们进⼊这篇⽂章中真正有营养的部分之前，让我们先弄清楚进程到底有没有完全挂死。在最新的系统内核
上/proc/PID/status 可以告诉我们答案：
进程状态是D —— Disk Sleep （不可中断睡眠）。然后看看voluntaryctxtswitches  和nonvoluntaryctxtswitches 的数值 —— 它可以告诉你进程占⽤（或者释放）了多少次CPU 。等⼏秒钟之后，再次执⾏该命令，看看这些数值有没有增加。在我这个案例中，这些数值没有增加，据此我可以得出结论，这个进程是完全挂死了（额，⾄少在执⾏命令的这⼏秒钟内是完全挂死的）。所以，现在我更有信⼼认为这个进程是完全挂死了（⽽不是在飞⾏在雷达探测不到地带 —— 在0.04%以下的低CPU 占⽤率下运⾏）。
顺便说⼀句，有两个地⽅可以获得上下⽂切换次数（并且第⼆种⽅法还可以在⽼的系统内核上⼯作）：
1
[root@oel6 ~]# cat /proc/27288/status 2
Name:  find 3
State:  D (disk sleep)4
Tgid:  272885
Pid:    272886
PPid:  272457
TracerPid:  08
Uid:    0  0  0  09
Gid:    0  0  0  010
FDSize: 25611
Groups: 0 1 2 3 4 6 10 12
VmPeak:  112628 kB 13
VmSize:  112280 kB 14
VmLck:        0 kB 15
VmHWM:      1508 kB 16
VmRSS:      1160 kB 17
VmData:      260 kB 18
VmStk:      136 kB 19
VmExe:      224 kB 20
VmLib:      2468 kB 21
VmPTE:        88 kB 22
VmSwap:        0 kB 23
Threads:    124
SigQ:  4/1583125
SigPnd: 000000000004000026
ShdPnd: 000000000000000027
SigBlk: 000000000000000028
SigIgn: 000000000000000029
SigCgt: 000000018000000030
CapInh: 000000000000000031
CapPrm: ffffffffffffffff 32
CapEff: ffffffffffffffff 33
CapBnd: ffffffffffffffff 34
Cpus_allowed:  ffffffff,ffffffff 35
Cpus_allowed_list:  0-6336
Mems_allowed:  37
00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,38
00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,39
00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,40
00000000,00000000,00000000,00000000,0000000141
Mems_allowed_list:  042
voluntary_ctxt_switches:    995043nonvoluntary_ctxt_switches: 17104
44
你需要看看nr_switchs 的数值（等于nrvoluntaryswitches  +nrinvoluntaryswitches ）。
在上⾯的输出中，总的nr_switches 次数是27054，这个值同时也是/proc/PID/schedstat 的结果中的第3个字段。
并且它不会增加...
⽤/proc ⽂件系统查看内核态信息
那么，看起来我们的进程很漂亮的挂死了:)strace 和pstatck 都没有⽤武之地。它们使⽤ptrace()系统调⽤来附着到进程上，并查看进程的内存，但是由于进程绝望的挂死了，很可能挂在某个系统调⽤上，因此我猜测ptrace()调调本⾝也被挂住了。（顺便说⼀句，我试过strace 那个附着到⽬标进程的strace 进程，结果⽬标进程崩溃了。记着我警告过你:)。）
那么，怎么看到底挂在哪个系统调⽤上呢 —— 没法⽤strace 或者pstack ？幸运的是我运⾏的是现代的内核 ——
跟/proc/PID/syscall 打个招呼吧！
2
find (27288, #threads: 1)3
---------------------------------------------------------4
<_start                      :    617547410.6892825
se.vruntime                        :      2471987.5428956
se.sum_exec_runtime                :          1119.4803117
se.statistics.wait_start          :            0.0000008
se.statistics.sleep_start          :            0.0000009
se.statistics.block_start          :    617547410.68928210
se.statistics.sleep_max            :            0.08919211
se.statistics.block_max            :        60082.95133112
_max            :            1.11046513
se.statistics.slice_max            :            0.33421114
se.statistics.wait_max            :            0.81283415
se.statistics.wait_sum            :          724.74550616
se.statistics.wait_count          :                2721117
se.statistics.iowait_sum          :            0.00000018
se.statistics.iowait_count        :                    019
<_migrations                  :                  31220
_migrations_cold  :                    021
_failed_migrations_affine:                    022
_failed_migrations_running:                  9623
_failed_migrations_hot:                179424
_forced_migrations :                  15025
_wakeups          :                1850726
_wakeups_sync      :                    127
_wakeups_migrate  :                  15528
_wakeups_local    :                1850429
_wakeups_remote    :                    330
_wakeups_affine    :                  15531
_wakeups_affine_attempts:                  15832
_wakeups_passive  :                    033
_wakeups_idle      :                    034
avg_atom                          :            0.04137935
avg_per_cpu                        :            3.58807736
nr_switches                        :                2705437
nr_voluntary_switches              :                995038
nr_involuntary_switches            :                1710439
se.load.weight                    :                102440
policy                            :                    041
prio                              :                  12042clock-delta                        :                  72
431
[root@oel6 ~]# cat /proc/27288/schedstat 21119480311 724745506 27054
3
好了，我可以拿他⼲嘛呢？ 嗯，这些数字代表某些东西。如果它是⼀个"0x 很⼤的数"，它通常表⽰⼀个内存地址（并
且，pmap 之类的⼯具可以⽤来查看它指向那⾥）；但是如果是⼀个很⼩的数字，那么很可能是⼀个数组索引 —— 例如打开的⽂件描述符数组（可以从/prco/PID/fd 读取到），或者是当前进程正在执⾏的系统调⽤号 —— 既然在这个例⼦中，我们正在处理系统调⽤。那么，这个进程是挂死在#262号系统调⽤上吗？
注意在不同的OS 类型、版本或者平台之间，系统调⽤号可能不同，因此你需要看看对应的OS 上的.h ⽂件。通常应该在/usr/include 中搜索"syscall*"。在我的Linux 上，系统调⽤定义在/usr/include/asm/unistd_64.h 中：
到了！系统调⽤262是某个叫做newfstatat 的东西。打开⼿册看看它到底是什么。关于系统调⽤名称有⼀个⼩⼩的技巧
—— 如果在⼿册中不到这个系统调⽤，试试去掉后缀或者前缀（例如，⽤man pread 代替man pread64）—— 在这个例⼦中，查时去掉"new" ——man fstata 。或者直接google 。
⽆论如何，系统调⽤"new-fstat-at"允许你读取⽂件属性，⾮常像通常的"stat"系统调⽤。那么我们挂在这个⽂件元数据读取操作上。我们前进了⼀步，但是仍然不知道为什么会挂在这⼉？
好了，跟我的⼩朋友/proc/PID/statck 打个招呼吧，使⽤它可以读取进程的内核堆栈的调试信息：
最上⾯的函数就是在内核代码中挂住的地⽅ —— 它跟WCHAN 输出完全吻合（注意，实际上有更多的函数在调⽤栈上，例如内核scheduler()函数，它使进程休眠或者唤醒进程，但是这些函数没有显⽰出来，很可能是因为它们是等待条件的结果⽽不是原因）。
感谢它打印出了完整的内核态堆栈，我们可以从下⽽上的看⼀下函数调⽤，从⽽理解是怎么最终调⽤
到rpc_wait_bit_killable 的，这个函数结束了对调度器的调⽤并使进程进⼊睡眠模式。
底端的system_call_fastpath 是⼀个通⽤的内核调⽤处理函数，它为我们处理过的newfstatat 系统调⽤执⾏内核代码。然后继续向上，我们可以看到好⼏个NFS 函数。这是100%⽆可抵赖的证据，证明我们处在某些NFS 代码路径下（under NFS
codepath ）。我没有说在NFS 代码路径中（in NFS codepath ），当你继续向上看的时候，你会看到最上⾯的NFS 函数接着调⽤了某些RPC 函数（rpc_call_sync ）以便跟其它进程通信 —— 在这个例⼦中可能是[kworker/N:N ]、 [nfsiod ]、 [lockd ] 或者 [rpciod ]内核IO 线程。并且因为某些原因⼀直没有从这些线程收到应答（通常的怀疑点是⽹络连接丢失、数据包丢失或者仅仅是⽹络连通性问题）。2262 0xffffffffffffff9c 0x20cf6c8 0x7fff97c52710 0x100 0x100 0x676e776f645f616d 0x7fff97c52658 0x390e2da8ea
31
[root@oel6 ~]# grep 262 /usr/include/asm/unistd_64.h 2#define __NR_newfstatat            262
31
[root@oel6 ~]# cat /proc/27288/stack 2
[] rpc_wait_bit_killable+0x24/0x40 [sunrpc]3
[] __rpc_execute+0xf5/0x1d0 [sunrpc]4
[] rpc_execute+0x43/0x50 [sunrpc]5
linux下的sleep函数[] rpc_run_task+0x75/0x90 [sunrpc]6
[] rpc_call_sync+0x42/0x70 [sunrpc]7
[] nfs3_rpc_wrapper.clone.0+0x35/0x80 [nfs]8
[] nfs3_proc_getattr+0x47/0x90 [nfs]9
[] __nfs_revalidate_inode+0xcc/0x1f0 [nfs]10
[] nfs_revalidate_inode+0x36/0x60 [nfs]11
[] nfs_getattr+0x5f/0x110 [nfs]12
[] vfs_getattr+0x4e/0x8013
[] vfs_fstatat+0x70/0x9014
[] sys_newfstatat+0x24/0x5015
[] system_call_fastpath+0x16/0x1b 16[] 0xffffffffffffffff
17

版权声明：本站内容均来自互联网，仅供演示用，请勿用于商业和其他非法用途。如果侵犯了您的权益请与我们联系QQ:729038198，我们将在24小时内删除。