英文地址：

https://tanelpoder.com/2013/02/21/peeking-into-linux-kernel-land-using-proc-filesystem-for-quickndirty-troubleshooting/

https://tanelpoder.com/2013/02/21/peeking-into-linux-kernel-land-using-proc-filesystem-for-quickndirty-troubleshooting/

中文地址：初探Linux内核态——通过proc文件系统作快速问题定位

https://hualet.org/blog/2018/01/23

序言

I’m not going to use kernel debuggers or SystemTap scripts here, just plain old “cat /proc/PID/xyz” commands against some useful /proc filesystem entries.

这篇文章也不会涉及内核调试器或者SystemTap脚本之类的东西，完全是最最简单地在有用的proc文件系统节点上执行“cat /proc/PID/xyz”这样的命令。

问题重现Troubleshooting a “slow” process定位一个程序“运行缓慢”的问题

下面要举的这个例子是这样的：一个DBA反映说他们的find命令一直运行缓慢，半天都没有什么输出，他们想知道这是为什么。

听到这个问题的时候我就大概有直觉造成这个问题的原因，但是他们还是想知道怎么系统地追踪这类问题，并找到解决方案。刚好出问题的现场还在……

还好，系统是运行在OEL6上的，内核比较新，确切地说是2.6.39 UEK2。

首先，让我们看看find进程是否还在：

[root@oel6 ~]# ps -ef | grep findroot 27288 27245 4 11:57 pts/0 00:00:01 find . -type froot 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 27288top - 11:58:15 up 7 days, 3:38, 2 users, load average: 1.21, 0.65, 0.47Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombieCpu(s): 0.1%us, 0.1%sy, 0.0%ni, 99.8%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%stMem: 2026460k total, 1935780k used, 90680k free, 64416k buffersSwap: 4128764k total, 251004k used, 3877760k free, 662280k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND27288 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 27288Process 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 27288F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD0 D root 27288 27245 0 80 0 - 28070 rpc_wa 11:57 pts/0 00:00:01 find . -type fps -flp 8691F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD4 S root 8691 1 0 80 0 - 282524 ep_pol Apr21 ? 00:15:21 ./dn

The process is in state D (uninterruptible sleep) which is usually disk IO related (as the ps man pages also say).

进程此时正处于D状态，按照man手册的说法，这通常是因为磁盘IO导致的。

And the WCHAN (the function which caused this sleep/wait in this process) field is a bit truncated. I could use a ps option (read the man) to print it out a bit wider, but as this info comes from the proc filesystem anywa

而WCHAN字段（表示导致程序处于休眠/等待状态的函数调用）则有点儿被切掉了。

显然我可以翻一下ps的man手册，看看怎么把这个字段调宽一点好完整打印出来，不过既然我都知道了这个信息来自于proc文件系统，就没这个必要了。

[root@oel6 ~]# cat /proc/27288/wchanrpc_wait_bit_killable

额……这个进程居然在等待某些RPC调用。RPC调用通常意味着这个程序在跟其他进程通信（不管是本地还是远程）。

Hmm… this process is waiting for some RPC call.

RPC usually means that the process is talking to other processes (either in the local server or even remote servers).

But we still don’t know why.

总归，我们还是不知道为什么会卡住。

基础知识复习：

/proc/[pid]/stat

