Linux 内核调试篇4

Linux 内核调试篇4（基于Linux6.6）---printk原理分析

一、printk 原理概述

在 Linux 内核中，printk 是用于输出调试信息、日志消息和错误报告的函数。与用户空间的 printf 类似，printk 允许内核将信息输出到系统日志中，但其有着不同的实现和使用场景。由于内核无法像用户空间程序那样直接使用标准输出（例如 stdout），printk 提供了一个专门的机制来处理内核日志信息。

printk 基本作用

printk 主要用于在内核空间中输出日志信息，调试内核代码时查看执行状态或错误信息。它与 printf 类似，但 printk 的输出内容会被发送到内核日志缓冲区，随后可以通过 dmesg 命令查看。

printk 的基本调用方式

int printk(const char *fmt, ...);

• fmt：格式化字符串，类似于 printf。
• ...：可选的附加参数，依赖于格式化字符串中的占位符。

1.1、printk 的内部工作原理

printk 经过精心设计，以适应内核的多任务、多CPU环境，它的工作原理涉及以下几个关键点：

1、日志级别（Log Levels）

printk 支持不同的日志级别，这决定了日志消息的严重性，以及它们的输出方式。日志级别可以帮助过滤不同级别的日志消息。常见的日志级别包括：

• KERN_EMERG：紧急消息，通常会导致系统崩溃。
• KERN_ALERT：需要立即处理的消息。
• KERN_CRIT：严重错误。
• KERN_ERR：一般错误。
• KERN_WARNING：警告信息。
• KERN_NOTICE：正常但值得注意的信息。
• KERN_INFO：普通信息，系统运行状态。
• KERN_DEBUG：调试信息，通常仅在开发和调试时使用。

例如，输出一个普通信息：

printk(KERN_INFO "This is an info message.\n");

不同的日志级别对应着不同的输出策略和显示方式。

2、日志缓冲区

所有通过 printk 输出的消息首先会被写入内核日志缓冲区。这个缓冲区有大小限制，当缓冲区满时，新的消息会覆盖掉旧的消息。因此，在使用 printk 输出日志时，如果产生过多的输出，可能会丢失早期的日志。

内核日志缓冲区通常存储在内存中，每条消息包含日志级别、时间戳和实际的日志内容。

3、时间戳

每条通过 printk 输出的消息会附带一个时间戳，记录该日志信息的产生时间。printk 自动为每条消息添加时间信息，这对于调试和诊断非常有用。

4、printk 输出到控制台

当内核输出日志时，printk 会将日志消息放入缓冲区后，由 console 子系统负责将这些信息显示到控制台。控制台输出并不是实时的，可能受到控制台输出的限制，例如字符模式控制台或 framebuffer 控制台的输出能力。内核中有一个称为 console_lock 的锁机制，用于保护控制台的输出操作，避免多个内核线程同时写入控制台时出现竞态条件。

5、日志的同步与异步

printk 的输出可以是同步或异步的。为了提高效率，printk 通常会尽可能异步处理日志输出，特别是在不需要实时输出到控制台的情况下。这通过内核中的 logbuf 和 kmsg 系统实现。

• 同步输出：在某些情况下（例如内核崩溃或紧急错误），printk 会进行同步输出，确保日志信息被及时记录。
• 异步输出：在多数情况下，printk 会在后台将日志写入内核日志缓冲区，而不会阻塞当前执行的进程。

6、多核支持

Linux 内核支持多核处理器，因此多个处理器可能会同时调用 printk。为了防止日志混乱，printk 使用了锁（如 console_lock）来确保日志写入的顺序和一致性。

此外，内核中还有对每个处理器的日志缓冲区支持，允许不同 CPU 核心同时产生日志信息。

7、printk 与 dmesg

所有通过 printk 输出的日志信息都存储在内核日志缓冲区中，用户可以通过 dmesg 命令查看这些日志信息。dmesg 会从内核日志缓冲区中读取消息，并将它们打印到用户空间。

二、 内核中prink的实现

 kernel/printk/printk.c

