📚 课程目录第3章日志与打印调试

Linux内核调试技巧内核分析工具系统调试 - 第3节

3、日志与打印调试：printk的级别、格式、动态调试（dynamic_debug）、ftrace的printk事件，以及如何通过dmesg和串口日志定位早期启动问题

在内核开发与系统故障排查中，日志与打印是最基础、最直接的观测手段。与用户态程序不同，内核无法依赖标准C库的printf，也无法随意使用调试器打断点（尤其是在中断上下文或调度器锁定期间）。因此，printk 作为内核自带的格式化输出接口，成为贯穿内核启动、运行、崩溃全生命周期的“眼睛”。然而，printk并非简单的“内核版printf”，其日志级别、格式规范、动态控制机制以及与ftrace、dmesg、串口等工具的协同方式，共同构成了一套完整的日志调试体系。本章将深入剖析printk的级别与格式、dynamic_debug的精细管控、ftrace对printk事件的追踪，并重点讲解如何利用dmesg与串口日志定位早期启动阶段的疑难问题。

上图展示了printk日志调试体系的整体架构。printk作为核心，向下延伸出dynamic_debug、ftrace事件和输出通道三个关键分支，而早期启动问题定位则依赖于early_printk、bootconsole和串口日志的配合。下面我们将逐一深入每个环节。

3.1 printk的日志级别与格式规范

3.1.1 核心原理：八级日志体系

printk的日志级别定义在 include/linux/kern_levels.h 中，共8个级别（0-7），数字越小优先级越高。内核通过 console_loglevel 变量控制哪些级别的消息可以输出到console。默认情况下，console_loglevel 为7（即所有级别都输出），但可以通过内核启动参数 loglevel= 或 quiet 调整。级别定义如下：

级别宏	数值	含义	典型场景
KERN_EMERG	0	系统不可用	内核崩溃前的最后输出
KERN_ALERT	1	必须立即处理	硬件故障、内存损坏
KERN_CRIT	2	严重错误	驱动初始化失败
KERN_ERR	3	错误情况	I/O错误、资源不足
KERN_WARNING	4	警告	性能下降、配置不合理
KERN_NOTICE	5	正常但重要	设备热插拔、文件系统挂载
KERN_INFO	6	信息	驱动版本、硬件探测信息
KERN_DEBUG	7	调试信息	函数入口/出口、变量值

使用printk时，必须显式指定级别，否则默认使用 DEFAULT_MESSAGE_LOGLEVEL（通常为4）。例如：

printk(KERN_ERR "Failed to allocate DMA buffer, size=%zu\n", size);
printk(KERN_INFO "Driver version %s loaded\n", DRV_VERSION);
// 不推荐：printk("no level specified\n");

3.1.2 格式规范与注意事项

printk的格式字符串与printf基本一致，但有几个内核特有的注意事项：

长度修饰符：对于 size_t 使用 %zu，对于 ssize_t 使用 %zd，对于指针使用 %p（内核会进行指针哈希，防止地址泄露）。
特殊格式：%pK 仅在具有CAP_SYSLOG权限时显示真实地址；%pI4/%pI6 用于格式化IP地址；%pM 用于MAC地址。
设备相关打印：推荐使用 dev_info()、dev_err() 等封装，它们会自动添加设备名，便于过滤。
避免在原子上下文使用可能导致睡眠的操作：printk本身不会睡眠，但如果在持有自旋锁时调用，且console驱动需要睡眠（如串口等待FIFO空），则可能引发死锁。此时应使用 printk_ratelimited() 或 printk_once() 限制频率。

经验提醒：在编写驱动时，建议将调试信息统一使用 pr_debug() 或 dev_dbg()，而不是直接使用 printk(KERN_DEBUG ...)。这样可以通过dynamic_debug机制在运行时动态开启，无需重新编译内核。

3.1.3 案例拆解：从日志级别判断问题严重性

假设我们在调试一个PCIe网卡驱动，遇到设备无法识别的问题。初始现象是系统启动后 lspci 看不到设备。我们首先查看dmesg输出：

# dmesg | grep -i pcie
[    2.345678] pcieport 0000:00:01.0: AER: Corrected error received: 0000:01:00.0
[    2.345690] pcieport 0000:00:01.0: AER: can't find device of ID0000

这里只有 KERN_INFO 级别的AER信息，没有 KERN_ERR。这说明PCIe链路层已经枚举到了设备，但设备驱动可能没有正确匹配。进一步使用dynamic_debug开启PCIe核心的调试信息：

