熟悉linux内核,或者看过linux内核源码的同学就会知道,在内核中,有一个类似于c语言的输出函数,叫做printk,使用它,我们可以打印各种我们想要的信息,比如内核当前的运行状态,又或者是我们自己的调试日志等,非常方便。
那当我们调用printk函数后,这些输出的信息到哪里去了呢?我们又如何在linux下的用户态,查看这些信息呢?
为了解答这些疑问,我画了一张printk全景图,放在了文章开始的部分,这张图既包含了printk在内核态的实现,又包含了其输出的信息在用户态如何查看。
我们可以根据这张图,来理解printk的整体架构。
在内核编码时,如果想要输出一些信息,通常并不会直接使用printk,而是会使用其衍生函数,比如 pr_err / pr_info / pr_debug 等,这些衍生函数附带了日志级别、所属模块等其他信息,比较友好,但其最终还是调用了printk。
printk函数会将每次输出的日志,放到内核为其专门分配的名为ring buffer的一个槽位里。
ring buffer其实就是一个用数组实现的环形队列,不过既然是环形队列,就会有一个问题,即当ring buffer满了的时候,下一条新的日志,会覆盖最开始的旧的日志。
ring buffer的大小,可以通过内核参数来修改。
printk在将日志放到ring buffer后,会再调用系统console的相关方法,将还未输出到系统控制台的消息,继续输出到控制台,这个后面会详细说,这里就暂不赘述。
以上就是printk在内核态的实现。
在用户态,我们有几个方式,可以查看printk输出的内核日志,比如使用dmesg命令,cat /proc/kmsg文件,或者是使用klogctl函数等,这些方式分别对应于全景图中用户态的橙色、绿色、和蓝色的部分。
dmesg命令,在默认情况下,是通过读取/dev/kmsg文件,来实现查看内核日志的。
当该命令运行时,dmesg会先调用open函数,打开/dev/kmsg文件,该打开操作在内核中的逻辑,会为dmesg分配一个file实例,在这个file实例里,会有一个seq变量,该变量记录着下一条要读取的内核日志在ring buffer中的位置。
刚打开/dev/kmsg文件时,这个seq指向的就是ring buffer中最开始的那条日志。
之后,dmesg会以打开的/dev/kmsg文件为媒介,不断的调用read函数,从内核中读取日志消息,每读取出一条,seq的值都会加一,即指向下一条日志的位置,依次往复,直到所有的内核日志读取完毕,dmesg退出。
以上就是dmesg的主体实现。
第二种查看内核日志的方式,是通过 cat /proc/kmsg 命令。
该命令和dmesg命令的实现机制基本类似,都是通过读文件,只不过cat读取的是/proc/kmsg文件,而dmesg读取的是/dev/kmsg文件。
读取这两个文件最大的区别是,/dev/kmsg文件每次打开时,内核都会为其分配一个单独的seq变量,而/proc/kmsg文件每次打开时,用的都是同一个全局的静态seq变量,叫做syslog_seq。
syslog_seq指向的也是下一条要读取的内核日志在ring buffer中的位置,但因为它是一个全局的静态变量,当有多个进程要读取/proc/kmsg文件时,就会有一个比较严重的问题,即内核日志会被这几个进程随机抢占读取,也就是说,每个进程读到的都是整个内核日志的一部分,是不完整的,这也是dmesg命令默认不使用/proc/kmsg文件的原因。
第三种查看内核日志的方式,是通过klogctl函数。
该函数是glibc对syslog系统调用的一个简单封装,其具体使用方式,可以参考全景图中用户态的蓝色部分。
klogctl函数可以指定很多命令,在上图的示例中,我们使用的是SYSLOG_ACTION_READ命令,以此来模拟 cat /proc/kmsg 行为。
其实在内核层面,cat /proc/kmsg命令,使用的就是klogctl对应的syslog系统调用的SYSLOG_ACTION_READ命令的处理逻辑,所以示例中的klogctl函数相关代码,和 cat /proc/kmsg 命令其实是等价的。
也就是说,klogctl函数在内核里使用的也是syslog_seq变量,它也有和/proc/kmsg文件同样的问题。
其实还有一种方式可以查看内核日志,就是通过系统控制台。
但这种方式和前面讲的三种方式都不一样,它是完全被动的,是内核在调用printk函数,将日志信息放到ring buffer后,再去通知系统控制台,告知其可以输出这些日志。
系统控制台也是通过一个console_seq变量,记录下一条要输出内核日志的所在位置。
这里说的系统控制台,是指我们在开机的时候,黑色屏幕输出的那些内容,但当我们进入图形化界面后,我们就看不到系统控制台的输出了,除非我们再用 ctrl + alt + f1/f2/f3 等方式,切换成系统控制台。
系统控制台输出的内容,是被日志级别过滤过的,内核默认的日志过滤级别是7,即debug级别以上的日志,比如info / err 等,这些都会输出,但debug级别不会输出。
该日志过滤级别,可以通过很多方式改变,比如说,可以通过内核参数 loglevel,所以,如果发现系统控制台没有输出想要的日志信息,先看下其是否被过滤掉了。
以上就是printk生态的完整实现。
了解printk函数的实现,对于内核开发者或研究者来说,意义非常大,但对于普通的应用开发人员来说,又有什么帮助呢?
其实,随着技术的深入,我们不应该再只关心应用层面的行为,而且还要关心系统层面的行为,这样我们才能更好的去定位问题,更好的去保证我们应用的健康运行。
比如,当我们的应用需要内存时,会向操作系统申请,操作系统此时给我们的,其实是虚拟内存,只有当我们的进程真正的在使用这些内存时,比如读/写,操作系统才会为其分配物理内存。
但假设此时物理内存没有了,那操作系统会怎么办?
对于linux内核来说,它会选择一个使用内存最多的进程,然后将其kill掉,以此来释放内存,保证后续的内存分配操作能够成功,这个我在之前文章 为什么我的进程被kill掉了 有详细讲过。
对于内核的这种行为,我们就应该多加关注,而关注的方式,就是查看内核日志。
比如,linux内核在kill掉进程时,会用pr_err记录一行日志:
如果我们发现一个进程跑着跑着就没有了,就可以通过dmesg命令,查看是否有这个日志,如果有,说明该进程因为系统内存不足,被操作系统kill掉了。
类似的,内核里还有很多error级别,甚至更高级别的日志需要我们关注,通过这些日志,我们可以及时的发现系统的异常情况,必要时可以人工介入进行干预。
总之,对系统了解的越深,内核日志对我们的帮助就越大。
就这些,希望你喜欢。