asmlinkage __visible int _printk(const char *fmt, ...)
{
	va_list args;
	int r;

#ifdef CONFIG_SCM_CM
	if (unlikely(keep_silent))
		return 0;
#endif

	va_start(args, fmt);
	r = vprintk(fmt, args);
	va_end(args);

	return r;
}
EXPORT_SYMBOL(_printk);

printk几个特点：

• 它可以从任何上下文中调用。
• 我们尝试获取console_lock。 如果成功，那很容易 - 记录了输出并调用控制台驱动程序。
• 如果无法获得信号量，将输出放入日志缓冲区并返回。
• 现任持有人console_sem会注意到console_unlock（）中的新输出;
• 还会在释放锁之前将其发送到控制台。
   

主要实现如下：

 kernel/printk/printk_safe.c

asmlinkage int vprintk(const char *fmt, va_list args)
{
#ifdef CONFIG_KGDB_KDB
	/* Allow to pass printk() to kdb but avoid a recursion. */
	if (unlikely(kdb_trap_printk && kdb_printf_cpu < 0))
		return vkdb_printf(KDB_MSGSRC_PRINTK, fmt, args);
#endif

	/*
	 * Use the main logbuf even in NMI. But avoid calling console
	 * drivers that might have their own locks.
	 */
	if (this_cpu_read(printk_context) || in_nmi()) {
		int len;

		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
		defer_console_output();
		return len;
	}

	/* No obstacles. */
	return vprintk_default(fmt, args);
}
EXPORT_SYMBOL(vprintk);

可以看到，这个实现中判断了各种上下文，就像注释总共说的那样，能够获取console_lock，表示现在可以直接打印，如果不能获取，那就放入缓冲区，待上一次的console_unlock的时候会输出缓冲区的内容。

以最常见的默认情况来分析。

	return vprintk_default(fmt, args);

  kernel/printk/printk.c

int vprintk_default(const char *fmt, va_list args)
{
	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
}
EXPORT_SYMBOL_GPL(vprintk_default);

 说到这里加入一个东西，就是内核中printk有打印等级。

 include/linux/kern_levels.h

 /* integer equivalents of KERN_<LEVEL> */
#define LOGLEVEL_SCHED		-2	/* Deferred messages from sched code
					 * are set to this special level */
#define LOGLEVEL_DEFAULT	-1	/* default (or last) loglevel */
#define LOGLEVEL_EMERG		0	/* system is unusable */
#define LOGLEVEL_ALERT		1	/* action must be taken immediately */
#define LOGLEVEL_CRIT		2	/* critical conditions */
#define LOGLEVEL_ERR		3	/* error conditions */
#define LOGLEVEL_WARNING	4	/* warning conditions */
#define LOGLEVEL_NOTICE		5	/* normal but significant condition */
#define LOGLEVEL_INFO		6	/* informational */
#define LOGLEVEL_DEBUG		7	/* debug-level messages */

使用时通常使用下面这几个

 include/linux/kern_levels.h

  
#define KERN_EMERG	KERN_SOH "0"	/* system is unusable */
#define KERN_ALERT	KERN_SOH "1"	/* action must be taken immediately */
#define KERN_CRIT	KERN_SOH "2"	/* critical conditions */
#define KERN_ERR	KERN_SOH "3"	/* error conditions */
#define KERN_WARNING	KERN_SOH "4"	/* warning conditions */
#define KERN_NOTICE	KERN_SOH "5"	/* normal but significant condition */
#define KERN_INFO	KERN_SOH "6"	/* informational */
#define KERN_DEBUG	KERN_SOH "7"	/* debug-level messages */
 
#define KERN_DEFAULT	KERN_SOH "d"	/* the default kernel loglevel */

下面就是输出函数：