# echo 'file drivers/pci/probe.c +p' > /sys/kernel/debug/dynamic_debug/control
# dmesg | grep -i "pci 0000:01:00"
[    3.123456] pci 0000:01:00.0: [8086:10d3] type 00 class 0x020000
[    3.123460] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x000fffff 64bit]
[    3.123465] pci 0000:01:00.0: reg 0x18: [mem 0x00000000-0x00003fff 64bit]

此时发现设备配置空间读取正常，但BAR地址全为0，说明固件没有分配资源。最终定位到BIOS设置中PCIe Resizable BAR选项被禁用，导致驱动无法正确映射。这个案例说明：日志级别决定了你能否看到问题，而dynamic_debug决定了你能否看到细节。

3.1.4 常见误区与总结

风险提示：不要在生产环境随意将 console_loglevel 设为8（即 debug），这会导致大量调试信息输出，严重降低系统性能，并可能将敏感的内核地址信息暴露给用户态进程。建议使用 loglevel=4 作为默认，需要时再通过 echo 8 > /proc/sys/kernel/printk 临时调整。

另一个常见误区是混淆 dmesg 与 console 输出。dmesg读取的是内核环形缓冲区（/dev/kmsg），无论是否输出到console，所有级别的printk都会记录在缓冲区中（除非被 ignore_loglevel 或 log_buf_len 限制）。而console输出受 console_loglevel 控制。因此，dmesg是完整日志，console是过滤后的子集。

3.2 动态调试（dynamic_debug）

3.2.1 核心原理：编译期埋点，运行期开关

dynamic_debug机制允许内核在运行时动态开启或关闭特定代码路径的调试输出，而无需重新编译或重启系统。其原理是：在编译时，所有 pr_debug()、dev_dbg()、print_hex_dump_debug() 等调用会被转换为对 dynamic_pr_debug() 的调用，并记录下文件、函数、行号等元数据。运行时，通过 /sys/kernel/debug/dynamic_debug/control 接口可以精确控制每个调试点的开关状态。

使用dynamic_debug的前提是内核配置了 CONFIG_DYNAMIC_DEBUG（通常默认开启）。查看当前所有调试点：

# cat /sys/kernel/debug/dynamic_debug/control | head -20
# filename:lineno [module]function flags format
drivers/pci/probe.c:1234 [pci]pci_scan_device =_ "PCI: %s\n"
drivers/pci/probe.c:1240 [pci]pci_scan_device =_ "PCI: %s\n"

每行格式为：文件:行号 [模块]函数标志格式字符串。标志位 p 表示启用打印，f 表示打印函数名，l 表示打印行号，m 表示打印模块名，t 表示打印线程ID。

3.2.2 操作流程：精确控制调试输出

启用某个文件的全部调试信息：

# echo 'file drivers/net/ethernet/intel/igb/* +p' > /sys/kernel/debug/dynamic_debug/control

启用某个函数的调试信息并附加函数名和行号：

# echo 'func igb_probe +pfl' > /sys/kernel/debug/dynamic_debug/control

按模块启用：

# echo 'module igb +p' > /sys/kernel/debug/dynamic_debug/control

禁用所有调试输出：

# echo -n '' > /sys/kernel/debug/dynamic_debug/control

还可以通过内核启动参数 dyndbg="file xxx.c +p" 在启动早期就开启调试，这对于定位初始化阶段的问题非常有用。

实战技巧：当驱动在probe阶段失败且没有输出任何日志时，可以在内核启动参数中添加 dyndbg="file drivers/i2c/busses/i2c-designware-common.c +p"，这样在I2C控制器初始化时就会打印详细的寄存器操作信息，帮助判断硬件是否正常响应。

3.2.3 案例拆解：定位USB设备枚举失败

某嵌入式设备上，USB 3.0摄像头无法被识别。系统日志只有一行 usb 1-1: new high-speed USB device number 5 using xhci_hcd，随后没有更多信息。我们怀疑是设备描述符读取失败。开启USB核心的调试：

# echo 'file drivers/usb/core/hub.c +p' > /sys/kernel/debug/dynamic_debug/control
# echo 'file drivers/usb/core/message.c +p' > /sys/kernel/debug/dynamic_debug/control
# 重新插拔设备
# dmesg | tail -30
[  123.456789] usb 1-1: new high-speed USB device number 6 using xhci_hcd
[  123.456812] usb 1-1: ep0 maxpacket = 64
[  123.456820] usb 1-1: device descriptor read/64, error -71
[  123.456825] usb 1-1: device descriptor read/64, error -71
[  123.456830] usb 1-1: failed to get device descriptor, error -71

错误码 -71 对应 -EPROTO，表示协议错误。进一步开启xhci驱动的调试：

