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

在这里插入图片描述

内核版本：6.1+

书接上回：Linux Kernel 编程-你不知道的printk(1)：https://mp.weixin.qq.com/s/TIuxhG3b-KBYXzrDYy__Aw

上回我们介绍了：

printk()的简单使用
pintk 的实现：ring buffer
使用 systemd 命令 journalctl 查看日志
printk 日志级别
printk 替代者 pr_<foo> 宏

下面我们继续介绍一些 printk 在实际工程中的一些使用细节。

1. printk 输出到控制台 console

回想一下，printk 日志一般输出到三个位置：

第一个是内核内存日志缓冲区（默认输出）
第二种是非易失性磁盘/文件（systemd-journal ）
最后一个是控制台设备 (可配置)

控制台设备是纯粹的内核特性，即用户在非图形界面环境中登录的初始终端窗口（ /dev/console）。在 Linux 中，我们可以定义多个控制台：终端 tty 窗口（如 /dev/console）、文本模式 VGA 控制台、帧缓冲区，甚至是通过 USB 提供的串口（在嵌入式系统开发期间很常见）。

例如，当我们通过 USB 转 RS232 TTL UART（USB 转串扣）线将 linux 开发板连接到 x86_64 笔记本电脑时，然后使用终端仿真软件(如 putty、SecureCRT等)，输入 tty 命令，可以查看对应的设置。

# tty
/dev/ttyS0

控制台通常是比较重要的日志，包括来自内核底层的日志打印。 Linux 的 printk 使用 sysctl 机制，将其日志传送到控制台设备。为了更好地理解这一点，我们首先查看相关的 proc 信息（这里，在我们的 x86_64 Ubuntu 虚拟机）：

$ cat /proc/sys/kernel/printk
4	4	1	7

前面的四个数字为 printk 日志级别（0 表示最高，7 表示最低）。前面的四个整数序列的含义是这样的：

当前控制台日志级别。含义是所有小于该值的日志都将被发送到控制台设备。
缺乏显式日志级别的默认级别。
允许的最低日志级别。
启动时默认日志级别。

我们可以看到日志级别4对应的是KERN_WARNING。因此，第一个数字为 4（实际上，Linux 发行版上的典型默认值），所有低于日志级别 4 的 printk 除了被记录到内核日志缓冲区和文件外，还将被发送到控制台设备。实际上，这些设置，适用于以下日志级别的所有内核消息：KERN_EMERG、KERN_ALERT、KERN_CRIT 和 KERN_ERR 默认情况下也会自动发送到控制台设备。

现在将 /proc/sys/kernel/printk 文件的第一个整数值设置为 8 ，保证所有 printk 也直接发送到控制台，从而使 printk 的行为就像常规 printf 一样！在这里，需要使用 root 用户进行设置：

$ sudo sh -c "echo '8 4 1 7' > /proc/sys/kernel/printk"
$ cat /proc/sys/kernel/printk
8	4	1	7

然而，通过 proc 的设置是暂时的，一旦系统重新启动，所做的更改就会丢失。如果要想进行永久设置，则需要通过 sysctl 命令进行设置。同样，需要以 root 身份运行命令：

$ sudo sysctl -w kernel.printk='8 4 1 7'

2. 使用 printk 动态打印日志

作为程序员，我们需要调试技术。根据日志，我们可以了解代码的执行流程，从而可以发现错误。对于 Linux 内核，那些以日志级别 KERN_DEBUG 就是所谓的调试打印，内核中可以通过一些函数进行 “DEBUG” 级别日志输出：

pr_debug("<fmt str>"[, args…]);
dev_dbg(dev, "<fmt str>"[, args…]);
printk(KERN_DEBUG "<fmt str>"[, args…]);

printk DEBUG 级别在默认情况下始终处于关闭状态，只有定义了 “DEBUG” 后，它们才真正生效。

这似乎很方便，但是，在实际生产环境中，如果需要从给定模块查看一些调试打印，该怎么办？有一种方法是定义符号 DEBUG（可以在 Makefle 中定义）、重新编译驱动、卸载并重新加载驱动模块。然而，这种方法在大多数生产系统上并不实用（甚至不允许）。因此，我们需要一种更加动态的方法，这正是内核的动态调试功能所提供的。

通过内核动态调试功能，日志级别为 KERN_DEBUG 的每个 printk 输出都会被编译到内核中。在 make menuconfig 中，动态调试选项位于：

Kernel hacking > printk and dmesg options > Enable dynamic printk() support

confg 配置为 CONFIG_DYNAMIC_DEBUG ，我们假设此配置已经启用（设置为y）。

要检查内核的动态调试是否可用（在 x86 上），如果显示为 y 则可用，否则不可用：

$ grep "DYNAMIC_DEBUG=y" /boot/config-$(uname -r)
CONFIG_DYNAMIC_DEBUG=y

