这段时间复习了一下内核调试系统,注意看了一下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()类似,区别在于:
所以,除非要在启动初期在终端上输出,否则我们认为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 ""
/*
* 标注为一个“连续”的日志打印输出行(只能用于一个
* 没有用 \n封闭的行之后). 只能用于启动初期的 core/arch 代码
* (否则续行是非SMP的安全).
*/
#define KERN_CONT ""
/* printk's without a loglevel use this.. */
#define DEFAULT_MESSAGE_LOGLEVEL CONFIG_DEFAULT_MESSAGE_LOGLEVEL
printk(KERN_EMERG "log_level:%s\n", KERN_EMERG);
printk( "<0>" "log_level:%s\n", KERN_EMERG);
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <errno.h>
//#define __LIBRARY__ /* _syscall3 and friends are only available through this */
//#include <linux/unistd.h>
/* 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\n", argv[0]);
exit(1);
}
if (klogctl(8, NULL, level) < 0) {
fprintf(stderr, "%s: syslog(setlevel): %s\n",
argv[0], strerror(errno));
exit(1);
}
exit(0);
}
2.2:相关辅助宏
#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
2.3:输出速率控制
在调试的时候,有时某些部分可能printk会产生大量输出, 导致系统无法正常工作,并可能使系统日志ring buffer溢出(旧的信息被快速覆盖)。特别地,当使用一个慢速控制台设备(如串口), 过量输出也能拖慢系统。这样反而难于发现系统出问题的地方。所以你应当非常注意:正常操作时不应当打印任何东西,打印的输出应当是指示需要注意的异常,并 小心不要做过头。
#define printk_ratelimit() __printk_ratelimit(__func__)
这个函数应当在你认为打印一个可能会出现大量重复的消息之前调用,如果这个函数返回非零值, 继续打印你的消息, 否则跳过它。典型的调用如这样:
if (printk_ratelimit())
printk(KERN_NOTICE "The printer is still on fire\n");
/proc/sys/kern/printk_ratelimit( 可以看作一个监测周期,在这个周期内只能发出下面的控制量的信息)
/proc/sys/kernel/printk_ratelimit_burst(以上周期内的最大消息数,如果超过了printk_ratelimit()返回0)
2.4:最后特别提醒:
3、printk的内核实现
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 */