# echo 'file drivers/usb/host/xhci-ring.c +p' > /sys/kernel/debug/dynamic_debug/control
# dmesg | grep xhci
[  123.456900] xhci_hcd 0000:00:14.0: WARN: xHC CMD_RUN timeout
[  123.456905] xhci_hcd 0000:00:14.0: WARN: xHC died!

最终定位到xHCI控制器固件异常，需要更新BIOS或检查硬件连接。这个案例展示了dynamic_debug如何层层深入，从USB核心到主机控制器驱动，逐步缩小问题范围。

3.2.4 常见误区与性能考量

风险提示：dynamic_debug虽然强大，但开启过多调试点会显著增加日志输出量，导致 printk 成为性能瓶颈。在中断密集的路径（如网络收包、块设备IO）上开启调试，可能造成CPU占用率飙升甚至触发watchdog超时。建议每次只开启与问题相关的模块，并在问题定位后立即关闭。

另一个误区是忘记检查 CONFIG_DYNAMIC_DEBUG 是否开启。如果内核配置中没有该选项，/sys/kernel/debug/dynamic_debug/ 目录将不存在。此时需要重新编译内核，或者在编译驱动时使用 ccflags-y += -DDEBUG 强制开启 pr_debug（但这样无法在运行时关闭）。

3.3 ftrace的printk事件与trace_printk

3.3.1 核心原理：将日志嵌入函数调用上下文

ftrace是内核的跟踪基础设施，可以记录函数调用、调度事件、中断上下文等。其中，trace_printk() 是一个特殊的打印函数，它将输出写入ftrace环形缓冲区，而不是内核日志缓冲区。这意味着：

时间戳精度更高：ftrace缓冲区记录的是纳秒级时间戳，而dmesg通常只有毫秒级。
上下文信息丰富：trace_printk的输出会与函数调用轨迹、进程切换、中断等事件交织在一起，便于分析调用序列。
性能开销更低：trace_printk不经过console输出，也不受 console_loglevel 限制，适合高频路径。

使用trace_printk需要在代码中显式调用：

#include <linux/tracepoint.h>
// 在需要跟踪的位置
trace_printk("dma_map_single: addr=%pad, size=%zu\n", &dma_addr, size);

查看ftrace输出：

# mount -t tracefs nodev /sys/kernel/tracing
# echo 1 > /sys/kernel/tracing/events/printk/enable
# cat /sys/kernel/tracing/trace | grep dma_map

3.3.2 操作流程：结合函数跟踪定位时序问题

ftrace的printk事件（即 trace_printk）可以与函数跟踪（function_graph）配合使用，以观察某个函数内部的执行流程：

# 设置跟踪器为函数图模式
# echo function_graph > /sys/kernel/tracing/current_tracer
# 启用printk事件
# echo 1 > /sys/kernel/tracing/events/printk/enable
# 设置只跟踪目标函数
# echo 'igb_probe' > /sys/kernel/tracing/set_ftrace_filter
# 触发操作（如重新加载驱动）
# modprobe -r igb; modprobe igb
# 查看结果
# cat /sys/kernel/tracing/trace | head -100

输出会显示 igb_probe 的调用图，其中 trace_printk 的输出会以注释形式出现在对应位置，例如：

 3)               |  igb_probe() {
 3)               |    pci_enable_device() {
 3)               |      pci_enable_device_flags() {
 3)   0.500 us    |        pci_read_config_word();
 3)               |        /* igb_probe: pci_enable_device succeeded */
 3)   1.200 us    |      }
 3)   1.500 us    |    }

3.3.3 案例拆解：分析驱动初始化时序

某网络驱动在加载时偶尔会卡死，怀疑是等待硬件中断超时。使用ftrace的 trace_printk 在关键路径上打点：

// 驱动代码中
static int igb_open(struct net_device *netdev)
{
    trace_printk("igb_open: start\n");
    // 发送打开命令
    writel(IGB_CTRL_RST, hw->hw_addr + IGB_CTRL);
    trace_printk("igb_open: reset issued, waiting for ready\n");
    // 等待硬件就绪
    for (i = 0; i < 100; i++) {
        if (rd32(IGB_STATUS) & IGB_STATUS_READY) {
            trace_printk("igb_open: ready after %d loops\n", i);
            break;
        }
        udelay(100);
    }
    trace_printk("igb_open: done, status=%d\n", i);
}

通过ftrace输出，我们发现 igb_open: reset issued 之后没有立即出现 ready 消息，而是经过了约50ms才打印 ready after 500 loops。进一步结合中断事件跟踪，发现硬件在复位后没有产生预期的MSI-X中断，导致驱动只能通过轮询等待。最终定位到中断亲和性配置错误，修复后初始化时间从50ms降至2ms。

