全部博文（14）
2012年（14）
分类： LINUX
2012-12-06 16:22:03
在调试的时候，有时某些部分可能printk会产生大量输出, 导致系统无法正常工作，并可能使系统日志ring buffer溢出（旧的信息被快速覆盖）。特别地，当使用一个慢速控制台设备(如串口), 过量输出也能拖慢系统。这样反而难于发现系统出问题的地方。所以你应当非常注意：正常操作时不应当打印任何东西，打印的输出应当是指示需要注意的异常，并小心不要做过头。
这个函数应当在你认为打印一个可能会出现大量重复的消息之前调用，如果这个函数返回非零值, 继续打印你的消息, 否则跳过它。典型的调用如这样:
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();
/*这一段的代码没有理解的很明白。。。*/
/*printk的递归调用 ? 是在说printk的时候发生oops吗？ */
if (unlikely(printk_cpu == this_cpu)) {
//oops_in_progress只有在panic函数中才为1
if (!oops_in_progress) {
recursion_bug = 1;
goto out_restore_irqs;
}
/*如果在printk运行时，这个CPU崩溃，确信不能死锁，10秒1次初始化锁logbuf_lock和console_sem，留时间给控制台打印完全的oops信息*/
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);
}
/*将要输出的字符串按照fmt中的格式编排好，放入printk_buf中，并返回应该输出的字符个数*/
printed_len += vscnprintf(printk_buf + printed_len,
sizeof(printk_buf) - printed_len, fmt, args);
/*拷贝printk_buf数据到环形缓冲区中，如果调用者没有提供合适的日志级别，则插入默认级别*/
/*拷贝的过程由函数emit_log_char实现，每次拷贝一个字节*/
for (p = printk_buf; *p; p++) {
if (new_text_line) {
/* If a token, set current_log_level and skip over */
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;
/*如果设置了此选项，则在每一条printk信息前都要加上时间参数*/
if (printk_time) {
/* Follow the token with the 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.%06lu] ",
(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;
}
/*
* 网上有这样一句话，要想对console进行操作，必须获取console结构的信号量。如果获取信号量，则可以通过log the output and call the console
* drivers. 反之，则place the output into the log buff and return. 现有的信号量holeder在release函数中将会注意到
* 新的output，在释放信号量前将会把output信息发送给console
*/
/*
* 在acquire_console_semaphore_for_printk函数的注释中有这样一句话：此函数被调用时拥有logbuf_lock的自旋锁，并且处于禁止中断状态
* 在返回时（无论成功get sem）应保证logbuf_lock的自旋锁被释放，但是仍然禁止中断
*/
if (acquire_console_semaphore_for_printk(this_cpu))
/*此函数将log_buf中的内容发送给console，并且唤醒klogd*/
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缓冲区。
/*
* The indices into log_buf are not constrained to log_buf_len - they
* must be masked before subscripting
*/
static unsigned log_start; /* Index into log_buf: next char to be read by syslog() */
static unsigned con_start; /* Index into log_buf: next char to be sent to consoles */
static unsigned log_end; /* Index into log_buf: most-recently-written-char + 1 */
其中的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; /* Nothing to print */
_con_start = con_start;
_log_end = log_end;
con_start = log_end; /* Flush */
spin_unlock(&logbuf_lock);
stop_critical_timings(); /* don't trace print latency */
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函数来实现的。
/*
* Call the console drivers on a range of log_buf
*/
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的实现流程就已经结束了，并不复杂，流程比较清晰
