4. printk 高级用法：动态调试、格式化输出、时间戳与函数名打印

在驱动中断处理流程的调试中，基础的 printk 往往无法满足复杂场景的需求。本章深入讲解 printk 的高级特性，包括动态调试控制、格式化输出技巧、时间戳精度配置以及函数名自动打印，帮助你在中断上下文实现精准、低开销的日志采集。

4.1 动态调试：运行时开关与细粒度控制

动态调试（Dynamic Debug）允许你在不重新编译内核或模块的情况下，按文件、函数、行号或模块名动态启用/禁用 pr_debug() / dev_dbg() 等调试打印。这对于中断流程的现场排查至关重要。

4.1.1 核心机制

• 编译前提： 内核需要开启 CONFIG_DYNAMIC_DEBUG 以及 CONFIG_DEBUG_FS。
• 控制接口： /sys/kernel/debug/dynamic_debug/control。
• 匹配粒度： 支持按模块名（module）、源文件（file）、函数（func）、行号（line）以及格式字符串（format）进行匹配。

4.1.2 常用操作命令

4.1.3 驱动代码适配

驱动中需要使用 pr_debug() / dev_dbg() 而非 printk(KERN_DEBUG ...)，才能被动态调试框架接管。

#include <linux/printk.h>

static irqreturn_t my_irq_handler(int irq, void *dev_id)
{
    /* 此打印受 dynamic debug 控制 */
    pr_debug("IRQ %d received, dev_id = %p\n", irq, dev_id);

    /* 中断处理逻辑 */
    return IRQ_HANDLED;
}

4.2 格式化输出：从基础到进阶

printk 的格式化字符串与标准 C 库 printf 基本一致，但内核提供了若干扩展格式符，用于打印内核特有的数据类型。

4.2.1 常用格式符速查

4.2.2 中断上下文格式化示例

static irqreturn_t timer_irq_handler(int irq, void *dev_id)
{
    struct my_device *dev = (struct my_device *)dev_id;
    unsigned long flags;

    /* 打印中断号、设备状态、寄存器地址 */
    printk(KERN_INFO "[%s] irq=%d, status=0x%08x, reg_base=%px\n",
           __func__, irq, dev->status, dev->reg_base);

    /* 使用 %pM 打印 MAC 地址 */
    printk(KERN_DEBUG "MAC: %pM\n", dev->mac_addr);

    return IRQ_HANDLED;
}

4.3 时间戳打印：精确到微秒的中断时序

中断调试的核心诉求之一是精确测量中断发生的时间点以及处理耗时。内核提供了多种时间戳方案。

4.3.1 方法一：printk 时间戳前缀（全局开启）

通过内核启动参数或 /sys/module/printk/parameters/time 控制。

# 启动参数方式（在 bootloader 或 /etc/default/grub 中添加）
printk.time=1

# 运行时动态开启
echo 1 > /sys/module/printk/parameters/time

开启后，每条 printk 输出会自动添加形如 [ 5.123456] 的时间前缀，单位为秒，精度为微秒。

4.3.2 方法二：使用 ktime_get() 手动打印高精度时间

在中断处理中手动获取时间戳，可以精确测量中断处理函数内部各阶段的耗时。

#include <linux/ktime.h>

static irqreturn_t precise_irq_handler(int irq, void *dev_id)
{
    ktime_t start, end;
    s64 delta_ns;

    start = ktime_get();

    /* 中断处理核心逻辑 */
    do_work();

    end = ktime_get();
    delta_ns = ktime_to_ns(ktime_sub(end, start));

    printk(KERN_DEBUG "IRQ %d handled in %lld ns\n", irq, delta_ns);

    return IRQ_HANDLED;
}

4.3.3 方法三：动态调试时间戳标志

动态调试支持在启用打印时附加时间戳，无需修改代码：

echo 'func my_irq_handler +pt' > /sys/kernel/debug/dynamic_debug/control

其中 t 标志表示在调试输出前添加 [时间戳] 前缀。

4.4 函数名与行号自动打印

在调试信息中自动包含函数名和行号，可以极大提升日志的可追溯性，避免手动维护字符串。

4.4.1 使用内核预定义宏

4.4.2 封装调试宏

建议驱动中封装统一的调试宏，自动注入函数名和行号：

#define IRQ_DBG(fmt, ...) \
    printk(KERN_DEBUG "[%s:%d] " fmt, __func__, __LINE__, ##__VA_ARGS__)

static irqreturn_t my_irq_handler(int irq, void *dev_id)
{
    IRQ_DBG("IRQ %d entered\n", irq);

    /* 处理逻辑 */

    IRQ_DBG("IRQ %d processed successfully\n", irq);
    return IRQ_HANDLED;
}

输出示例：

[my_irq_handler:123] IRQ 42 entered
[my_irq_handler:128] IRQ 42 processed successfully

4.4.3 动态调试的 f 和 l 标志

如果使用动态调试，无需封装宏，直接通过标志控制：

# 启用函数名和行号
echo 'func my_irq_handler +pfl' > /sys/kernel/debug/dynamic_debug/control

此时 pr_debug("IRQ %d\n", irq); 会自动输出为：

my_irq_handler:123: IRQ 42

4.5 综合示例：中断处理流程的完整调试输出

以下示例整合了动态调试、格式化输出、时间戳和函数名打印：

#include <linux/module.h>
#include <linux/interrupt.h>
#include <linux/ktime.h>

#define DRV_NAME "irq_demo"

static irqreturn_t demo_irq_handler(int irq, void *dev_id)
{
    ktime_t now = ktime_get();
    s64 now_ms = ktime_to_ms(now);

    /* 使用 pr_debug，受动态调试控制 */
    pr_debug("[%lld ms] IRQ %d handled by %s\n",
             now_ms, irq, dev_id ? (char *)dev_id : "NULL");

    /* 模拟中断处理 */
    do_some_work();

    return IRQ_HANDLED;
}

static int __init demo_init(void)
{
    pr_info("IRQ demo module loaded\n");
    return 0;
}

static void __exit demo_exit(void)
{
    pr_info("IRQ demo module unloaded\n");
}

module_init(demo_init);
module_exit(demo_exit);
MODULE_LICENSE("GPL");

调试时执行：

# 启用该模块所有调试输出，附加函数名、行号、时间戳
echo 'module irq_demo +pflt' > /sys/kernel/debug/dynamic_debug/control

预期输出：

demo_irq_handler:42: [1234567 ms] IRQ 42 handled by my_device