一、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打印内核版本信息了:
printk(KERN_NOTICE "%s", linux_banner);。
二、printk的使用
printk()和C库中的printf()在使用上最主要的区别就是
printk()指定了日志级别。
（1）日志等级
内核根据日志级别来判断是否在终端（console）上打印消息：内核把级别比某个特定值低的所有消息显示在终端（console）上。但是所有信息都会记录在printk的“ring buffer”中。
printk有8个loglevel,定义在<<a href="http://biancheng.dnbcw.info/linux/" style="color: rgb(0, 102, 204); text-decoration: none;">linux/kernel.h>中：
- #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 ""
-
- #define KERN_CONT ""
如果使用时没有指定日志等级，内核会选用DEFAULT_MESSAGE_LOGLEVEL，这个定义位于kernel/printk.c：
-
- #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\n", KERN_EMERG);
当编译预处理完成之后，前例中的代码实际被编译成成如下格式：
- printk( "<0>" "log_level:%s\n", KERN_EMERG);
给一个printk()什么日志等级完全取决于你。那些正式、且需要保持的消息应该根据信息的性质给出相应的日志等级。但那些为了解决一个问题临时加得到处都是的调试信息可以有两种做法：
一种选择是保持终端的默认记录等级不变，给所有调试信息KERN CRIT或更低的等级以保证信息一定会被输出。
另一种方法则相反，给所有调试信息KERN DEBUG等级，而调整终端的默认记录等级为7，也可以输出所有调试信息。
两种方法各有利弊。
（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__)
-
-
- #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
-
-
- #if defined(DEBUG)
- #define pr_debug(fmt, ...) \
- printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
- #elif defined(CONFIG_DYNAMIC_DEBUG)
-
- #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就可以消除这些调试使用的代码，无需真正地去删除调试输出代码。
（3）输出速率控制
在调试的时候，有时某些部分可能printk会产生大量输出, 导致系统无法正常工作，并可能使系统日志ring buffer溢出（旧的信息被快速覆盖）。特别地，当使用一个慢速控制台设备(如串口), 过量输出也能拖慢系统。这样反而难于发现系统出问题的地方。所以你应当非常注意：正常操作时不应当打印任何东西，打印的输出应当是指示需要注意的异常，并小心不要做过头。
在某些情况下, 最好的做法是设置一个标志变量表示：已经打印过这个了，以后不再打印任何这个信息。而对于打印速率的控制内核已经提供了一个现成的宏:
- #define printk_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的信息到log buffer，并且printk使用的“ring buffer”
三、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];
并使用了一套指针来管理：
-
- static unsigned log_start;
- static unsigned con_start;
- static unsigned log_end;
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) {
char tbuf[50], *tp;
unsigned tlen;
unsigned long long t;
unsigned long nanosec_rem;
t = cpu_clock(printk_cpu);
nanosec_rem = do_div(t, 1000000000);
tlen = sprintf(tbuf, "[%5lu.lu] ",
(unsigned long) t,
nanosec_rem / 1000);
for (tp = tbuf; tp < tbuf + tlen; tp++)
emit_log_char(*tp);
printed_len += tlen;
}
if (!*p)
break;
}
emit_log_char(*p);
if (*p == '\n')
new_text_line = 1;
}
if (acquire_console_semaphore_for_printk(this_cpu))
release_console_sem();
lockdep_on();
out_restore_irqs:
raw_local_irq_restore(flags);
preempt_enable();
return printed_len;
}
对于printk来说，一共有两个缓冲区printk_buf以及log_buf，前者有种临时缓冲的意思，后者用来存储最终要输出的字符串。后面将详细说一下其中最主要的log_buf。 对于vscnprintf函数来说，其就是最终通过vsnprintf()函数将printk的参数根据fmt格式进行转换，并将转换的结果暂存到printk_buf中，最终又将printk_buf中的数据保存到log_buf中。
下面在讨论往log_buf缓冲区写数据的函数emit_log_char之前，先简要说一下printk中的log_buf缓冲区。
static unsigned log_start;
static unsigned con_start;
static unsigned log_end;
其中的log_end标志着下一个写入的位置，其是上一次写的末尾+1；而log_start和con_start则是syslog和consoles读取数据的起始位置。在缓冲区写入的时候正是通过这三个变量以及C语言的特性完成环形的实现。
下面看一下写缓冲区的具体函数实现。
static void emit_log_char(char c)
{
LOG_BUF(log_end) = c;
log_end++;
if (log_end - log_start > log_buf_len)
log_start = log_end - log_buf_len;
if (log_end - con_start > log_buf_len)
con_start = log_end - log_buf_len;
if (logged_chars < log_buf_len)
logged_chars++;
}
这个写入满足每次只写入一个字符，通过LOG_BUF将字符c赋值给缓冲区，通过后面的长度变化来实现环形的概念。其中的LOG_BUF是这样定义的：
#define LOG_BUF(idx) (log_buf[(idx) & LOG_BUF_MASK])
在写入时根据log_end的大小mod缓冲区长度，获取最终的写入位置。
环形缓冲区在字面看来就是一个数组 static char __log_buf[__LOG_BUF_LEN]；其长度一般为4096大小(内核可修改)。而log_end长度为unsigned long范围，远远大于数组的大小，对于每一个字符的赋值log_end则只管++,在加一之后进行判断，如果log_end的值大于log_start，则表示缓冲区的长度已经达到最大，下一次的写入就将覆盖之前最旧的位置，因此log_start = log_end - log_buf_len,将log_start的位置向后移一位（因为每次只写入一个字符，不可能超过一位）。log_end和log_start通过unsigned long的自然溢出来实现环形的判断，而对其中每一次赋值则不再考虑环形的实现形式。（罗里啰嗦了这么多，也不知道能不能看明白，不过我是明白了。。。感觉方法挺巧的。。）
函数的最后，则是release_console_sem函数，在此函数中完成console相关的操作。主要过程就是将con_start与log_end间的数据通过call_console_drivers函数来完成数据往控制台的传递，并且在最后环形klogd进程。
而call_console_drivers函数则是遍历内核中的console链表console_driver,对于其中的每一个console结构，调用其注册的write函数。
这两个函数的代码都比较简单，就不再多说了。
void release_console_sem(void)
{
unsigned long flags;
unsigned _con_start, _log_end;
unsigned wake_klogd = 0;
if (console_suspended) {
up(&console_sem);
return;
}
console_may_schedule = 0;
for ( ; ; ) {
spin_lock_irqsave(&logbuf_lock, flags);
wake_klogd |= log_start - log_end;
if (con_start == log_end)
break;
_con_start = con_start;
_log_end = log_end;
con_start = log_end;
spin_unlock(&logbuf_lock);
stop_critical_timings();
call_console_drivers(_con_start, _log_end);
start_critical_timings();
local_irq_restore(flags);
}
console_locked = 0;
up(&console_sem);
spin_unlock_irqrestore(&logbuf_lock, flags);
if (wake_klogd)
wake_up_klogd();
}
call_console_drivers函数在最终是通过__call_console_drivers函数来实现的。
static void __call_console_drivers(unsigned start, unsigned end)
{
struct console *con;
for (con = console_drivers; con; con = con->next) {
if ((con->flags & CON_ENABLED) && con->write &&
(cpu_online(smp_processor_id()) ||
(con->flags & CON_ANYTIME)))
con->write(con, &LOG_BUF(start), end - start);
}
}
至此，整个printk的实现流程就已经结束了，并不复杂，流程比较清晰
四、用户空间访问内核日志
用户空间访问和控制内核日志有两个接口：
（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和日志系统的总体结构：
此文由下面博客组合而成方便阅读
原文地址：内核日志及printk结构浅析 作者：tekkamanninja
原文地址：printk实现分析 作者：luoyan_xy
本文详细介绍Linux内核中的printk机制，包括其基本概念、使用方法、内核实现原理及用户空间访问方式。文章涵盖printk的功能特性、日志级别设置、输出速率控制等方面，并解析了printk的环形缓冲区设计。
扫一扫
3584
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