接下来，我们使用动态调试的接口是 debugfs 文件系统：<debugfs_mount_point>/dynamic_debug/control。然而，在许多生产系统上，debugfs 可能未配置（或保持为“不可见”）；在这种情况下，通过配置 proc : /proc/dynamic_debug/control 也能实现相同的效果。

查看 control 文件内容，会显示编译到内核中的所有调试打印或调用点：

$ head -n1 /proc/dynamic_debug/control
# filename:lineno [module]function flags format

第一行显示格式，除 flags 的字段外，其它字段含义都是不言而喻的。

例如，让我们查找 virtio_net 驱动程序（模块）的一些调试打印调用点：

$ grep "virtio_net" /proc/dynamic_debug/control | head -n 3
drivers/net/virtio_net.c:3361 [virtio_net]virtnet_probe =_ "virtnet: registered device %s with %d RX and TX vq's\012"
drivers/net/virtio_net.c:3338 [virtio_net]virtnet_probe =_ "virtio_net: registering cpu notifier failed\012"
drivers/net/virtio_net.c:3327 [virtio_net]virtnet_probe =_ "virtio_net: registering device failed\012"

可以看到调试打印已关闭（“=_” 表示关闭）。要打开它，需要将值 +p 写入标志字段。还可以配置其他几个可选值：m、f、l 和 t。

下面是一些示例，在不同级别的范围内运行动态调试工具。首先确保满足基本先决条件 (CONFIG_DYNAMIC_DEBUG=y)。另外，可以用路径 /proc/dynamic_debug/control 替换下面使用的 /sys/kernel/debug/dynamic_debug/control 的文件路径：

开启路径名包含字符串“virtio_net”的所有文件中的所有调试消息

echo -n 'file *virtio_net* +p' > /sys/kernel/debug/dynamic_debug/control

在另一个终端中使用 journalctl -k -f 查看有大量日志输出：

$ journalctl -k -f
kernel: Sent skb 00000000ed86f85a
kernel: ens3: xmit 00000000e94cce87 cc:d8:1f:1f:be:1b
kernel: Sent skb 00000000e94cce87
kernel: Receiving skb proto 0x0800 len 46 type 0
kernel: Receiving skb proto 0x0800 len 46 type 0
kernel: Receiving skb proto 0x8100 len 81 type 1
kernel: Receiving skb proto 0x0800 len 136 type 0
kernel: ens3: xmit 000000005dc578b3 cc:d8:1f:1f:be:1b

使用 -p 将其关闭：

echo -n 'file *virtio_net* -p' > /sys/kernel/debug/dynamic_debug/control

启用所有 printk DEBUG 输出（所有 pr_debug()|dev_dbg() 调用点）

Note：谨慎使用，这会导致非常大量内核日志输出

echo -n 'module * +pflmt' > /sys/kernel/debug/dynamic_debug/control

关闭输出：

echo -n 'module * -pflmt' > /sys/kernel/debug/dynamic_debug/control

其中 flags：pflmt 含义如下：

static struct { unsigned flag:8; char opt_char; } opt_array[] = {
	{ _DPRINTK_FLAGS_PRINT, 'p' },
	{ _DPRINTK_FLAGS_INCL_MODNAME, 'm' },
	{ _DPRINTK_FLAGS_INCL_FUNCNAME, 'f' },
	{ _DPRINTK_FLAGS_INCL_LINENO, 'l' },
	{ _DPRINTK_FLAGS_INCL_TID, 't' },
	{ _DPRINTK_FLAGS_NONE, '_' },
};

内核文档中有更多示例，参见：https://www.kernel.org/doc/html/v6.1/admin-guide/dynamic-debug-howto.html#examples。

3. 限制 printk 的输出速率

如果频繁执行的代码路径中，有 printk 打印时，输出可能很快就会溢出内核日志缓冲区（在内存中，它是一个循环缓冲区），从而可能覆盖关键信息。除此之外，不断增长的磁盘日志文件无限地重复几乎相同的内核日志消息也很浪费磁盘空间。试想，中断处理程序代码路径中的 printk，如果以 100 Hz 的频率（即每秒 100 次）调用硬件中断会怎样？

为了缓解这些问题，内核提供了一个有趣且有用的替代方案：rate-limited printk 。 pr_<foo>_ratelimited() 宏（其中 foo 是 emerg、alert、crit、err、warn、notice、info 或 debug 之一）与常规 printk 具有相同的语法；当输出太频繁的时候，它可以有效地抑制打印速率。

内核提供了两个名为 printk_ratelimit 和 printk_ratelimit_burst 的 sysctl 文件。我们直接查看sysctl文档（https://www.kernel.org/doc/Documentation/sysctl/kernel.txt）来了解确切的含义：

