嵌入式Linux驱动调试printk的9个高阶用法最后一个是救命级一句话总结printk不只是printk——掌握这些技巧你能把内核日志从噪音变成手术刀。做嵌入式Linux驱动开发的人90%的时间都在跟printk打交道。但我见过太多人只会两种printk用法printk(KERN_INFO xxx %d\n, xxx);printk(KERN_ERR error: %d\n, ret);然后出了问题只会用dmesg看日志满屏的打印看到眼瞎。今天我把自己积累的一些printk高阶用法分享出来。每一个都是我在真实项目中验证过的能让你少掉很多头发。技巧一用动态调试Dynamic Debug代替手动开关这是最基础也是最重要的技巧——别再手动注释掉printk了。大多数嵌入式工程师做调试的经典操作#defineDEBUG#ifdefDEBUGprintk(KERN_DEBUGfifo_write: offset%d\n,off);#endif调试完了把#define DEBUG注释掉。过两周又出问题了再取消注释编译烧录复现…你一天的时间就浪费在注释-编译-烧录-复现这个循环里了。正确的做法是用内核的动态调试机制Dynamic Debugpr_debug(fifo_write: offset%d\n,off);然后在运行时动态控制# 打开某个文件的全部调试信息echofile fifo.c p/sys/kernel/debug/dynamic_debug/control# 打开某个函数的调试信息echofunc fifo_write p/sys/kernel/debug/dynamic_debug/control# 带条件的调试echofile fifo.c line 123 p/sys/kernel/debug/dynamic_debug/control# 关闭echofile fifo.c -p/sys/kernel/debug/dynamic_debug/control优势不需要重新编译内核不需要重启设备线上也能开日志。用完关掉不占用生产环境的性能。注意需要在编译内核时打开CONFIG_DYNAMIC_DEBUG。大部分嵌入式Linux发行版都默认开了但如果你是自己裁剪的内核记得加上。技巧二用printk的级别控制过滤噪音printk有8个级别从高到低级别宏含义0KERN_EMERG紧急消息1KERN_ALERT需要立即处理2KERN_CRIT严重错误3KERN_ERR错误4KERN_WARNING警告5KERN_NOTICE通知6KERN_INFO信息7KERN_DEBUG调试关键配置是/proc/sys/kernel/printkcat/proc/sys/kernel/printk# 输出: 7 4 1 7# ^console ^default ^min ^console_loglevel这四个数字分别是console_loglevel比这个数字高的消息会打印到控制台default_message_loglevel没指定级别的printk默认使用这个minimum_console_loglevelconsole_loglevel能设置的最小值default_console_loglevelconsole_loglevel的默认值实战用法# 只打印错误以上的消息生产环境echo3 4 1 7/proc/sys/kernel/printk# 全部打开调试时echo8 4 1 7/proc/sys/kernel/printk# 只打印你自己的驱动日志配合自定义级别echo3 4 1 7/proc/sys/kernel/printk这样你就不用在一堆怪异鸡肋的内核日志里大海捞针了。技巧三printk_ratelimited — 防止日志风暴嵌入式设备上最常见的调试事故你在一个中断处理函数或者高频调用的函数里加了一行printk然后——boom系统直接卡死。不是printk本身卡死而是你的串口/控制台被海量的日志撑爆了。特别是在115200波特率下printk的传输速度大约只有11KB/s。如果你在1ms调一次的中断里打印一行50字节的日志瞬间就有50KB/s的日志量——4倍于串口吞吐能力。内核提供了限速版本printk_ratelimited(KERN_INFOspi_transfer: %d bytes\n,len);默认配置是5秒内最多打印10条超出的丢弃。也可以自定义// 在文件开头定义自己的限速参数staticDEFINE_RATELIMIT_STATE(my_ratelimit,5*HZ,10);if(__ratelimit(my_ratelimit))printk(KERN_INFOi2c_transfer timeout: addr0x%02x\n,addr);这个技巧能救你一命——我见过不止一个同事因为在中断里加printk把系统打崩溃了然后怀疑是硬件问题排查了两天。技巧四pr_cont — 分步打印一行日志当你需要在一个循环里打印数组或者缓冲区的完整内容时// 错误的做法——每个元素一行for(i0;ilen;i)printk(KERN_DEBUGbuf[%d] 0x%02x\n,i,buf[i]);// 正确的做法——一行打印完for(i0;ilen;i)pr_cont(%02x ,buf[i]);printk(\n);pr_cont会延续上一行printk的输出而不是另起一行。但是要注意pr_cont在多核系统中可能会被其他CPU的printk打断导致输出错乱。如果实在需要保证完整性可以先把内容拼接到一个局部缓冲区里再用一次printk输出charhexbuf[256];intpos0;for(i0;imin(len,64);i)possnprintf(hexbufpos,sizeof(hexbuf)-pos,%02x ,buf[i]);printk(KERN_DEBUGrx data: %s\n,hexbuf);技巧五printk timestamp — 精确测时嵌入式调试中非常常见的问题“这个操作到底花了多长时间”不要用jiffies手动算时间差——printk自带时间戳# 在printk消息前加上相对时间戳从系统启动开始的秒数.微秒echoY/sys/module/printk/parameters/time# 或者直接在kernel cmdline加# printk.timey效果[ 5.123456] dwc_otg_hcd: USB reset on port 1 [ 5.234567] dwc_otg_hcd: USB reset done这样你就能精确知道两个事件之间的时间差在微秒级别。更高级的做法——用trace_printk代替printk做性能测量// 比printk快100倍以上适合高频调用场景trace_printk(irq_handler: took %lu us\n,delta);通过/sys/kernel/debug/tracing/trace查看输出。这是printk的替代方案中最轻量级的。技巧六hex_dump — 协议调试神器调试I2C/SPI/USB这类总线协议时经常需要查看原始数据内容。传统做法for(i0;ilen;i)printk(KERN_DEBUGbuf[%d] 0x%02x\n,i,buf[i]);内核提供了专用函数print_hex_dump(KERN_DEBUG,i2c tx: ,DUMP_PREFIX_OFFSET,16,1,tx_buf,tx_len,true);输出效果i2c tx: 00000000: 12 34 ab cd 78 9a bc de f0 12 34 56 78 9a ab cd i2c tx: 00000010: 12 34 56 78参数含义DUMP_PREFIX_OFFSET显示偏移地址16每行16字节1每个字节用1列true显示ASCII字符这个函数在调试通信协议时比任何调试器都好用。技巧七dump_stack — 谁在调用我有时候你打开了一个驱动发现某个函数被莫名其妙地调用了。你想知道是谁调的怎么办dump_stack();输出CPU: 0 PID: 123 Comm: kworker/u2:1 Not tainted 5.10.120 #1 Hardware name: MyBoard (DT) Call trace: dump_backtrace0x0/0x1a0 show_stack0x20/0x30 dump_stack0x74/0x90 my_driver_write0x3c/0x100 // - 当前函数 vfs_write0xc4/0x1e0 ksys_write0x64/0xe0 __arm64_sys_write0x1c/0x30 el0_svc_common0x80/0x180 do_el0_svc0x24/0x90 el0_sync_handler0x88/0x100 el0_sync0x158/0x17c一次调用就暴露了调用链比你看3天的代码逻辑图都有效。搭配技巧五的时间戳if(delta100)dump_stack();// 只有延迟超过100us才打印调用栈技巧八dev_dbg/dev_err — 比printk更专业驱动开发中最好用dev_dbg/dev_err/dev_info系列函数而不是裸printk// 不推荐printk(KERN_ERRmy_i2c_probe: i2c_add_driver failed\n);// 推荐dev_err(i2c_client-dev,i2c_add_driver failed\n);输出效果[ 12.345678] my_i2c_device i2c-0: i2c_add_driver failed优势自动带上设备名称多设备时一眼看出是哪个实例支持动态调试dev_dbg可以被dynamic debug控制代码更干净更符合内核编码规范一致性——所有内核驱动都用这套接口我见过最混乱的项目一个驱动里混用了printk、pr_info、dev_err、print_msg自己封装的四种打印方式后来排查问题时队友直接崩溃。统一用dev_xxx系列跟内核社区保持一致。技巧九最后一个是救命级 — printk死锁与NMI panic最最最危险的情况系统已经死了但你想知道死在哪。正常情况下printk要用到自旋锁console_lock来保护串口输出。但如果系统是在持有这个锁的时候死锁的你的printk永远也打不出来。这时候你需要NMINon-Maskable Interruptprintk// 配置NMI watchdogecho1/proc/sys/kernel/nmi_watchdog echo10/proc/sys/kernel/panic// 或者在内核cmdline加上// nmi_watchdog1 panic10当系统死锁超过10秒NMI watchdog会触发panic然后打印一个神奇的backtrace——即使console_lock被死锁持有NMI中断也能绕过它直接写串口。# 模拟死锁echoc/proc/sysrq-trigger或者更优雅地——用SysRq键# 触发一次完整的dumpechot/proc/sysrq-trigger# 显示所有任务状态echow/proc/sysrq-trigger# 显示D状态不可中断睡眠任务echol/proc/sysrq-trigger# 显示所有CPU的backtrace如果硬件串口可用按AltSysRqt嵌入式设备上通常是AltPrintScreent。这个技巧在量产现场救过我两次——一次是I2C总线死锁一次是中断处理函数里调了msleep导致系统挂死。没有这个技巧我只能飞过去用JTAG连板子看成本差一个数量级。完整决策流程图高,每毫秒级中等,每秒几次低,偶发是否二进制数据调用栈设备信息是否需要调试打印频率高吗trace_printkdynamic debug普通printk需要时间戳printk.timey正常使用查看/sys/kernel/debug/tracing/trace需要打印什么print_hex_dumpdump_stackdev_dbg/dev_errSysRq可用AltSysRqt/w/l配置nmi_watchdog最后printk看着简单但真正用好的人不多。这9个技巧如果你能掌握一半以上你的kernel调试效率至少提升3倍。记住最核心的原则不要直接printk— 用dev_dbg/pr_debug配合dynamic debug控制不要污染串口— 生产环境把console_loglevel设为3不要手动注释代码— 用运行时开关不要等系统挂了才想怎么调试— 提前配好nmi_watchdog嵌入式开发最大的成本不是硬件不是软件是**“等”**——等编译、等烧录、等复现、等日志。printk用好了能让你少等至少一半的时间。