2. printk 与动态调试:从“瞎猜”到“精准定位”

调试驱动,说白了就是跟内核“对话”。而最基础、最常用的对话方式,就是 printk。我刚开始做驱动时,觉得它不就是个打印函数嘛,有啥好学的?直到有一次,一个偶发性的中断丢失问题,我加了上百个 printk 才定位到原因,结果因为打印太多,系统直接卡死……嗯,从那以后,我才老老实实把 printk 的级别控制和动态调试给研究透了。

2.1 printk 日志级别:给信息贴上“优先级”标签

printk 和用户态的 printf 最大的区别,就是它自带 日志级别 (loglevel)。这个级别决定了这条信息有多“紧急”,以及它会不会出现在控制台上。

你想想看,内核里每秒可能有成千上万条调试信息,如果全打印到控制台,系统不卡死才怪。所以,我们需要给信息分个三六九等。

日志级别的定义在 <linux/kern_levels.h> 里,我常用的几个级别如下:

宏定义 级别值 含义 典型场景
KERN_EMERG 0 紧急事件,系统不可用 系统即将崩溃前的最后遗言
KERN_ALERT 1 必须立即处理 关键硬件故障
KERN_CRIT 2 严重错误 驱动初始化失败
KERN_ERR 3 错误情况 DMA 传输超时
KERN_WARNING 4 警告,可能有问题 中断频率异常
KERN_NOTICE 5 正常但重要的事件 设备热插拔
KERN_INFO 6 信息性消息 驱动版本号、探测到的硬件信息
KERN_DEBUG 7 调试信息 函数进入/退出、变量值
我的习惯: 开发阶段,我几乎只用 KERN_DEBUG 和 KERN_ERR。前者用来跟踪流程,后者用来捕获异常。等到发布时,把 KERN_DEBUG 的调用全删掉或注释掉,只保留 KERN_ERR 以上的关键信息。

使用方式很简单,直接在 printk 里拼接宏就行:

printk(KERN_ERR "my_driver: DMA transfer failed, status = 0x%x\n", status);
printk(KERN_DEBUG "my_driver: entering ioctl, cmd = %d\n", cmd);

注意,KERN_ERR 和后面的格式化字符串之间 没有逗号。这是内核打印的一个小陷阱,我第一次写的时候就漏掉了,结果编译出来的日志级别全乱了。

2.2 控制台日志级别:谁该出现在屏幕上?

日志级别不光给信息分类,还控制着信息的“出口”。内核有一个 控制台日志级别 (console_loglevel),只有优先级 高于 这个级别的信息,才会被打印到控制台(串口或显示器)。

默认情况下,控制台级别通常是 4(KERN_WARNING),这意味着只有 KERN_EMERG 到 KERN_WARNING 的信息会显示在屏幕上。而 KERN_INFO 和 KERN_DEBUG 则会被默默记录到内核日志缓冲区里。

你可以通过 proc 文件系统动态调整:

# 查看当前控制台日志级别
cat /proc/sys/kernel/printk
# 输出示例:4 4 1 7
# 分别代表:控制台级别、默认消息级别、最小控制台级别、默认控制台级别

# 将控制台级别改为 7,让所有调试信息都打印到控制台
echo 7 > /proc/sys/kernel/printk
我曾经踩过的坑: 在产品环境中,千万别把控制台级别设成 7。我曾经在一台嵌入式设备上这么干过,结果 KERN_DEBUG 级别的打印像洪水一样涌向慢速串口,导致系统响应变得极其缓慢,最后 watchdog 超时复位了。调试信息太多,有时候比没有信息更可怕。

2.3 dmesg 与日志管理:从环形缓冲区里“捞”信息

不管信息有没有打印到控制台,它们都会被内核写入一个 环形缓冲区 (ring buffer)。这个缓冲区的大小是固定的(通常几十到几百 KB),新消息会覆盖旧消息。

dmesg 命令就是我们从这个缓冲区里“捞”信息的工具。我个人几乎不用 dmesg 的裸输出,因为信息太多了。我常用的几个参数:

  • dmesg -T:显示人类可读的时间戳。不加这个,你看到的是系统启动后的秒数,很难和具体问题关联起来。
  • dmesg -l err:只显示 KERN_ERR 级别的信息。快速过滤出错误。
  • dmesg -w:实时等待新消息。相当于 tail -f,调试时非常有用。
  • dmesg -c:打印并清空缓冲区。适合在测试前后各执行一次,对比差异。