kernel/printk/printk.c 

  
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;
	unsigned long flags;
 
 
    /*
     * 默认打印等级处理
     */
	if (level == LOGLEVEL_SCHED) {
		level = LOGLEVEL_DEFAULT;
		in_sched = true;
	}
 
    /*
     * 有些console打印比较慢,所以要延迟等前一个打印完再继续打印
     */
	boot_delay_msec(level);
	printk_delay();
 
	/* This stops the holder of console_sem just where we want him */
	logbuf_lock_irqsave(flags);
 
    /*
     * 格式化处理数据
     */
	printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
	logbuf_unlock_irqrestore(flags);
 
	/* If called from the scheduler, we can not call up(). */
    /* 如果不是在调度函数,那就可以直接打印,否则就其它时候打印 */
	if (!in_sched) {
		/*
		 * 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();
	}
 
	wake_up_klogd();
	return printed_len;
}

上面函数关注两个点

printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
console_unlock();

第一点：

kernel/printk/printk.c

__printf(4, 0)
int vprintk_store(int facility, int level,
		  const struct dev_printk_info *dev_info,
		  const char *fmt, va_list args)
{
	struct prb_reserved_entry e;
	enum printk_info_flags flags = 0;
	struct printk_record r;
	unsigned long irqflags;
	u16 trunc_msg_len = 0;
	char prefix_buf[8];
	u8 *recursion_ptr;
	u16 reserve_size;
	va_list args2;
	u32 caller_id;
	u16 text_len;
	int ret = 0;
	u64 ts_nsec;

	if (!printk_enter_irqsave(recursion_ptr, irqflags))
		return 0;

	/*
	 * Since the duration of printk() can vary depending on the message
	 * and state of the ringbuffer, grab the timestamp now so that it is
	 * close to the call of printk(). This provides a more deterministic
	 * timestamp with respect to the caller.
	 */
	ts_nsec = local_clock();

	caller_id = printk_caller_id();

	/*
	 * The sprintf needs to come first since the syslog prefix might be
	 * passed in as a parameter. An extra byte must be reserved so that
	 * later the vscnprintf() into the reserved buffer has room for the
	 * terminating '\0', which is not counted by vsnprintf().
	 */
	va_copy(args2, args);
	reserve_size = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args2) + 1;
	va_end(args2);

	if (reserve_size > LOG_LINE_MAX)
		reserve_size = LOG_LINE_MAX;

	/* Extract log level or control flags. */
	if (facility == 0)
		printk_parse_prefix(&prefix_buf[0], &level, &flags);

	if (level == LOGLEVEL_DEFAULT)
		level = default_message_loglevel;

	if (dev_info)
		flags |= LOG_NEWLINE;

	if (flags & LOG_CONT) {
		prb_rec_init_wr(&r, reserve_size);
		if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
			text_len = printk_sprint(&r.text_buf[r.info->text_len], reserve_size,
						 facility, &flags, fmt, args);
			r.info->text_len += text_len;

			if (flags & LOG_NEWLINE) {
				r.info->flags |= LOG_NEWLINE;
				prb_final_commit(&e);
			} else {
				prb_commit(&e);
			}

			ret = text_len;
			goto out;
		}
	}

	/*
	 * Explicitly initialize the record before every prb_reserve() call.
	 * prb_reserve_in_last() and prb_reserve() purposely invalidate the
	 * structure when they fail.
	 */
	prb_rec_init_wr(&r, reserve_size);
	if (!prb_reserve(&e, prb, &r)) {
		/* truncate the message if it is too long for empty buffer */
		truncate_msg(&reserve_size, &trunc_msg_len);

		prb_rec_init_wr(&r, reserve_size + trunc_msg_len);
		if (!prb_reserve(&e, prb, &r))
			goto out;
	}

	/* fill message */
	text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &flags, fmt, args);
	if (trunc_msg_len)
		memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
	r.info->text_len = text_len + trunc_msg_len;
	r.info->facility = facility;
	r.info->level = level & 7;
	r.info->flags = flags & 0x1f;
	r.info->ts_nsec = ts_nsec;
	r.info->caller_id = caller_id;
	if (dev_info)
		memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));

	/* A message without a trailing newline can be continued. */
	if (!(flags & LOG_NEWLINE))
		prb_commit(&e);
	else
		prb_final_commit(&e);

	ret = text_len + trunc_msg_len;
