Linux Kernel 编程-你不知道的printk(1)

内核版本：6.1+

我们都知道 linux通过 printk()这个 API 记录内核日志，printk有很多细节，并且linux内核中提供了新的API记录日志。下面将深入探讨一些细节。这些对内核/驱动开发人员来说，清楚地理解这些非常重要。

1. printk()的简单使用

当我们使用 C 语言进行开发，为了打印日志，我们在用户空间 通常会使用可靠的 printf() glibc API（或者编写 C++ 代码时的 cout）。然而在内核空间中，没有用户模式或其他库，内核中作为 printf() 的替代者printk()可供我们使用。

他是一个宏，在内核源中的定义位置：include/linux/printk.h:printk(fmt, …)。

实际的函数在这里：kernel/printk/printk.c:_printk()。

内核或内核模块通过 printk() API 打印日志很简单，并且与使用 printf() 非常相似：

printk(KERN_INFO "Hello, world\n");

printf 和 printk 之间的一个关键区别是：用户空间 printf()库 API 的工作方式是根据输入格式化文本字符串并调用 write() 系统调用，该系统调用实际上执行对 stdout 设备的写入，通过默认是终端窗口（或控制台设备）。

内核 printk API 也根据输入格式化其文本字符串，但其输出目的地不同。它首先写入内核日志缓冲区，也可能写入更多位置，下面是一些常见的位置：

• Memory 中的（易失性）内核日志缓冲区

• （非易失性）日志文件，内核日志文件

• 控制台设备

当通过 printk() 打印日志时，可以保证输出进入内核内存 (RAM) 中的日志缓冲区中。那么如何查看内核日志缓冲区内容呢？有几种方法。现在，让我们使用快速简单的方法。

$ dmesg
dmesg: read kernel buffer failed: Operation not permitted

dmesg命令失败了，我们经常会遇到所谓的 sysctl。这里，sysctl 是系统控制的缩写，通常位于 /proc/sys/<dir>/*下；那里是几个目录，包括fs、kernel、net、user、vm。通常，root 访问需要写入 sysctl，而无需特殊权限即可读取多个。关于内核 sysctls 的官方内核文档在这里https://www.kernel.org/doc/Documentation/sysctl/kernel.txt。更详细的：https://www.kernel/org/doc/Documentation/sysctl/ 或者 https://sysctl-explorer.net/

在版本较新的内核中 dmesg_restrict 的 sysctl会阻止普通用户查看内核日志内容；这有利于安全（防止信息泄露）。所以，这次使用 root 权限；让我们查看内核日志缓冲区的最后两行：

$ sudo dmesg | tail -n2
[39884.691954] Hello, world

现在可以看到：“Hello, world” 的输出信息了。

Note： 你可能会在内核日志中看到一条消息，例如：loading out-of-tree module taints kernel and possibly module verification failed: signature and/or required key missing - tainting kernel.。出于安全原因，大多数现代 Linux 发行版都会将内核标记为受污染（字面意思是，如果是第三方/源码树外/外部（或未签名）内核，则为“受污染”或“被污染”模块。（这实际上更像是一种伪法律掩盖，类似于“如果从现在开始出现问题，我们不承担任何责任” —— 你明白了！）

在内核日志中，如 dmesg 程序所示，方括号内的数字最左边的列是一个简单的时间戳，这个时间戳是一个 Kconfig 变量——一个内核配置选项，名为 CONFIG_PRINTK_TIME；它可以被 printk.time 内核参数覆盖（链接：https://elixir.bootlin.com/linux/v6.1.25/source/Documentation/admin-guide/kernel-parameters.txt#L4504）。

2. pintk 的实现：ring buffer

内核日志缓冲区只是内核虚拟地址空间内的一个内存缓冲区，其中保存（记录）printk 输出。从技术上来说，它是全局 __log_buf[] 变量。它在内核源码中的定义如下：

kernel/printk/printk.c
#define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT)
#define LOG_BUF_LEN_MAX (u32)(1 << 31)
static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_buf = __log_buf;
static u32 log_buf_len = __LOG_BUF_LEN;

它被设计为环形缓冲区；它的大小有限（__LOG_BUF_LEN 字节），一旦满了，它就会从字节 0 开始被覆盖。因此，它被称为“环形”缓冲区。在这里，我们可以看到大小基于 Kconfig 变量 CONFIG_LOG_BUF_SHIFT。可以作为内核配置参数：General Setup | Kernel log buffer size. 。

它是一个范围为 12-25 的整数值（可以搜索 init/Kconfig 查看），默认值为 18。因此，默认情况下内核日志缓冲区的大小为 (1 << 18)，即 218 = 256 KB。然而，实际运行时大小也受到其他配置的影响，特别是LOG_CPU_MAX_BUF_SHIFT。此外，Kconfig 文件中描述，“当使用 log_buf_len 内核参数时，此选项也会被忽略，因为它强制环形缓冲区的大小精确（2 的幂）。” 内核参数详细配置 https://www.kernel.org/doc/html/latest/ admin-guide/kernel-parameters.html

log_buf_len=n[KMG]   Sets the size of the printk ring buffer,
       			     in bytes. n must be a power of two and greater
       			     than the minimal size. The minimal size is defined
       			   	 by LOG_BUF_SHIFT kernel config parameter. There is
         			 also CONFIG_LOG_CPU_MAX_BUF_SHIFT config parameter
         			 that allows to increase the default size depending
         			 on the number of CPUs. See init/Kconfig for more details.

无论内核日志缓冲区的大小如何，printk有两个问题显而易见：

它被记录在Memory中；如果系统崩溃或重新启动，我们都会丢失内核日志。

默认情况下，日志缓冲区不是很大，通常只有 256 KB。因此，很明显大量的打印在环形缓冲区中会环绕，从而丢失信息。

3. 使用 systemd 命令 journalctl 查看日志

正如用户空间应用程序使用日志一样，内核也使用日志；该功能称为 kernel logging。对于前面提到的将内核记录到小型易失性内存缓冲区的问题，一个明显的解决方案是将每个内核 printk 写入到存储中的文件中，这正是大多数现代 Linux 发行版的设置方式。内核日志文件的位置因发行版而异：通常，基于 Red Hat 的内核日志文件写入 /var/log/messages文件，基于 Debian 的内核日志文件写入/var/log/syslog。传统上，内核 printk 会连接到用户空间系统记录器守护进程 (syslogd) 来执行文件日志记录，从而进行复杂的处理，例如日志轮换、压缩和归档。

然而，在过去的几年中，系统日志记录已经完全被名为 systemd 强大的系统初始化新框架所取代（它取代了旧的 SysV init 框架，或者通常与旧的 SysV init 框架一起工作）。事实上，systemd 现在甚至在嵌入式 Linux 设备上也经常使用。在 systemd 框架中，日志记录由名为 systemd-journal 的守护进程执行，journalctl 程序是它的命令行工具。

使用日志检索 systemd-journal 一个关键优势是，所有日志，来自应用程序（进程和线程）、库、系统守护进程、内核、驱动程序等的日志都写入（合并）到这里。

这样，我们就可以看到事件的（反向）时间线，而无需手动将不同的日志拼凑成时间线。Journalctl(1) 手册页详细介绍了其各种选项。在这里，提供一些基于 journalctl 的方便别名（假设它在 PATH 中）：

# jlog: 从最近启动后的，所有日志
alias jlog='journalctl -b --all --catalog –no-pager'

# jlogr: 同上，使用 reverse 参数反向打印
alias jlogr='journalctl -b --all --catalog --no-pager --reverse'

# jlogf: 仅显示最新的日志，并在将新日志追加到日志时连续打印新日志，用于实时追踪日志。
alias jlogf='journalctl -f'

# jlogk: 仅仅显示从最近启动后的内核日志
alias jlogk='journalctl -b -k --no-pager'

此外，journalctl 可以轻松地人性化的基于时间的方式搜索日志 - 例如，查看过去半小时内写入的所有内核日志：

journalctl -k --since="30 min ago"

4. printk 日志级别

当通过 printk API 向打印日志时，通常还必须指定记录的日志级别。为了理解和使用这些 printk 日志级别，首先看一下举世闻名的 hello world 之内核模块：

printk(KERN_INFO "Hello, world\n");

KERN_INFO是什么意思？首先，现在要小心，它不是下意识反应所说的那样——一个参数。它和“Hello, world\n”格式字符串之间没有逗号字符，只有空格。KERN_INFO 是内核 printk 可以记录的八个日志级别之一。它的存在使我们能够根据日志级别过滤消息。内核为 printk 定义了八种可能的日志级别：

// include/linux/kern_levels.h
#ifndef __KERN_LEVELS_H__
#define __KERN_LEVELS_H__

#define KERN_SOH "\001" /* ASCII Start Of Header */
#define KERN_SOH_ASCII '\001'