3.3.4 常见误区与总结

经验提醒：trace_printk的输出不会出现在dmesg中，因此排查问题时需要同时查看 /sys/kernel/tracing/trace 和 dmesg。另外，trace_printk的格式字符串不能包含 %p 等需要特殊处理的格式，因为ftrace的格式化器不支持所有printk扩展。

另一个常见误区是忘记关闭ftrace。ftrace持续运行会带来一定的性能开销（即使没有事件触发，函数跟踪的钩子也会影响CPU流水线）。建议在定位问题后立即执行 echo nop > /sys/kernel/tracing/current_tracer 关闭跟踪。

3.4 通过dmesg与串口日志定位早期启动问题

3.4.1 核心原理：早期启动的特殊性

内核启动早期（从 start_kernel 到 console_init 完成）存在几个特殊约束：

console尚未注册：标准的 printk 输出无法显示在屏幕上或串口上，只能写入环形缓冲区。
内存分配器未完全初始化：不能使用 kmalloc 等动态内存接口。
中断可能未开启：依赖中断的驱动无法工作。
调度器未运行：不能使用 schedule() 或睡眠操作。

因此，早期启动问题需要特殊的输出手段：early_printk 和 bootconsole。

3.4.2 操作流程：配置串口日志

要在启动早期看到日志，需要在内核启动参数中配置串口。常见的配置方式：

# 方式1：使用earlycon（推荐，更早可用）
earlycon=uart8250,mmio32,0xfe215000,115200n8
# 方式2：使用bootconsole（在console注册前使用）
console=ttyS0,115200n8
# 方式3：同时配置earlycon和console
earlycon=uart8250,mmio32,0xfe215000,115200n8 console=ttyS0,115200n8

其中 0xfe215000 是UART控制器的物理地址，需要根据具体硬件平台修改。对于ARM64平台，还可以使用 earlycon=pl011,mmio32,0x... 或 earlycon=sbi（RISC-V）。

查看启动日志：

# 在主机上使用minicom或screen连接串口
# minicom -D /dev/ttyUSB0 -b 115200
# 重启目标设备，观察串口输出

如果串口完全没有输出，可以尝试以下排查步骤：

确认串口线连接正确，且目标设备的UART引脚电平匹配（3.3V vs 5V）。
检查bootloader（U-Boot）是否配置了正确的串口参数，并确认U-Boot阶段有输出。
如果U-Boot有输出但内核没有，检查内核启动参数中的 earlycon 地址是否正确。
尝试使用 earlyprintk（x86平台）或 earlycon（ARM平台）的不同变体。

3.4.3 案例拆解：定位内核启动挂死

某ARM64设备在启动到 Calibrating delay loop... 之后挂死，没有任何后续输出。我们配置了 earlycon 和 console，串口日志如下：

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[    0.000000] Linux version 5.15.0-rc6+ (build@host) (gcc (Ubuntu 9.4.0-1ubuntu1~20.04) 9.4.0) #1 SMP PREEMPT
[    0.000000] Machine model: MyBoard Rev.B
[    0.000000] earlycon: uart8250 at MM
        
            ← 上一章
            📖 返回目录
            下一章 →
        
        可可资料掘金营 · 点击在线试看（想要更多资料，咨询可可微信keke90988）

📚 课程目录

Linux内核调试技巧 内核分析工具 系统调试 - 第3节

3、日志与打印调试：printk的级别、格式、动态调试（dynamic_debug）、ftrace的printk事件，以及如何通过dmesg和串口日志定位早期启动问题

3.1 printk的日志级别与格式规范

3.1.1 核心原理：八级日志体系

3.1.2 格式规范与注意事项

3.1.3 案例拆解：从日志级别判断问题严重性

3.1.4 常见误区与总结

3.2 动态调试（dynamic_debug）

3.2.1 核心原理：编译期埋点，运行期开关

3.2.2 操作流程：精确控制调试输出

3.2.3 案例拆解：定位USB设备枚举失败

3.2.4 常见误区与性能考量

3.3 ftrace的printk事件与trace_printk

3.3.1 核心原理：将日志嵌入函数调用上下文

3.3.2 操作流程：结合函数跟踪定位时序问题

3.3.3 案例拆解：分析驱动初始化时序

3.3.4 常见误区与总结

3.4 通过dmesg与串口日志定位早期启动问题

3.4.1 核心原理：早期启动的特殊性

3.4.2 操作流程：配置串口日志

3.4.3 案例拆解：定位内核启动挂死

Linux内核调试技巧内核分析工具系统调试 - 第3节