out:
	printk_exit_irqrestore(recursion_ptr, irqflags);
	return ret;
}

第二点：

kernel/printk/printk.c

void console_unlock(void)
{
	bool do_cond_resched;
	bool handover;
	bool flushed;
	u64 next_seq;

	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. Therefore, create
	 * a local to use for the printing loop.
	 */
	do_cond_resched = console_may_schedule;

	do {
		console_may_schedule = 0;

		flushed = console_flush_all(do_cond_resched, &next_seq, &handover);
		if (!handover)
			__console_unlock();

		/*
		 * Abort if there was a failure to flush all messages to all
		 * usable consoles. Either it is not possible to flush (in
		 * which case it would be an infinite loop of retrying) or
		 * another context has taken over printing.
		 */
		if (!flushed)
			break;

		/*
		 * Some context may have added new records after
		 * console_flush_all() but before unlocking the console.
		 * Re-check if there is a new record to flush. If the trylock
		 * fails, another context is already handling the printing.
		 */
	} while (prb_read_valid(prb, next_seq, NULL) && console_trylock());
}
EXPORT_SYMBOL(console_unlock);

标记log字符串位置的，第一条索引和序列号的，下一条索引和序列号的，已经prink下一条的写入位置的。

kernel/printk/printk.c 

 /* the next printk record to read by syslog(READ) or /proc/kmsg */
static u64 syslog_seq;
static u32 syslog_idx;
static size_t syslog_partial;
 
/* index and sequence number of the first record stored in the buffer */
static u64 log_first_seq;
static u32 log_first_idx;
 
/* index and sequence number of the next record to store in the buffer */
static u64 log_next_seq;
static u32 log_next_idx;
 
/* the next printk record to write to the console */
static u64 console_seq;
static u32 console_idx;
 
/* the next printk record to read after the last 'clear' command */
static u64 clear_seq;
static u32 clear_idx;
 
 
 

最大的log缓冲区，以及这个缓冲区的一些基本操作。

kernel/printk/printk.c

 #define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_buf = __log_buf;
static u32 log_buf_len = __LOG_BUF_LEN;
 
 
 
/* Return log buffer address */
char *log_buf_addr_get(void)
{
	return log_buf;
}
 
/* Return log buffer size */
u32 log_buf_len_get(void)
{
	return log_buf_len;
}
 
/* human readable text of the record */
static char *log_text(const struct printk_log *msg)
{
	return (char *)msg + sizeof(struct printk_log);
}
 
/* optional key/value pair dictionary attached to the record */
static char *log_dict(const struct printk_log *msg)
{
	return (char *)msg + sizeof(struct printk_log) + msg->text_len;
}
 
/* get record by index; idx must point to valid msg */
static struct printk_log *log_from_idx(u32 idx)
{
	struct printk_log *msg = (struct printk_log *)(log_buf + idx);
 
	/*
	 * A length == 0 record is the end of buffer marker. Wrap around and
	 * read the message at the start of the buffer.
	 */
	if (!msg->len)
		return (struct printk_log *)log_buf;
	return msg;
}
 
/* get next record; idx must point to valid msg */
static u32 log_next(u32 idx)
{
	struct printk_log *msg = (struct printk_log *)(log_buf + idx);
 
	/* length == 0 indicates the end of the buffer; wrap */
	/*
	 * A length == 0 record is the end of buffer marker. Wrap around and
	 * read the message at the start of the buffer as *this* one, and
	 * return the one after that.
	 */
	if (!msg->len) {
		msg = (struct printk_log *)log_buf;
		return msg->len;
	}
	return idx + msg->len;
}

知道上面的操作后，看下面，打印等级是怎么处理的。

