内核日志及printk结构浅析

1、问题的引出：

做DPDK项目时，调试rte_kni.ko时，发现printk并不会向我们想想的那样把log信息显示在我们的终端上。有人总结了三个原因：

原因1：printk()有一个控制日志级别的字段，如果该字段的日记级别高于console默认的日志级别那么才会打印出来（数值越小日志级别越高，分为从0-7共计8个日志级别）。有一种简单的改变当前终端的日志级别的方法，echo 8 > /sys/kernel/printk。理论上这样printk就能输出到终端了。但是我的没有。

原因2：syslogd守护进程的规则有问题，/etc/syslog.conf中定义了一些列规则，其中就包含数内核消息的处理规则，fedora中的syslogd守护进程叫做rsyslogd，相应它的规则配置文件叫rsyslog.conf，其中有一行”#kern.*                /dev/console“它的意思是把所有日志级别的内核log都输出到/dev/console即我们的终端。我们只需要把该行的'#'去掉，重启，理论上那么内核log (printk()输出也是内核log）就会输出到终端了。但是我的还是不能。

原因3：系统中同时有klogd和syslogd守护进程那么不管日志级别是什么都不能输出到终端。

如果不能在终端上看到printk的输出，那么可以通过查看/var/log/messages文件，或运行dmesg命令查看，或查看/proc/kmsg文件获得信息，或是通过ctrl+alt+f2~f6进入系统文本模式装载模块，这样也可以看到prink()输出的信息，当然这里就准确对应原因1中所讲的规则。

最后说一下syslogd、直接通过/proc/kmsg、和dmesg读取printk输出缓冲区的区别：

syslogd：读取了缓冲区中的数据，不会删除缓冲区中的数据。

直接读取/proc/kmsg：读取了缓冲区中的数据后，将缓冲区中的数据删除（klogd默认就是采用这种方法）。

dmesg：在不刷新缓冲区的情况下获得缓冲区的内容，并将内容返回给stdout。

本文里的知识来至LDD3，和一位网友的博客（http://www.cnitblog.com/textbox/archive/2009/10/13/61785.html）。

1、printk概述:

对于做Linux内核开发的人来说，printk实在是再熟悉不过了。内核启动时显示的各种信息大部分都是通过她来实现的，在做内核驱动调试的时候大部分 时候使用她就足矣。她之所以用得如此广泛，一个是由于她使用方便，还有一个重要的原因是她的健壮性。它使用范围很广，几乎是内核的任何地方都能调用它。你既可以在中断上下文、进程上下中调用她，也可以在任何持有锁时调用她，更可以在SMP系统中调用她，且调用时连锁都不必使用。这样好的适应性来源于她的设计，一个由三个指针控制的简单“ring buffer”。

注意上面说到的是：“几乎”在内核的任何地方都可以使用。那什么地方使用会有“问题”？那就是在系统启动过程的早期，终端初始化之前的某些地方虽然可以使用，但是在终端和控制台被初始化之前所有信息都被缓存在printk的简单的ring buffer（环形缓冲区）中，直到终端和控制台被初始化之后，所有缓存信息都被一并输出。

如果你要调试的是启动过程最开始的部分（如setup_arch()），可以依靠此时能够工作的硬件设备（如串口）与外界通信，使用printk()的变体early_printk()函数。她在启动过程初期就具有在终端上打印的能力，功能与prink()类似，区别在于：

（1）函数名

（2）能够更早地工作（输出信息）

（3）她有自己的小缓存（一般为512B）

（4）一次性输出到硬件设备，不再以ring buffer的形式保留信息。

但该函数在一些构架上无法实现，所以这种办法缺少可移植性。（大多数构架都可以，包括x86和arm）。

所以，除非要在启动初期在终端上输出，否则我们认为printk()在任何情况下都能工作。这点从内核的启动代码中就可以看出，在已进入start_kernel不久就通过printk打印内核版本信息了。

2、printk的使用:

printk()和C库中的printf()在使用上最主要的区别就是 printk()指定了日志级别。

2.1：日志等级

内核根据日志级别来判断是否在终端（console）上打印消息：内核把级别比某个特定值低的所有消息显示在终端（console）上。但是所有信息都会记录在printk的“ring buffer”中。

printk有8个loglevel,定义在中：

#define KERN_EMERG "<0>" /* 系统不可使用 */

#define KERN_ALERT "<1>" /* 需要立即采取行动 */

#define KERN_CRIT "<2>" /* 严重情况 */

#define KERN_ERR "<3>" /* 错误情况 */

#define KERN_WARNING "<4>" /* 警告情况 */

#define KERN_NOTICE "<5>" /* 正常情况, 但是值得注意 */

#define KERN_INFO "<6>" /* 信息型消息 */