Status information about the process. This is used by ps(1）

cat /proc/27288/wchan

wchan %lu This is the "channel" in which the process is wait-

ing. It is the address of a system call

敲重点：

nwchan WCHAN address of the kernel function where the processis sleeping (use wchan if you want the kernelfunction name). Running tasks will display adash ('-') in this column.

到底是不是完全卡住了？

在我们揭开这篇文章最后的谜底之前，我们还是先搞清楚这个进程到底是不是完全卡住了。

其实，在新一点的Linux内核中，/proc/PID/status 这个文件可以告诉我们这点：

[root@oel6 ~]# cat /proc/27288/status Name: findState: D (disk sleep)Tgid: 27288Pid: 27288PPid: 27245TracerPid: 0Uid: 0 0 0 0Gid: 0 0 0 0FDSize: 256Groups: 0 1 2 3 4 6 10 VmPeak: 112628 kBVmSize: 112280 kBVmLck: 0 kBVmHWM: 1508 kBVmRSS: 1160 kBVmData: 260 kBVmStk: 136 kBVmExe: 224 kBVmLib: 2468 kBVmPTE: 88 kBVmSwap: 0 kBThreads: 1SigQ: 4/15831SigPnd: 0000000000040000ShdPnd: 0000000000000000SigBlk: 0000000000000000SigIgn: 0000000000000000SigCgt: 0000000180000000CapInh: 0000000000000000CapPrm: ffffffffffffffffCapEff: ffffffffffffffffCapBnd: ffffffffffffffffCpus_allowed: ffffffff,ffffffffCpus_allowed_list: 0-63Mems_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,00000001Mems_allowed_list: 0voluntary_ctxt_switches: 9950nonvoluntary_ctxt_switches: 17104

(主要看State字段和最后两行：voluntary_ctxt_switches和 nonvoluntary_ctxt_switches)

进程处于D——Disk Sleep（不可打断休眠状态），

voluntary_ctxt_switches 和 nonvoluntary_ctxt_switches的数量则能告诉我们这个进程被分给时间片的次数。

voluntary_ctxt_switches: 9950nonvoluntary_ctxt_switches: 17104voluntary_ctxt_switches表示自愿切换的次数，nonvoluntary_ctxt_switches表示强制切换的次数，pidstat -w 1

过几秒再看看这些数字有没有增加，如果没有增加，则说明这个进程是完全卡死的，

目前我在追踪的例子就是这个情况，反之，则说明进程不是完全卡住的状态。

the process is in the state D – Disk Sleep (uninterruptible sleep).

And look into the number of voluntary_ctxt_switches and nonvoluntary_ctxt_switches – this tells you how many times the process was taken off CPU (or put back).

顺便提一下，还有两种办法也可以获取进程的上下文切换数量（第二种在老旧的内核上也能工作）：

[root@oel6 ~]# cat /proc/27288/schedfind (27288, #threads: 1)--------------------------------------------------------- 0avg_atom : 0.041379avg_per_cpu : 3.588077nr_switches : 27054nr_voluntary_switches : 9950nr_involuntary_switches : 17104se.load.weight : 1024policy : 0prio : 120clock-delta : 72

我们要的就是输出中的nr_switches字段（等于 nr_voluntary_switches + nr_involuntary_switches），值是27054，跟/proc/PID/schedstat 中的第三个字段是一致的：

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

等一段时间，也是一样的结果，数量没有增长……

Here you need to look into the nr_switches number (which equals nr_voluntary_switches + nr_involuntary_switches).

The total nr_switches is 27054 in the above output and this is also what the 3rd field in /proc/PID/schedstat shows:

[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[root@VM-0-10-centos 1]# cat stack[ffffffff8f49c2be] ep_poll+0x23e/0x360[ffffffff8f49d79d] SyS_epoll_wait+0xed/0x120[ffffffff8f992ed2] system_call_fastpath+0x25/0x2a[ffffffffffffffff] 0xffffffffffffffff

可以看到最顶部的函数就是我们现在卡在的地方，正是上面WCHAN字段显示的内容：rpc_wait_bit_killable。

（注意：实际上不一定最顶部的函数就是我们想要的，因为内核可能也执行了 schedule 之类的函数来让程序进入休眠或者运行。这里没有显示可能是因为卡主是因为其他调用卡主了才进入睡眠状态，而不是相反的逻辑）。

The top function is where in kernel code we are stuck right now – which is exactly what the WCHAN output showed us (note that actually there are some more functions on top of it, such as the kernel schedule() function which puts processes to sleep or on CPU as needed, but these are not shown here probably because they’re a result of this wait condition itself, not the cause).

多亏了这个神器，我们现在可以从头到尾推导出程序卡主的整个过程和造成最终 rpc_wait_bit_killable 函数卡主的原因了：

thanks to the full kernel-land stack of this task we can read it from bottom up to understand how did we end up calling this rpc_wait_bit_killable function in the top, which ended up calling the scheduler and put us into sleep mode.

最底部的 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 ; doneUID PID PPID C STIME TTY TIME CMDroot 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]

通过开启内核的tracing肯定可以确切找到是内核的哪两个线程之间再通信，

不过限于文章篇幅，这里就不展开了，毕竟这只是一个实用（且简单）的问题追踪定位练习。

基础知识复习：

/proc/[pid]/syscall显示当前进程正在执行的系统调用。举例如下：

# cat /proc/2948/syscall7 0x7f4a452cbe70 0xb 0x1388 0xffffffffffdff000 0x7f4a4274a750 0x0 0x7ffd1a8033f0 0x7f4a41ff2c1d

第一个值是系统调用号（7代表poll），

后面跟着6个系统调用的参数值（位于寄存器中），

最后两个值依次是堆栈指针和指令计数器的值

。如果当前进程虽然阻塞，但阻塞函数并不是系统调用，则系统调用号的值为-1，后面只有堆栈指针和指令计数器的值。

基础知识复习：stack：proc/[pid]/stack显示当前进程的内核调用栈信息# cat /proc/2948/stack[ffffffff80168375] poll_schedule_timeout+0x45/0x60[ffffffff8016994d] do_sys_poll+0x49d/0x550[ffffffff80169abd] SyS_poll+0x5d/0xf0[ffffffff804c16e7] system_call_fastpath+0x16/0x1b[00007f4a41ff2c1d] 0x7f4a41ff2c1d[ffffffffffffffff] 0xffffffffffffffff

什么内核栈，内核也有函数调用栈

怎么理解linux内核栈？

https://www.zhihu.com/question/57013926

. C语言书里面讲的堆、栈大部分都是用户态的概念，用户态的堆、栈对应用户进程虚拟地址空间里的一个区域，栈向下增长，堆用malloc分配，向上增长

每个进程都有一个单独的内核栈。

每个进程运行时都持有上下文，用于保证并行性。为了保证内核和用户态隔离，陷入内核不影响用户态，所以使用了不同的栈。内核栈只是对内核态上下文中的栈的称谓。

什么是弱符号。

#includestdio.hint weak; // 未初始化全局变量，弱符号int strong = 1024; // 已初始化全局变量，强符号__attribute__((weak)) int weak1 = 2222; // 使用标识修饰的弱符号int main(void){ printf("编程珠玑\n"); return 0;}考察：说出下面输出结果double num;void change(){ num = 1023;}//main.c#includestdio.hvoid change();int num = 1024;int main(void){printf("before:num is %d\n", num);change();printf("after:num is %d\n", num);return 0;}./a.outbefore:num is 1024after:num is 0//不是after:num is 1023

为什么修改后是0？原因在于double类型的数据存储与int类型数据存储格式不一样（参考《对浮点数的一些理解》），且它们占用空间长度都不一样，在本文例子中，double占用8字节，而int占用4字节。

局部静态遍历：不分配在栈上，和全局遍历区别，限定在指定函数内

二次链接呀？？？

看文章怎么看不出别人说什么：浮躁了。

task switching activity情况统计(-w)

也可以用 pidstat -w 命令查看进程切换的每秒统计值：

进程自愿切换(Voluntary)和强制切换(Involuntary)的次数被统计在 /proc/pid/status 中，其中voluntary_ctxt_switches表示自愿切换的次数，

nonvoluntary_ctxt_switches表示强制切换的次数

两者都是自进程启动以来的累计值。

cswch/s Total number of voluntary context switches the task made per second. A voluntary context switch occurs when a task blocks because it requires a resource that is unavailable. nvcswch/s Total number of non voluntary context switches the task made per second. A involuntary context switch takes place when a task executes for the duration of its time slice and then is forced to relinquish the processor.cpu使用情况统计(-u)

使用-u选项，pidstat将显示各活动进程的cpu使用统计，执行”pidstat -u”与单独执行”pidstat”的效果一样。

间隔 5 秒后输出一组数据pidstat -u 5 1复制代码

可以明显看出时stress命令导致的 cpu 负载过高。

内存使用情况统计(-r)

使用-r选项，pidstat将显示各活动进程的内存使用统计：

使用-d选项，我们可以查看进程IO的统计信息：

使用pidstat进行问题定位时，以下命令常被用到：pidstat -u 1pidstat -r 1pidstat -d 1以上命令以1秒为信息采集周期，分别获取cpu、内存和磁盘IO的统计信息。复制代码使用pidstat查看某个进程的情况

查看nginx master进程的2s采样输出3次的内存使用情况

#nginx pid=32pidstat -r 2 -p 32 3复制代码minflt/s: 每秒次缺页错误次数(minor page faults)，次缺页错误次数意即虚拟内存地址映射成物理内存地址产生的page fault次数[没有分配物理内存]majflt/s: 每秒主缺页错误次数(major page faults)，当虚拟内存地址映射成物理内存地址时，相应的page在swap中，这样的page fault为major page fault，一般在内存使用紧张时产生【数据在磁盘上，不在内存中】VSZ: 该进程使用的虚拟内存(以kB为单位)RSS: 该进程使用的物理内存(以kB为单位)%MEM: 该进程使用内存的百分比Command: 拉起进程对应的命令 注明：本文章来源于互联网，如侵权请联系客服删除！