举个例子,我想看最近一次 USB 设备插入时内核打印了什么:

# 先清空缓冲区
dmesg -c
# 插入 USB 设备
# 然后查看新产生的日志
dmesg -T | tail -20

这里有个小技巧:dmesg 的输出可以配合 grep 使用。比如我只关心我的驱动 my_driver 的日志:

dmesg -T | grep "my_driver"

2.4 动态调试 (Dynamic Debug):手术刀式的精准控制

好了,前面说的都是“全局”控制。但实际调试中,我们往往只想看某个特定函数、某一行代码的打印。这时候,动态调试 (dyndbg) 就派上用场了。

动态调试的核心思想是:把 pr_debug()、dev_dbg() 这些调试打印,在编译时编译进内核,但默认是“关闭”的。运行时,你可以通过 debugfs 接口,像开关灯一样,精准地打开或关闭某一条打印。

要使用动态调试,内核需要开启 CONFIG_DYNAMIC_DEBUG 选项。检查方法:

cat /boot/config-$(uname -r) | grep CONFIG_DYNAMIC_DEBUG
# 如果输出是 y,说明已开启

动态调试的控制接口在 /sys/kernel/debug/dynamic_debug/control。这个文件里列出了所有使用了 pr_debug/dev_dbg 的调用点。每一行都包含文件名、函数名、行号、格式字符串等信息。

我个人觉得,动态调试最强大的地方在于它的 过滤语法。你可以按模块、函数、文件名、行号来开启或关闭打印。

几个我常用的例子:

# 开启 my_driver.ko 模块的所有动态打印
echo "module my_driver +p" > /sys/kernel/debug/dynamic_debug/control

# 只开启 my_driver.c 文件中 my_function 函数的打印
echo "file my_driver.c function my_function +p" > /sys/kernel/debug/dynamic_debug/control

# 开启第 123 行到第 125 行的打印
echo "file my_driver.c line 123-125 +p" > /sys/kernel/debug/dynamic_debug/control

# 关闭所有动态打印
echo "module my_driver -p" > /sys/kernel/debug/dynamic_debug/control

这里的 +p 表示开启打印,-p 表示关闭。除了 p,还有 f(打印函数名)、l(打印行号)、t(打印线程 ID)等标志位,可以组合使用。

避坑指南: 我曾经在调试一个网络驱动的并发问题时,用 module my_net_driver +p 开启了所有动态打印。结果因为打印太多,改变了代码的执行时序,那个并发 bug 竟然复现不出来了!这就是所谓的 Heisenbug(海森堡 bug)——观察行为本身改变了被观察对象。所以,动态调试也要“精准打击”,能开一个函数就别开一个文件,能开一行就别开一个函数。

2.5 知识体系:一张图看懂调试日志

说了这么多,我们来梳理一下整个日志系统的脉络。下面这张图展示了从 printk 调用到最终输出的完整路径:

驱动调试日志系统流程图 printk / pr_debug 日志级别 < 控制台级别? 是 否 打印到控制台 写入环形缓冲区 dmesg 读取缓冲区 动态调试 (dyndbg) 过滤 核心:日志级别控制“是否打印到控制台”,动态调试控制“是否记录到缓冲区”

从这张图可以看得很清楚:日志级别 控制的是“是否上屏”,而 动态调试 控制的是“是否记录”。两者配合使用,才能做到既不影响系统性能,又能随时获取需要的调试信息。

2.6 实战建议:我的调试工作流

最后,分享一下我个人在调试驱动时,关于日志的“三板斧”:

  1. 开发阶段: 在关键路径上大量使用 pr_debug() 和 dev_dbg()。控制台级别保持默认(4),用 dmesg -w 实时观察。如果某个模块问题多,就用动态调试单独打开它的所有打印。
  2. 定位阶段: 当怀疑某个特定函数时,用 echo "function my_func +p" > control 精准打开。配合 dmesg -T | grep my_func 过滤,效率极高。
  3. 发布阶段: 保留所有 pr_debug() 调用,但确保动态调试默认是关闭的。这样,产品在现场出问题时,我们可以远程通过 ssh 或 adb 动态打开调试信息,而无需重新编译内核或驱动。这个能力,在排查那些“只在客户现场复现”的 bug 时,简直是救命稻草。

记住,调试日志是你的“眼睛”。但眼睛太多,反而会看不清。学会控制它们,你才能看到真正想看的东西。