性能文章>精致全景图 | linux内核输出的日志去哪里了>

精致全景图 | linux内核输出的日志去哪里了原创

3年前
8983314

 

因为图片比较大,微信公众号上压缩的比较厉害,所以很多细节都看不清了,我单独传了一份到github上,想要原版图片的,可以点击下方的阅读原文,或者直接使用下面的链接,来访问github:

 

https://github.com/wangyuntao/linux-kernel-illustrated

 

另外,精致全景图系列文章,以及之后的linux内核分析文章,我都会整理到这个github仓库里,欢迎大家star收藏。

 


 

熟悉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级别,甚至更高级别的日志需要我们关注,通过这些日志,我们可以及时的发现系统的异常情况,必要时可以人工介入进行干预。

 

总之,对系统了解的越深,内核日志对我们的帮助就越大。

 

就这些,希望你喜欢。

点赞收藏
分类:标签:
KINGYT

公众号 卯时卯刻,也可搜 ytcode

请先登录,查看3条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

从 Linux 内核角度探秘 JDK MappedByteBuffer

从 Linux 内核角度探秘 JDK MappedByteBuffer

14
3