#define KERN_DEBUG "<7>" /* 调试级别的信息 */

/* 使用默认内核日志级别 */

#define KERN_DEFAULT ""

/*

* 标注为一个“连续”的日志打印输出行(只能用于一个

* 没有用  封闭的行之后). 只能用于启动初期的 core/arch 代码

* (否则续行是非SMP的安全).

*/

#define KERN_CONT ""

如果使用时没有指定日志等级，内核会选用DEFAULT_MESSAGE_LOGLEVEL，这个定义位于kernel/printk.c：

/* printk's without a loglevel use this.. */

#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL

可以看出，这个等级是可以在内核配置时指定,这种机制是从2.6.39开始有的，如果你不去特别配置，那么默认为<4>,也就是KERN_WARNING。

内核将最重要的记录等级 KERN_EMERG定为“”，将无关紧要的调试记录等级“KERN_DEBUG”定为“<7>”。

内核用这些宏指定日志等级和当前终端的记录等级console_loglevel来决定是不是向终端上打印，使用示例如下：

printk(KERN_EMERG "log_level:%s ", KERN_EMERG);

当编译预处理完成之后，前例中的代码实际被编译成成如下格式：

printk( "<0>" "log_level:%s ", KERN_EMERG);

给一个printk()什么日志等级完全取决于你。那些正式、且需要保持的消息应该根据信息的性质给出相应的日志等级。但那些为了解决一个问题临时加得到处都是的调试信息可以有两种做法：

一种选择是保持终端的默认记录等级不变，给所有调试信息KERN CRIT或更低的等级以保证信息一定会被输出。

另一种方法则相反，给所有调试信息KERN DEBUG等级，而调整终端的默认记录等级为7，也可以输出所有调试信息。

两种方法各有利弊。

这里说到了调整内核的默认的日志级别，在我3年半前的学习笔记《 Linux设备驱动程序学习（2）-调试技术 》中有介绍，可以通过 /proc/sys/kernel/printk来改变，或者C程序调用syslog系统调用来实现。但是现在的glibc的函数接口改了，由于 syslog 这个词使用过于广泛，这个函数的名称被修改成 klogctl，所以原来博文中的代码无法使用了，以下是新版的 console_loglevel代码：

#include 

#include 

#include 

#include 

//#define __LIBRARY__ /* _syscall3 and friends are only available through this */

//#include 

/* define the system call, to override the library function */

//_syscall3(int, syslog, int, type, char *, bufp, int, len);

int main(int argc, char **argv)

{

int level;

if (argc == 2) {

level = atoi(argv[1]); /* the chosen console */

} else {

fprintf(stderr, "%s: need a single arg ", argv[0]);

exit(1);

}

if (klogctl(8, NULL, level) < 0) {

fprintf(stderr, "%s: syslog(setlevel): %s ",

argv[0], strerror(errno));

exit(1);

}

exit(0);

}

2.2：相关辅助宏

如果确定printk所需要的日志等级，每次都要在其中添加以上宏，似乎有点麻烦了。所以内核黑客们定义了一些宏来方便printk的使用，这些宏在内核代码中也是随处可见：

#ifndef pr_fmt

#define pr_fmt(fmt) fmt

#endif

#define pr_emerg(fmt, ...) 

printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)

#define pr_alert(fmt, ...) 

printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)

#define pr_crit(fmt, ...) 

printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)

#define pr_err(fmt, ...) 

printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)

#define pr_warning(fmt, ...) 

printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)

#define pr_warn pr_warning

#define pr_notice(fmt, ...) 

printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)

#define pr_info(fmt, ...) 

printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)

#define pr_cont(fmt, ...) 