kernel/printk/printk.c 

 skip:
		if (console_seq == log_next_seq)
			break;
 
		msg = log_from_idx(console_idx);        //取出一个打印
		if (suppress_message_printing(msg->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.
			 */
            /* 等级比设置的等级低,那么就调到一下个log信息,这个低等级的忽略掉 */
			console_idx = log_next(console_idx);
			console_seq++;
			goto skip;
		}
 
 
/* 判断打印等级 */
static bool suppress_message_printing(int level)
{
	return (level >= console_loglevel && !ignore_loglevel);
}

三、总结

1. printk 的调用链

当调用 printk 输出信息时，实际上会通过多个中间层实现最终的控制台输出。其主要流程可以概括为：

1. printk 被调用：内核中通过调用 printk 函数生成日志消息，printk 内部会将消息放入内核日志缓冲区。
2. console_lock 锁机制：printk 调用时，首先会获取一个名为 console_lock 的锁，确保日志消息不会被多个内核线程同时输出到控制台，避免信息冲突。
3. 输出到 console 系统：printk 会根据当前的日志级别，将日志信息传递给 console 系统。console 系统将根据设备类型（例如，虚拟控制台、串口、framebuffer 等）将日志输出到合适的输出设备。
4. console 驱动：console 系统最终将消息通过相应的驱动（例如，tty 设备驱动、fb 驱动、serial 驱动等）输出到实际的控制台设备。

2. printk 与 console 的关系

（1）内核日志缓冲区

printk 会将日志消息放入内核日志缓冲区，这个缓冲区是一个环形缓冲区，存储了所有通过 printk 输出的消息。消息会按照日志级别的不同进行处理，日志级别低的消息（如 KERN_DEBUG）可能会被过滤掉，而较高级别的日志（如 KERN_ERR、KERN_WARNING）会优先输出。

（2）日志消息的传递

在调用 printk 输出日志时，内核会执行如下步骤：

1. 格式化日志消息：与 printf 类似，printk 首先会根据传入的格式化字符串生成日志内容。

2. 选择合适的日志级别：printk 会根据传入的日志级别（如 KERN_INFO、KERN_ERR 等）决定消息的优先级和输出策略。

3. 写入日志缓冲区：日志消息被写入内核日志缓冲区。这个缓冲区有大小限制，因此老旧的消息可能会被新的日志覆盖。

4. 控制台输出：通过 console 系统将日志消息输出到实际的控制台设备。

（3）console 系统

console 系统是内核用来管理不同输出设备的抽象层。它支持多种输出设备（如虚拟控制台、串口设备、framebuffer 等），并通过不同的驱动程序将消息输出到相应的硬件设备。

• console_print 函数：printk 会调用 console_print（或者直接调用与特定控制台设备相关的输出函数），将日志消息传递给控制台系统。

• 控制台设备注册：每个支持输出的设备都会在内核启动时注册到 console 系统中。注册时会指定该设备如何处理输出，例如通过终端设备（tty）、串口设备或图形设备等。

（4）输出到控制台

console 系统会根据配置输出消息：

• 虚拟控制台：如果消息需要输出到文本模式控制台，console 系统会将日志消息输出到当前的虚拟终端（通常是 /dev/tty1 到 /dev/tty7）。

• 串口输出：如果配置了串口控制台输出，printk 输出的日志将通过串口端口发送出去。

• Framebuffer 输出：在图形模式下，printk 可以将日志信息通过 framebuffer 输出到屏幕上，通常用于嵌入式设备。

3. 关键函数和调用链

下面是 printk 与 console 系统之间的核心调用链：

1. printk -> vprintk
vprintk 是 printk 的实际实现函数，负责格式化日志消息并将其写入内核日志缓冲区。

2. vprintk -> console_print
vprintk 会将日志信息传递给 console_print，这是一个用于输出日志到控制台的函数。

3. console_print -> console_drivers
console_print 通过查询控制台设备的驱动，选择合适的输出设备进行日志输出。如果设备没有被注册，则会使用默认的控制台输出（例如，虚拟控制台）。

4. 控制台锁

在多核处理器或多线程环境中，printk 输出的日志可能会引发竞态条件。因此，内核引入了一个名为 console_lock 的锁机制，来保证日志输出的顺序性和一致性。console_lock 用于保护控制台输出，防止多个 CPU 同时向控制台输出信息，导致日志交错和混乱。