printk_ratelimit:
Some warning messages are rate limited. printk_ratelimit specifies
the minimum length of time between these messages (in jiffies), by
default we allow one every 5 seconds.
A value of 0 will disable rate limiting.
==============================================
printk_ratelimit_burst:
While long term we enforce one message per printk_ratelimit
seconds, we do allow a burst of messages to pass through.
printk_ratelimit_burst specifies the number of messages we can
send before ratelimiting kicks in.

在 x86_64 Ubuntu 22.04 LTS 上，它们的默认值如下：

$ cat /proc/sys/kernel/printk_ratelimit /proc/sys/kernel/printk_ratelimit_burst
5
10

这意味着默认情况下，在 5 秒时间间隔内发生的同一消息最多有10 个打印。printk ratelimit 在抑制内核 printk 输出时，会显示一条有用的消息，说明有多少早期的 printk 输出被抑制。

ratelimit_test_init: 41 callbacks suppressed
ratelimit_test:ratelimit_test_init():45: [51] ratelimited printk @ KERN_INFO
[6]

内核提供以下宏替代 printk，可以起到限制打印/日志记录的速率的作用：

printk_ratelimited(): Warning! Do not use it – the kernel warns against this.

pr_*_ratelimited(): Where the wildcard * is replaced by the usual – one of emerg, alert, crit, err, warn, notice, info, or debug.

dev_*_ratelimited(): Where the wildcard * is replaced by the usual – one of emerg, alert, crit, err, warn, notice, info, or debug.

优先使用 pr_*_ratelimited() 宏而不是 printk_ratelimited()；驱动程序应使用 dev_*_ratelimited() 宏。

4. 从用户空间输出内核日志

我们经常使用的一种流行的调试技术是在代码中的各个点进行打印，通常可以让我们缩小问题的根源。这确实是一种有用的调试技术，更正式地称为检测代码。内核开发人员经常使用古老的 printk API 来达到这个目的。

假设我们已经编写了一个内核模块，并且正在对其进行调试（通过在代码中的适当位置添加多个 printk 打印），这些输出可以在运行时通过 dmesg （或journalctl）看到它们。

这样很好，但是，如果正在运行一些用户空间测试脚本，并希望通过打印出特定消息来查看脚本和内核模块的执行顺序，该怎么办？比如，假设我们希望日志看起来像这样：

test_script: @user msg 1
kernel_module: msg n, msg n+1, ..., msg n+m 
test_script: @user msg 2 ...

我们可以让用户空间测试脚本将消息写入内核日志缓冲区，就像内核 printk 一样，通过将所述消息写入特殊的 /dev/kmsg 设备文件来实现：

echo "test_script: @user msg 1" > /dev/kmsg

$ dmesg -w
[55527.523756] test_script: @user msg 1

dmesg 有多个选项，使输出更易于阅读，我们可以为dmesg 设置一个别名：

$ alias dmesg='sudo dmesg --decode --nopager --color --ctime'
$ dmesg -w
kern :debug : [Mon Jul 10 08:14:32 2023] wlo1: Limiting TX power to 30 (30 -
0) dBm as advertised by b8:<...>
user :info : [Mon Jul 10 08:25:27 2023] test_script: test msg at KERN_INFO

5. 通过 pr_fmt 宏格式化 printk 输出

通常，我们需要为 printk() 提供上下文输出，例如：它到底发生在哪里？当然我们可以编写这样的代码，利用各种 GCC 宏，如 __FILE__、__func__ 和 __LINE__，来输出文件名、函数名和行号，标记打印从哪里发生的：

pr_info("%s:%s:%s():%d: mywork XY failed!\n", OURMODNAME, __FILE__, __func__, __LINE__);

问题是，如果项目中有很多 printk 打印，那么保证标准 printk 格式可能会很痛苦（例如，首先显示模块名称，后跟文件名，然后是函数名称，可能还有行号），很难确保项目中所有开发者一致且正确的遵循。

pr_fmt（）宏就是为了解决这个问题的，在代码的开头定义这个宏（它必须在第一个 #include）之前，保证代码中的每个后续 printk 都将被预设使用此宏指定的格式。

/**
... 
*/

#define pr_fmt(fmt) "%s:%s(): " fmt, KBUILD_MODNAME, __func__

#include <linux/init.h>
#include <linux/module.h>
#include <linux/kernel.h>

static int __init helloworld_init(void)
{
	pr_info("inserted\n");
	 ... 
}

pr_fmt() 宏使用预定义的 KBUILD_MODNAME 宏来替换内核模块的名称，并使用 GCC __func__ 说明符来显示我们当前正在运行的函数的名称。还可以为 __FILE__ 添加 %s，或者 __LINE__ 宏匹配的 %d 以显示行号。

现在，我们在这个内核模块的 init 函数中打印的 pr_info() 将在内核日志中显示如下：

[381534.391966] helloworld:helloworld_init(): inserted

pr_fmt() 宏非常有用，在内核中，有大量源文件以 pr_fmt() 开头。pr_fmt() 还会通过 dev_*() 宏影响驱动 printk 输出。