printk(KERN_CONT fmt, ##__VA_ARGS__)

/* 除非定义了DEBUG ，否则pr_devel()不产生任何代码 */

#ifdef DEBUG

#define pr_devel(fmt, ...) 

printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#else

#define pr_devel(fmt, ...) 

no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#endif

/* 如果你在写一个驱动，请使用dev_dbg */

#if defined(DEBUG)

#define pr_debug(fmt, ...) 

printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#elif defined(CONFIG_DYNAMIC_DEBUG)

/* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */

#define pr_debug(fmt, ...) 

dynamic_pr_debug(fmt, ##__VA_ARGS__)

#else

#define pr_debug(fmt, ...) 

no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

#endif

从上面的代码大家应该就可以知道这些宏的使用了。值得注意的是：pr_devel和 pr_debug这些宏只有在定义了DEBUG之后才会产生实际的 printk代码，这样方便了内核开发：在代码中使用这些宏，当调试结束，只要简单地#undef DEBUG就可以消除这些调试使用的代码，无需真正地 去删除调试输出代码。

2.3：输出速率控制

在调试的时候，有时某些部分可能printk会产生大量输出, 导致系统无法正常工作，并可能使系统日志ring buffer溢出（旧的信息被快速覆盖）。特别地，当使用一个慢速控制台设备(如串口), 过量输出也能拖慢系统。这样反而难于发现系统出问题的地方。所以你应当非常注意：正常操作时不应当打印任何东西，打印的输出应当是指示需要注意的异常，并 小心不要做过头。

在某些情况下, 最好的做法是设置一个标志变量表示：已经打印过这个了，以后不再打印任何这个信息。而对于打印速率的控制内核已经提供了一个现成的宏:

#define printk_ratelimit() __printk_ratelimit(__func__)

这个函数应当在你认为打印一个可能会出现大量重复的消息之前调用，如果这个函数返回非零值, 继续打印你的消息, 否则跳过它。典型的调用如这样:

if (printk_ratelimit())

printk(KERN_NOTICE "The printer is still on fire ");

printk_ratelimit通过跟踪发向控制台的消息的数量和时间来工作。当输出超过一个限度, printk_ratelimit 开始返回 0 使消息被丢弃。我们可以通过修改 ：

/proc/sys/kern/printk_ratelimit( 可以看作一个监测周期，在这个周期内只能发出下面的控制量的信息) 

/proc/sys/kernel/printk_ratelimit_burst(以上周期内的最大消息数，如果超过了printk_ratelimit()返回0)

来控制消息的输出.

在中还定义了其他的宏，比如printk_ratelimited(fmt, ...)等，有兴趣的朋友就去文件中看看便知，很好理解的。

2.4：最后特别提醒：

1、虽然printk很健壮，但是看了源码你就知道，这个函数的效率很低：做字符拷贝时一次只拷贝一个字节，且去调用console输出可能还产生中断。所以如果你的驱动在功能调试完成以后做性能测试或者发布的时候千万记得尽量减少printk输出，做到仅在出错时输出少量信息。否则往console输出无用信息影响性能。我刚开始学驱动的时候就犯过这样的白痴错误，在测试CAN驱动性能的时候居然printk出信息来核对，结果直接宕机。

2、printk的临时缓存printk_buf只有1K，所有一次printk函数只能记录<1K的信息到log buffer，并且printk使用的“ring buffer”

3、printk的内核实现

对于Linux的printk内核日志，常常被称为kernel ring buffer，这是由于printk的缓存实现就是使用了一个简单的ring buffer（环形缓冲区）。但是这里需要注意的是，不要和内核trace系统ring buffer混淆，虽然他们都是为了跟踪调试，但是trace系统的ring buffer实现更加完善复杂，而printk使用的ring buffer则非常简单，其实就定义了一个字符数组：

static char __log_buf[__LOG_BUF_LEN];

并使用了一套指针来管理：

/*

* 在指向log_buf时并没有用log_buf_len做限制 - 所以他们

* 在作为下标使用前必须用掩码处理（去除CONFIG_LOG_BUF_SHIFT以上的高位）

*/

static unsigned log_start; /* log_buf中的索引: 指向由syslog()读取的下一个字符 */

static unsigned con_start; /* log_buf中的索引: 指向发送到console的下一个字符 */

static unsigned log_end; /* log_buf中的索引:最近写入的字符地址 + 1 */

具体的实现CU中已经有一位博友写过了，我这里就不再啰嗦了，我转载备份了一下：《printk实现分析》

4、用户空间访问内核日志

用户空间访问和控制内核日志有两个接口：

（1）通过glibc的klogctl函数接口调用内核的syslog系统调用

（2）通过fs/proc/kmsg.c内核模块中导出的procfs接口：/proc/kmsg文件。

他们其实最终都调用了/kernel/printk.c中的do_syslog函数，实现对__log_buf的访问及相关变量的修改。

但值得注意的是：从/proc/kmsg中获取数据，那么__log_buf中被读取过的数据就不再保留（也就是会修改log_start指针）, 然而 syslog 系统调用返回日志数据并保留数据给其他进程。读取/proc文件是 klogd的默认做法。dmesg命令可用来查看缓存的内容并保留它，其实它是将__log_buf中的所有内容返回给stdout，并不管它是否已经被读取过。

这里我还是推荐大家 RTFSC – Read The Fucking Source Code，自己看这些代码比什么都强，我这里就只引个路。

在用户空间有专门用于记录系统日志的程序，统称为“syslog守护进程”。早期及现在的大部分嵌入式系统使用的是klogd+syslogd组合，现在 大多数发行版都使用rsyslogd或者syslogd-ng了。这些用户空间的程序我这里就不分析了，我不擅长，运维的可能比较清楚。我只知道一下他们 大致的调用关系就好。

这里我用一张图来总结一下内核printk和日志系统的总体结构：