#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 "" /* the default kernel loglevel */

所以，现在我们看到 KERN_<FOO> 日志级别仅仅是字符串（“0”、“1”、…、“7”），它们是 printk 内核日志的前缀，仅此而已。这使我们能够根据日志级别过滤消息。注释清楚地展示了何时使用哪种日志级别。

5. printk 替代者 pr_<foo> 宏

pintk 写起来很麻烦，宏 pr_<too>()可减轻编码痛苦。

printk(KERN_INFO "<format-str>", vars...);

可替代为：

pr_info("<format-str>", vars...);

其中 是日志级别，是 emerg、alert、crit、err、warn、notice、info 或 debug 之一：

// include/linux/printk.h:
/**
* pr_emerg - Print an emergency-level message
* @fmt: format string
* @...: arguments for the format string
*
* This macro expands to a printk with KERN_EMERG loglevel. It uses pr_fmt() to
* generate the format string.
*/
#define pr_emerg(fmt, ...) \
printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
/**
* pr_alert - Print an alert-level message
* @fmt: format string
* @...: arguments for the format string
*
* This macro expands to a printk with KERN_ALERT loglevel. It uses pr_fmt() to
* generate the format string.
*/
#define pr_alert(fmt, ...) \
printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)

#define pr_err(fmt, ...) \
printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)

#define pr_warn(fmt, ...) \
printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)

#define pr_notice(fmt, ...) \
printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)

#define pr_info(fmt, ...) \
printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)

#ifdef DEBUG
#define pr_devel(fmt, ...) \
printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#endif

在使用 pr_*()宏时，有一个称为pr_cont()的宏。它的作用是充当连续字符串，继续前面的输出，这可能很有用，确保最终的 pr_cont() 包含换行符。例如：

// kernel/module.c
if (last_unloaded_module[0])
  pr_cont(" [last unloaded: %s]", last_unloaded_module);
pr_cont("\n");

原文： https://mp.weixin.qq.com/s/TIuxhG3b-KBYXzrDYy__Aw