嵌入式Linux驱动开发（4）——内核打印详解

嵌入式Linux驱动开发4——内核打印详解仓库已经开源所有教程主线内核移植跑新版本imx-linux/uboot都在这里欢迎各位大佬观摩喜欢的话点个⭐仓库地址https://github.com/Awesome-Embedded-Learning-Studio/imx-forge静态网页https://awesome-embedded-learning-studio.github.io/imx-forge/内核里的printf去哪了当你第一次写内核模块时最自然的冲动可能是写上一句printf(Hello, kernel!\n);// 编译错误然后你就会得到一个困惑的编译错误implicit declaration of function printf。说实话第一次看到这个错误的时候我还以为是自己忘包含头文件了翻了半天stdio.h才发现问题根本不在这里。为什么因为内核里没有标准C库。这不是内核开发者故意刁难你而是有深刻的技术原因。标准C库glibc是为用户空间程序设计的它依赖用户空间的种种设施而内核运行在一个完全不同的世界里。所以内核有自己的打印系统——printk。printk vs printf名字的微妙差异你可能会问为什么不直接叫kprintf或者kernel_printf而是叫printk这不是随意的命名而是有深意的。printf代表print formatted格式化打印而printk代表print kernel内核打印。那个k代表kernel提醒你这不是普通的打印这是在内核空间的打印。更重要的是printk和printf有本质区别。用户空间的printf没有日志级别的概念但在内核空间printk必须处理日志级别。这是因为内核的输出目的地是内核日志缓冲区而不是标准输出而且内核消息有紧急程度的区分有些消息需要立即显示到控制台有些则可以缓冲处理。日志级别从紧急到调试Linux内核定义了8个日志级别每个级别对应不同的紧急程度。从0级的KERN_EMERG紧急情况系统不可用到7级的KERN_DEBUG调试消息覆盖了从内核崩溃到详细调试信息的各种场景。说实话一开始我觉得这么多级别有点过度设计了但当你真正在调试一个复杂的驱动问题时你会感谢内核开发者提供了这么细粒度的控制。让我们看看modern_print_kernel_base00_driver的实际输出了解不同日志级别的效果[ 276.787517] EMERGENCY: System is unusable (level 0) [ 276.787526] ALERT: Action must be taken immediately (level 1) [ 276.787534] CRITICAL: Critical conditions occurred (level 2) [ 276.787541] ERROR: Error condition detected (level 3) [ 276.787549] WARNING: Warning condition (level 4) [ 276.787556] NOTICE: Normal but significant condition (level 5) [ 276.787564] INFO: Informational message (level 6)注意最后一行缺少了DEBUG级别的输出。这让我们发现了一个重要的事实默认的内核日志级别设置会过滤掉DEBUG消息。这一点真的坑了很多新手包括我自己。你明明在代码里写了pr_debug但就是看不到输出以为是代码有问题结果只是日志级别没设置对。pr_*宏现代化的打印方式直接使用printk虽然可以但内核开发者提供了更便利的pr_*宏系列。你对比一下就知道差距了。// 传统方式printk(KERN_INFODevice initialized\n);// 现代方式pr_info(Device initialized\n);现代方式明显更简洁不需要手动添加KERN_XXX前缀。而且pr_*宏还有其他优势更安全自动处理格式化字符串更易读代码更清晰支持前缀可以统一添加模块名前缀。这些优势在大型驱动开发中会越来越明显。pr_fmt统一前缀的魔法你注意到前面的测试输出中每条消息都有一个前缀modern_print_kernel_base00_driver:。这个前缀是怎么来的答案是pr_fmt宏。在驱动源码文件的开头定义#definepr_fmt(fmt)MY_DRIVER: fmt后续所有的pr_*宏都会自动添加这个前缀。在modern_print_kernel_base00_driver中就是这样做的#definepr_fmt(fmt)MODERN_PRINT_KERNEL: fmt有了这个前缀日志过滤变得非常简单dmesg|grepMODERN_PRINT_KERNEL调试定位也变得快速得多你可以马上找到问题发生的模块。在复杂系统中区分不同驱动的输出时这个前缀的价值就体现出来了。高级打印功能除了基本的pr_*宏内核还提供了一些高级打印功能这些在特定场景下真的能救命。第一个就是一次性打印*_once。有些消息你只想打印一次比如初始化信息。如果模块被反复加载卸载这些消息会重复出现淹没日志。使用*_once宏可以解决这个问题pr_info_once(This message will only appear once\n);pr_warn_once(Warning: deprecated API usage\n);pr_err_once(Critical: configuration error\n);即使多次加载模块这些消息只出现一次。在我们的测试中这个特性工作得很好。第二个是多行连续打印pr_cont。有时候你想打印多行相关内容但每行都加上时间戳和前缀会很乱。使用pr_cont继续上一行可以让输出更整洁pr_info(Multi-line message example:\n);pr_cont( - Line 1: Continued line without prefix\n);pr_cont( - Line 2: Continued line without prefix\n);pr_cont( - Line 3: Continued line without prefix\n);注意pr_cont输出的行没有时间戳和模块名前缀这样多行输出看起来就像一个整体。第三个是限速打印*_ratelimited。在高频路径中如果每次都打印会导致日志洪水。内核会自动限制这类消息的输出频率if(some_error_condition){pr_err_ratelimited(Frequent error occurred\n);}这个特性在处理中断、定时器等高频回调时特别有用不然你的日志会被瞬间淹没。模块参数动态控制调试级别modern_print_kernel_base00_driver演示了一个重要特性模块参数。你可以这样定义staticintdebug_level1;module_param(debug_level,int,0644);MODULE_PARM_DESC(debug_level,Debug level (0none, 1info, 2debug));这种机制让你可以在不重新编译模块的情况下动态调整输出的详细程度。我们对比三种不同参数的输出效果很明显。当debug_level0时没有Debug level 1的输出因为条件不满足。当debug_level1时显示基本信息输出。当debug_level2时如果启用了DEBUG日志级别还会显示更详细的调试信息。这种灵活性在实际开发中真的很有用。内核日志级别控制你可能会问为什么pr_debug默认不显示答案是内核日志级别控制。你可以通过以下命令查看当前日志级别cat/proc/sys/kernel/printk输出类似4 4 1 7这样四个数字。第一个数字是控制台日志级别决定了哪些消息显示到控制台。默认值通常是4所以pr_debug消息不会显示。如果你想看到所有消息包括DEBUG级别的可以这样设置echo8/proc/sys/kernel/printk设置完成后重新加载模块你就能看到DEBUG消息了。这个设置是临时的重启后会恢复默认值。如果想永久设置可以修改/etc/sysctl.conf文件。条件编译DEBUG宏的妙用除了运行时的日志级别控制内核还支持编译时的条件编译。pr_debug的行为取决于编译时选项如果定义了DEBUG它会被编译为printk(KERN_DEBUG …)如果未定义DEBUG它会被编译为空完全不生成代码。这个特性让你可以在发布版本中完全移除调试代码既减小了代码体积又避免了性能影响。如何在编译时启用DEBUG你可以在Makefile中添加ccflags-y -DDEBUG或者在编译时传递参数makeEXTRA_CFLAGS-DDEBUG还有一个类似的宏pr_devel它总是编译为空除非定义了DEBUG。它比pr_debug更激进即使在运行时启用DEBUG日志级别也不会显示。dmesg的高级用法dmesg是你最重要的调试工具内核把所有消息写入一个环形缓冲区dmesg就是查看这个缓冲区的窗口。除了基本的查看功能还有一些高级用法值得掌握。实时监控日志非常有用dmesg-w或者结合过滤使用dmesg-w|grepMODERN_PRINT_KERNEL这样你就能实时看到特定模块的日志输出不用反复手动执行dmesg命令。清空日志缓冲区在测试时很有用dmesg-cinsmod my_driver.kodmesg先清空加载模块然后查看纯净的输出这样可以避免被其他消息干扰。查看特定级别的消息dmesg-lerr,warn这个命令只显示错误和警告忽略其他级别的消息。当你只关心错误时这个过滤功能能帮你快速定位问题。时间戳显示让日志分析更方便dmesg-T这个参数让时间戳变成人类可读的格式而不是默认的秒数方便你理解事件发生的时间顺序。常见错误与最佳实践在我们踩过无数坑之后总结了一些常见的错误和最佳实践。第一个常见错误是忘记添加换行符。你可能会写成这样pr_info(Loading module);pr_info(Initialization complete);结果输出会连在一起“Loading moduleInitialization complete”。一定要记得在每个pr_*调用末尾加上换行符否则输出会混成一团。第二个错误是在敏感路径使用printk。在中断处理中使用可能睡眠的函数是危险的虽然printk通常不会睡眠但在某些配置下可能会。如果你的驱动在中断上下文中运行要特别小心。第三个错误是过度使用pr_debug。在高频循环中使用pr_debug会导致日志洪水不仅影响性能还会让日志无法阅读。更好的做法是使用条件打印或pr_debug_ratelimited。至于最佳实践我们总结了几条经验。首先始终使用pr_*宏不要直接用printk。其次添加统一前缀使用pr_fmt宏。第三选择合适的日志级别生产环境主要使用pr_err、pr_warn、pr_info开发调试时可使用pr_debug关键错误使用pr_emerg、pr_alert、pr_crit。第四考虑性能影响高频路径使用*_ratelimited。最后提供上下文错误消息要详细包含足够的调试信息这样你看到日志时能快速定位问题。下一步到这里我们已经把内核打印系统讲完了。你现在应该能熟练使用pr_*宏系列理解日志级别的控制知道如何通过dmesg查看和分析日志。这些技能在后面的驱动开发中会派上大用场因为调试驱动很大程度上就是在看日志、分析日志。接下来我们要学习内核调试技术了解如何在驱动出问题时系统地排查和定位问题。准备好了吗相关阅读深入理解Linux模块——模块参数与内核调试让模块活起来的魔法 - 相似度 100%深入理解Linux模块——内核模块编译与加载详解从 Makefile 到 insmod 的完整旅程 - 相似度 100%嵌入式Linux驱动开发3——内核模块机制 - Linux 的插件系统 - 相似度 100%