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
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 调用到最终输出的完整路径:
从这张图可以看得很清楚:日志级别 控制的是“是否上屏”,而 动态调试 控制的是“是否记录”。两者配合使用,才能做到既不影响系统性能,又能随时获取需要的调试信息。
2.6 实战建议:我的调试工作流
最后,分享一下我个人在调试驱动时,关于日志的“三板斧”:
- 开发阶段: 在关键路径上大量使用
pr_debug()和dev_dbg()。控制台级别保持默认(4),用dmesg -w实时观察。如果某个模块问题多,就用动态调试单独打开它的所有打印。 - 定位阶段: 当怀疑某个特定函数时,用
echo "function my_func +p" > control精准打开。配合dmesg -T | grep my_func过滤,效率极高。 - 发布阶段: 保留所有
pr_debug()调用,但确保动态调试默认是关闭的。这样,产品在现场出问题时,我们可以远程通过ssh或adb动态打开调试信息,而无需重新编译内核或驱动。这个能力,在排查那些“只在客户现场复现”的 bug 时,简直是救命稻草。
记住,调试日志是你的“眼睛”。但眼睛太多,反而会看不清。学会控制它们,你才能看到真正想看的东西。