printk
<p>基于 4.19 内核，参考文档：<a href="https://blog.csdn.net/sinat_34467747/article/details/106714435#:~:text=printk%E5%9C%A8%E5%86%85%E6%A0%B8%E6%BA%90">https://blog.csdn.net/sinat_34467747/article/details/106714435#:~:text=printk%E5%9C%A8%E5%86%85%E6%A0%B8%E6%BA%90</a></p>
<pre><code class="language-c">// file: kernel/printk/printk.c
/**
* printk - print a kernel message
* @fmt: format string
*
* This is printk(). It can be called from any context. We want it to work.
*
* We try to grab the console_lock. If we succeed, it's easy - we log the
* output and call the console drivers. If we fail to get the semaphore, we
* place the output into the log buffer and return. The current holder of
* the console_sem will notice the new output in console_unlock(); and will
* send it to the consoles before releasing the lock.
*
* One effect of this deferred printing is that code which calls printk() and
* then changes console_loglevel may break. This is because console_loglevel
* is inspected when the actual printing occurs.
*
* See also:
* printf(3)
*
* See the vsnprintf() documentation for format string extensions over C99.
*/
asmlinkage __visible int printk(const char *fmt, ...)
{
va_list args;
int r;
va_start(args, fmt);
r = vprintk_func(fmt, args);
va_end(args);
return r;
}
EXPORT_SYMBOL(printk);
</code></pre>
<pre><code class="language-c">// file: kernel/kernel/printk_safe.c
__printf(1, 0) int vprintk_func(const char *fmt, va_list args)
{
/*
* Try to use the main logbuf even in NMI. But avoid calling console
* drivers that might have their own locks.
*/
if ((this_cpu_read(printk_context) &amp; PRINTK_NMI_DIRECT_CONTEXT_MASK) &amp;&amp;
raw_spin_trylock(&amp;logbuf_lock)) { // 0x40000000
int len;
len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
raw_spin_unlock(&amp;logbuf_lock);
defer_console_output();
return len;
}
/* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
if (this_cpu_read(printk_context) &amp; PRINTK_NMI_CONTEXT_MASK) // 0x80000000
return vprintk_nmi(fmt, args);
/* Use extra buffer to prevent a recursion deadlock in safe mode. */
if (this_cpu_read(printk_context) &amp; PRINTK_SAFE_CONTEXT_MASK) // 0x3fffffff
return vprintk_safe(fmt, args);
/* No obstacles. */
return vprintk_default(fmt, args); // 一般是这种场景
}
</code></pre>
<p>函数属性：</p>
<pre><code class="language-c">#define __printf(a, b) __attribute__((__format__(printf, a, b)))
// 该宏定义主要通过 __format__ 属性，来让编译器按照 printf() 函数的参数格式来对函数的参数进行检查。</code></pre>
<p>关于 <code>printk_context</code>，搜索代码如下：</p>
<p><img src="https://www.showdoc.com.cn/server/api/attachment/visitFile?sign=afef8458242fb772dc6d074b8dad853c&amp;file=file.png" alt="" /></p>
<p>几个宏定义：</p>
<pre><code class="language-c">// file: kernel/printk/internal.h
#define PRINTK_SAFE_CONTEXT_MASK 0x3fffffff
#define PRINTK_NMI_DIRECT_CONTEXT_MASK 0x40000000
#define PRINTK_NMI_CONTEXT_MASK 0x80000000</code></pre>
<p>以 <code>vprintk_default</code> 为例，继续看函数：</p>
<pre><code class="language-c">// file: kernel/printk/printk.c
int vprintk_default(const char *fmt, va_list args)
{
int r;
#ifdef CONFIG_KGDB_KDB
/* Allow to pass printk() to kdb but avoid a recursion. */
if (unlikely(kdb_trap_printk &amp;&amp; kdb_printf_cpu &lt; 0)) {
r = vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
return r;
}
#endif
r = vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
return r;
}
EXPORT_SYMBOL_GPL(vprintk_default);
asmlinkage int vprintk_emit(int facility, int level,
const char *dict, size_t dictlen,
const char *fmt, va_list args)
{
int printed_len;
bool in_sched = false, pending_output;
unsigned long flags;
u64 curr_log_seq;
if (level == LOGLEVEL_SCHED) {
level = LOGLEVEL_DEFAULT;
in_sched = true;
}
boot_delay_msec(level); // 延时，里面有执行 touch_nmi_watchdog()
printk_delay(); // 延时，里面有执行 touch_nmi_watchdog()
/* This stops the holder of console_sem just where we want him */
logbuf_lock_irqsave(flags); // 对 logbuf_lock 加 spin 锁。这是全局变量
curr_log_seq = log_next_seq;
printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
pending_output = (curr_log_seq != log_next_seq);
logbuf_unlock_irqrestore(flags);
/* If called from the scheduler, we can not call up(). */
if (!in_sched &amp;&amp; pending_output) {
/*
* Disable preemption to avoid being preempted while holding
* console_sem which would prevent anyone from printing to
* console
*/
preempt_disable();
/*
* Try to acquire and then immediately release the console
* semaphore. The release will print out buffers and wake up
* /dev/kmsg and syslog() users.
*/
if (console_trylock_spinning()) // 这里面也有锁。在宕机场景，可能会导致死锁
console_unlock(); // 这里触发实际打印？
preempt_enable();
}
if (pending_output)
wake_up_klogd();
return printed_len;
}
EXPORT_SYMBOL(vprintk_emit);
/* Must be called under logbuf_lock. */
int vprintk_store(int facility, int level,
const char *dict, size_t dictlen,
const char *fmt, va_list args)
{
static char textbuf[LOG_LINE_MAX];
char *text = textbuf;
size_t text_len;
enum log_flags lflags = 0;
/*
* The printf needs to come first; we need the syslog
* prefix which might be passed-in as a parameter.
*/
text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
/* mark and strip a trailing newline */
if (text_len &amp;&amp; text[text_len-1] == '\n') {
text_len--;
lflags |= LOG_NEWLINE;
}
/* strip kernel syslog prefix and extract log level or control flags */
if (facility == 0) {
int kern_level;
while ((kern_level = printk_get_level(text)) != 0) {
switch (kern_level) {
case '0' ... '7':
if (level == LOGLEVEL_DEFAULT)
level = kern_level - '0';
/* fallthrough */
case 'd': /* KERN_DEFAULT */
lflags |= LOG_PREFIX;
break;
case 'c': /* KERN_CONT */
lflags |= LOG_CONT;
}
text_len -= 2;
text += 2;
}
}
if (level == LOGLEVEL_DEFAULT)
level = default_message_loglevel;
if (dict)
lflags |= LOG_PREFIX|LOG_NEWLINE;
return log_output(facility, level, lflags,
dict, dictlen, text, text_len);
}
static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len)
{
/*
* If an earlier line was buffered, and we're a continuation
* write from the same process, try to add it to the buffer.
*/
if (cont.len) {
if (cont.owner == current &amp;&amp; (lflags &amp; LOG_CONT)) {
if (cont_add(facility, level, lflags, text, text_len))
return text_len;
}
/* Otherwise, make sure it's flushed */
cont_flush();
}
/* Skip empty continuation lines that couldn't be added - they just flush */
if (!text_len &amp;&amp; (lflags &amp; LOG_CONT))
return 0;
/* If it doesn't end in a newline, try to buffer the current line */
if (!(lflags &amp; LOG_NEWLINE)) {
if (cont_add(facility, level, lflags, text, text_len))
return text_len;
}
/* Store it in the record log */
return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
}
/* insert record into the buffer, discard old ones, update heads */
static int log_store(int facility, int level,
enum log_flags flags, u64 ts_nsec,
const char *dict, u16 dict_len,
const char *text, u16 text_len)
{
struct printk_log *msg;
u32 size, pad_len;
u16 trunc_msg_len = 0;
/* number of '\0' padding bytes to next message */
size = msg_used_size(text_len, dict_len, &amp;pad_len);
if (log_make_free_space(size)) {
/* truncate the message if it is too long for empty buffer */
size = truncate_msg(&amp;text_len, &amp;trunc_msg_len,
&amp;dict_len, &amp;pad_len);
/* survive when the log buffer is too small for trunc_msg */
if (log_make_free_space(size))
return 0;
}
if (log_next_idx + size + sizeof(struct printk_log) &gt; log_buf_len) {
/*
* This message + an additional empty header does not fit
* at the end of the buffer. Add an empty header with len == 0
* to signify a wrap around.
*/
memset(log_buf + log_next_idx, 0, sizeof(struct printk_log)); // log_buf 为全局变量
log_next_idx = 0;
}
/* fill message */
msg = (struct printk_log *)(log_buf + log_next_idx); // 要存放的内存位置
memcpy(log_text(msg), text, text_len);
msg-&gt;text_len = text_len;
if (trunc_msg_len) {
memcpy(log_text(msg) + text_len, trunc_msg, trunc_msg_len);
msg-&gt;text_len += trunc_msg_len;
}
memcpy(log_dict(msg), dict, dict_len);
msg-&gt;dict_len = dict_len;
msg-&gt;facility = facility;
msg-&gt;level = level &amp; 7;
msg-&gt;flags = flags &amp; 0x1f;
if (ts_nsec &gt; 0)
msg-&gt;ts_nsec = ts_nsec;
else
msg-&gt;ts_nsec = local_clock();
memset(log_dict(msg) + dict_len, 0, pad_len);
msg-&gt;len = size;
/* insert message */
log_next_idx += msg-&gt;len; // ring buffer，实际存放内容，用多少，就划出多少
log_next_seq++;
return msg-&gt;text_len;
}</code></pre>
<h2>实际打印</h2>
<pre><code class="language-c">// file: kernel/printk/printk.c
/**
* console_unlock - unlock the console system
*
* Releases the console_lock which the caller holds on the console system
* and the console driver list.
*
* While the console_lock was held, console output may have been buffered
* by printk(). If this is the case, console_unlock(); emits
* the output prior to releasing the lock.
*
* If there is output waiting, we wake /dev/kmsg and syslog() users.
*
* console_unlock(); may be called from any context.
*/
void console_unlock(void)
{
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[LOG_LINE_MAX + PREFIX_MAX];
unsigned long flags;
bool do_cond_resched, retry;
if (console_suspended) {
up_console_sem();
return;
}
/*
* Console drivers are called with interrupts disabled, so
* @console_may_schedule should be cleared before; however, we may
* end up dumping a lot of lines, for example, if called from
* console registration path, and should invoke cond_resched()
* between lines if allowable. Not doing so can cause a very long
* scheduling stall on a slow console leading to RCU stall and
* softlockup warnings which exacerbate the issue with more
* messages practically incapacitating the system.
*
* console_trylock() is not able to detect the preemptive
* context reliably. Therefore the value must be stored before
* and cleared after the the &quot;again&quot; goto label.
*/
do_cond_resched = console_may_schedule;
again:
console_may_schedule = 0;
/*
* We released the console_sem lock, so we need to recheck if
* cpu is online and (if not) is there at least one CON_ANYTIME
* console.
*/
if (!can_use_console()) {
console_locked = 0;
up_console_sem();
return;
}
for (;;) {
struct printk_log *msg;
size_t ext_len = 0;
size_t len;
printk_safe_enter_irqsave(flags);
raw_spin_lock(&amp;logbuf_lock); // 加锁
if (console_seq &lt; log_first_seq) {
len = sprintf(text,
&quot;** %llu printk messages dropped **\n&quot;,
log_first_seq - console_seq);
/* messages are gone, move to first one */
console_seq = log_first_seq;
console_idx = log_first_idx;
} else {
len = 0;
}
skip:
if (console_seq == log_next_seq)
break;
msg = log_from_idx(console_idx);
if (suppress_message_printing(msg-&gt;level)) { // 抑制日志
/*
* Skip record we have buffered and already printed
* directly to the console when we received it, and
* record that has level above the console loglevel.
*/
console_idx = log_next(console_idx);
console_seq++;
goto skip;
}
/* Output to all consoles once old messages replayed. */
if (unlikely(exclusive_console &amp;&amp;
console_seq &gt;= exclusive_console_stop_seq)) {
exclusive_console = NULL;
}
len += msg_print_text(msg,
console_msg_format &amp; MSG_FORMAT_SYSLOG,
text + len,
sizeof(text) - len);
if (nr_ext_console_drivers) {
ext_len = msg_print_ext_header(ext_text,
sizeof(ext_text),
msg, console_seq);
ext_len += msg_print_ext_body(ext_text + ext_len,
sizeof(ext_text) - ext_len,
log_dict(msg), msg-&gt;dict_len,
log_text(msg), msg-&gt;text_len);
}
console_idx = log_next(console_idx);
console_seq++;
raw_spin_unlock(&amp;logbuf_lock);
/*
* While actively printing out messages, if another printk()
* were to occur on another CPU, it may wait for this one to
* finish. This task can not be preempted if there is a
* waiter waiting to take over.
*/
console_lock_spinning_enable(); // 设置 owner
stop_critical_timings(); /* don't trace print latency */
call_console_drivers(ext_text, ext_len, text, len); // 遍历 console 并输出。继续
start_critical_timings();
if (console_lock_spinning_disable_and_check()) { // 重置 owner 和 waiter
printk_safe_exit_irqrestore(flags);
return;
}
printk_safe_exit_irqrestore(flags);
if (do_cond_resched)
cond_resched();
}
console_locked = 0;
raw_spin_unlock(&amp;logbuf_lock);
up_console_sem();
/*
* Someone could have filled up the buffer again, so re-check if there's
* something to flush. In case we cannot trylock the console_sem again,
* there's a new owner and the console_unlock() from them will do the
* flush, no worries.
*/
raw_spin_lock(&amp;logbuf_lock);
retry = console_seq != log_next_seq;
raw_spin_unlock(&amp;logbuf_lock);
printk_safe_exit_irqrestore(flags);
if (retry &amp;&amp; console_trylock())
goto again;
}
EXPORT_SYMBOL(console_unlock);
/*
* Call the console drivers, asking them to write out
* log_buf[start] to log_buf[end - 1].
* The console_lock must be held.
*/
static void call_console_drivers(const char *ext_text, size_t ext_len,
const char *text, size_t len)
{
struct console *con;
trace_console_rcuidle(text, len);
if (!console_drivers)
return;
for_each_console(con) { // 遍历以 console_drivers 为表头的链表，访问每一个已经注册的 console，并调用该 console 中定义的 write 方法来打印日志信息
if (exclusive_console &amp;&amp; con != exclusive_console)
continue;
if (!(con-&gt;flags &amp; CON_ENABLED))
continue;
if (!con-&gt;write)
continue;
if (!cpu_online(smp_processor_id()) &amp;&amp;
!(con-&gt;flags &amp; CON_ANYTIME))
continue;
if (con-&gt;flags &amp; CON_EXTENDED)
con-&gt;write(con, ext_text, ext_len);
else
con-&gt;write(con, text, len);
}
}</code></pre>