Linux内核输出的日志去哪里了?

系统 Linux
在内核中,有一个类似于c语言的输出函数,叫做printk,使用它,我们可以打印各种我们想要的信息,比如内核当前的运行状态,又或者是我们自己的调试日志等,非常方便。

[[426557]]

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

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

就这些,希望你喜欢。 

 

责任编辑:庞桂玉 来源: 良许Linux
相关推荐

2021-09-08 05:46:51

Linux内核日志

2017-10-12 10:06:23

Linux内存free命令

2011-10-14 10:27:04

OpenFlow

2022-11-27 11:00:15

2014-04-10 15:42:08

Linux系统内存

2021-07-29 20:29:36

Linux c 代码Java

2021-02-25 09:50:01

LinuxWindows内核

2014-07-09 13:48:08

2013-10-28 09:40:51

Android内核

2020-06-10 10:50:15

Linuxpstore内核

2010-05-20 09:09:07

Linux内核

2010-10-25 10:52:34

2021-11-17 10:25:28

loguru日志Python

2020-04-17 10:50:19

5G运营商网络

2018-10-29 13:46:02

2023-01-05 12:04:27

DEBUG信息打印

2013-11-05 09:58:39

Linux内核

2013-11-06 13:03:10

Linux内核

2013-11-12 11:01:46

Linux内核

2013-11-07 13:59:56

Linux内核
点赞
收藏

51CTO技术栈公众号