一、printk概述
对于做Linux内核开发的人来说,printk实在是再熟悉不过了。内核启动时显示的各种信息大部分都是通过她来实现的,在做内核驱动调试的时候大部分时候使用她就足矣。她之所以用得如此广泛,一个是由于她使用方便,还有一个重要的原因是她的健壮性。它使用范围很广,几乎是内核的任何地方都能调用它。你既可以在中断上下文、进程上下中调用她,也可以在任何持有锁时调用她,更可以在SMP系统中调用她,且调用时连锁都不必使用。这样好的适应性来源于她的设计,一个由三个指针控制的简单“ringbuffer”。
注意上面说到的是:“几乎”在内核的任何地方都可以使用。那什么地方使用会有“问题”?那就是在系统启动过程的早期,终端初始化之前的某些地方虽然可以使用,但是在终端和控制台被初始化之前所有信息都被缓存在printk的简单的ringbuffer(环形缓冲区)中,直到终端和控制台被初始化之后,所有缓存信息都被一并输出。
如果你要调试的是启动过程最开始的部分(如setup_arch()),可以依靠此时能够工作的硬件设备(如串口)与外界通信,使用printk()的变体early_printk()函数。她在启动过程初期就具有在终端上打印的能力,功能与prink()类似,区别在于:
(1)函数名
(2)能够更早地工作(输出信息)
(3)她有自己的小缓存(一般为512B)
(4)一次性输出到硬件设备,不再以ring buffer的形式保留信息。
但该函数在一些构架上无法实现,所以这种办法缺少可移植性。(大多数构架都可以,包括x86和arm)。
所以,除非要在启动初期在终端上输出,否则我们认为printk()在任何情况下都能工作。这点从内核的启动代码中就可以看出,在已进入start_kernel不久就通过printk打印内核版本信息了: printk(KERN_NOTICE"%s", linux_banner);。
二、printk的使用
printk()和C库中的printf()在使用上最主要的区别就是 printk()指定了日志级别。
(1)日志等级
内核根据日志级别来判断是否在终端(console)上打印消息:内核把级别比某个特定值低的所有消息显示在终端(console)上。但是所有信息都会记录在printk的“ringbuffer”中。
printk有8个loglevel,定义在<<ahref="http://biancheng.dnbcw.info/linux/" style="color: rgb(0, 102,204); text-decoration: none;">linux/kernel.h>中:
- #defineKERN_EMERG "<0>"
- #defineKERN_ALERT "<1>"
- #defineKERN_CRIT "<2>"
- #defineKERN_ERR "<3>"
- #defineKERN_WARNING "<4>"
- #defineKERN_NOTICE "<5>"
- #defineKERN_INFO "<6>"
- #defineKERN_DEBUG "<7>"
- #defineKERN_DEFAULT ""
- #defineKERN_CONT ""
如果使用时没有指定日志等级,内核会选用DEFAULT_MESSAGE_LOGLEVEL,这个定义位于kernel/printk.c:
- #defineDEFAULT_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\n", KERN_EMERG);
当编译预处理完成之后,前例中的代码实际被编译成成如下格式:
- printk("<0>" "log_level:%s\n", KERN_EMERG);
给一个printk()什么日志等级完全取决于你。那些正式、且需要保持的消息应该根据信息的性质给出相应的日志等级。但那些为了解决一个问题临时加得到处都是的调试信息可以有两种做法:
一种选择是保持终端的默认记录等级不变,给所有调试信息KERN CRIT或更低的等级以保证信息一定会被输出。
另一种方法则相反,给所有调试信息KERNDEBUG等级,而调整终端的默认记录等级为7,也可以输出所有调试信息。
两种方法各有利弊。
(2)相关辅助宏
如果确定printk所需要的日志等级,每次都要在其中添加以上宏,似乎有点麻烦了。所以内核黑客们定义了一些宏来方便printk的使用,这些宏在内核代码中也是随处可见:
- #ifndefpr_fmt
- #definepr_fmt(fmt) fmt
- #endif
- #definepr_emerg(fmt, ...) \
- printk(KERN_EMERGpr_fmt(fmt), ##__VA_ARGS__)
- #definepr_alert(fmt, ...) \
- printk(KERN_ALERTpr_fmt(fmt), ##__VA_ARGS__)
- #definepr_crit(fmt, ...) \
- printk(KERN_CRITpr_fmt(fmt), ##__VA_ARGS__)
- #definepr_err(fmt, ...) \
- printk(KERN_ERRpr_fmt(fmt), ##__VA_ARGS__)
- #definepr_warning(fmt, ...) \
- printk(KERN_WARNINGpr_fmt(fmt), ##__VA_ARGS__)
- #definepr_warn pr_warning
- #definepr_notice(fmt, ...) \
- printk(KERN_NOTICEpr_fmt(fmt), ##__VA_ARGS__)
- #definepr_info(fmt, ...) \
- printk(KERN_INFOpr_fmt(fmt), ##__VA_ARGS__)
- #definepr_cont(fmt, ...) \
- printk(KERN_CONTfmt, ##__VA_ARGS__)
- #ifdefDEBUG
- #definepr_devel(fmt, ...) \
- printk(KERN_DEBUGpr_fmt(fmt), ##__VA_ARGS__)
- #else
- #definepr_devel(fmt, ...) \
- no_printk(KERN_DEBUGpr_fmt(fmt), ##__VA_ARGS__)
- #endif
- #ifdefined(DEBUG)
- #definepr_debug(fmt, ...) \
- printk(KERN_DEBUGpr_fmt(fmt), ##__VA_ARGS__)
- #elifdefined(CONFIG_DYNAMIC_DEBUG)
- #definepr_debug(fmt, ...) \
- dynamic_pr_debug(fmt,##__VA_ARGS__)
- #else
- #definepr_debug(fmt, ...) \
- no_printk(KERN_DEBUGpr_fmt(fmt), ##__VA_ARGS__)
- #endif
从上面的代码大家应该就可以知道这些宏的使用了。值得注意的是:pr_devel和 pr_debug这些宏只有在定义了DEBUG之后才会产生实际的printk代码,这样方便了内核开发:在代码中使用这些宏,当调试结束,只要简单地#undef DEBUG就可以消除这些调试使用的代码,无需真正地去删除调试输出代码。
(3)输出速率控制
在调试的时候,有时某些部分可能printk会产生大量输出,导致系统无法正常工作,并可能使系统日志ring buffer溢出(旧的信息被快速覆盖)。特别地,当使用一个慢速控制台设备(如串口),过量输出也能拖慢系统。这样反而难于发现系统出问题的地方。所以你应当非常注意:正常操作时不应当打印任何东西,打印的输出应当是指示需要注意的异常,并小心不要做过头。
在某些情况下,最好的做法是设置一个标志变量表示:已经打印过这个了,以后不再打印任何这个信息。而对于打印速率的控制内核已经提供了一个现成的宏:
- #defineprintk_ratelimit() __printk_ratelimit(__func__)
这个函数应当在你认为打印一个可能会出现大量重复的消息之前调用,如果这个函数返回非零值,继续打印你的消息, 否则跳过它。典型的调用如这样:
- if(printk_ratelimit())
- printk(KERN_NOTICE"The printer is still on fire\n");
printk_ratelimit通过跟踪发向控制台的消息的数量和时间来工作。当输出超过一个限度,printk_ratelimit 开始返回 0 使消息被丢弃。我们可以通过修改 :
- /proc/sys/kern/printk_ratelimit(可以看作一个监测周期,在这个周期内只能发出下面的控制量的信息)
- /proc/sys/kernel/printk_ratelimit_burst(以上周期内的最大消息数,如果超过了printk_ratelimit()返回0)
来控制消息的输出.
在中还定义了其他的宏,比如printk_ratelimited(fmt,...)等,有兴趣的朋友就去文件中看看便知,很好理解的。
(4)最后特别提醒:
1、虽然printk很健壮,但是看了源码你就知道,这个函数的效率很低:做字符拷贝时一次只拷贝一个字节,且去调用console输出可能还产生中断。所以如果你的驱动在功能调试完成以后做性能测试或者发布的时候千万记得尽量减少printk输出,做到仅在出错时输出少量信息。否则往console输出无用信息影响性能。我刚开始学驱动的时候就犯过这样的白痴错误,在测试CAN驱动性能的时候居然printk出信息来核对,结果直接宕机。
2、printk的临时缓存printk_buf只有1K,所有一次printk函数只能记录<1K的信息到logbuffer,并且printk使用的“ring buffer”
三、printk的内核实现
对于Linux的printk内核日志,常常被称为kernel ringbuffer,这是由于printk的缓存实现就是使用了一个简单的ringbuffer(环形缓冲区)。但是这里需要注意的是,不要和内核trace系统ringbuffer混淆,虽然他们都是为了跟踪调试,但是trace系统的ringbuffer实现更加完善复杂,而printk使用的ring buffer则非常简单,其实就定义了一个字符数组:
- staticchar __log_buf[__LOG_BUF_LEN];
并使用了一套指针来管理:
- static unsigned log_start;
- static unsigned con_start;
- static unsigned log_end;
下面就简要说明一下。
printk在内核中的实现代码如下。
asmlinkage int printk(constchar *fmt, ...)
{ va_listargs;
int r;
va_start(args,fmt);
r = vprintk(fmt, args);
va_end(args);
returnr;
}
vprintk在内核中的实现代码如下。
asmlinkage int vprintk(const char *fmt, va_list args)
{
int printed_len = 0;
int current_log_level = default_message_loglevel; //printk函数的默认输出级别
unsigned long flags;
int this_cpu;
char *p;
boot_delay_msec();
preempt_disable();
raw_local_irq_save(flags);
this_cpu = smp_processor_id();
if (unlikely(printk_cpu == this_cpu)) {
//oops_in_progress只有在panic函数中才为1
if (!oops_in_progress) {
recursion_bug = 1;
goto out_restore_irqs;
}
zap_locks();
}
lockdep_off();
spin_lock(&logbuf_lock);
printk_cpu = this_cpu;
if (recursion_bug) {
recursion_bug = 0;
strcpy(printk_buf, recursion_bug_msg);
printed_len = strlen(recursion_bug_msg);
}
printed_len += vscnprintf(printk_buf + printed_len,
sizeof(printk_buf) - printed_len, fmt, args);
for (p = printk_buf; *p; p++) {
if (new_text_line) {
if (p[0] == '<' && p[1] >= '0' && p[1] <= '7' &&
p[2] == '>') {
current_log_level = p[1] - '0';
p += 3;
printed_len -= 3;
}
emit_log_char('<');
emit_log_char(current_log_level + '0');
emit_log_char('>');
printed_len += 3;
new_text_line = 0;
if (printk_time) {