搞内核的同学几乎没有人没用过printk。它是内核里最直接的调试手段也是我们在排查宕机、死锁、驱动异常时最先想到的那根救命稻草。这篇文章我想把printk的完整工作流程、日志级别控制方式以及我自己在这上面踩过的一些坑系统梳理一遍希望对刚接触内核开发、或者已经在用但还没完全摸透它的朋友有帮助。printk能做什么一句话概括就是在内核代码任意上下文里输出一段格式化文本把它写进内核环形缓冲区ring buffer并按照配置决定是否同步输出到控制台。它解决了“内核态没有标准C库、不能直接调用printf”这个基础问题是所有内核调试信息的统一出口。无论你是写驱动、改调度器、调文件系统还是追一个神秘的系统重启问题printk都是你理解内核运行状态的第一入口。我尽量把原理讲清楚也会把真实项目里容易踩的坑直接摆出来内容比较多建议收藏后慢慢看。1. 搞懂printk的核心机制它和printf到底差在哪很多刚接触内核的人会把printk当成printf的一个“内核版本”这么理解没错但只对了一半。两者在“格式化输出”这个语义上确实一致可printk的底层运行环境比用户态的printf苛刻得多这就决定了它必须有一套完全不同的实现思路。1.1 从函数签名看起日志级别到底藏在哪printk的函数原型长这样int printk(const char *fmt, ...);乍一看和printf没什么区别但核心奥妙藏在fmt里。printk支持用KERN_xxx这样的宏作为格式串前缀用来声明这条日志的级别。比如printk(KERN_INFO Hello, kernel!\n);这里的KERN_INFO并不是打印时候的一个附加参数而是被编译器通过字符串拼接的方式“粘”到格式串的前面。预处理之后实际传给printk的格式串其实是6Hello, kernel!\n6就是日志级别对应的数字。内核在解析格式串时会先读取尖括号内的数字把它解析成这条日志的级别然后从格式串中剔除掉级别前缀再交给格式化逻辑处理。include/linux/printk.h里定义了完整的级别宏宏数值含义典型场景KERN_EMERG0系统不可用内核崩溃前的最紧急信息KERN_ALERT1必须立即处理严重硬件故障KERN_CRIT2严重错误驱动发生致命错误KERN_ERR3错误功能不可用但系统还能跑KERN_WARNING4警告有风险但影响不大KERN_NOTICE5正常但重要设备热插拔等事件KERN_INFO6信息驱动加载信息KERN_DEBUG7调试信息默认不输出到控制台这 8 个级别覆盖了从“系统马上要完蛋”到“纯吐槽式调试信息”的全部场景。级别越低数字越小紧急程度越高。注意printk还可以用KERN_CONT它表示“接着上一行继续打印”不会插入级别前缀也不会在工作流程里被当作新的一条日志。这个宏在调试多行输出时很有用但也容易造成控制台输出错乱我后面会细说。1.2 为什么内核要维护自己的输出函数用户态的printf依赖于 glibc 提供的缓冲机制、文件描述符、系统调用等一系列设施。但在内核态尤其是在中断上下文、调度器代码、时钟中断里你根本不能依赖这些用户态设施。printk的设计目标非常明确不管当前处于什么上下文也不管中断是否被禁用都要尽量可靠地把日志记录下来。为了做到这一点它不能像printf那样调用write()系统调用也不适合使用复杂的锁机制。因此内核维护了一个全局环形缓冲区__log_buf所有日志先写入这里再异步或同步地转发给控制台设备。这个设计思路和“飞机上的黑匣子”很像日志记录本身要在任何情况下都尽量可靠至于能不能实时显示出来反而是次要的。1.3printk与追踪、远程调试的关系在实际调试中printk通常不是孤立存在的。它和ftrace、kprobes、dynamic_debug这些机制互补。printk适合输出低频但关键的事件比如驱动初始化、错误路径、状态切换ftrace适合追踪高频函数调用比如调度器和网络收包路径。理解这一点能帮你在写日志时做好取舍不要什么函数入口都来一句printk否则生产环境会被日志刷爆。我还见过不少人把printk当成唯一的调试手段遇到问题就到处加打印编译、烧录、重启、看日志循环往复。这种做法效率极低。成熟的调试思路应该是先用ftrace或perf缩小范围再用printk在关键路径上做定点确认最后用kprobes在不能重新编译的现场做动态插桩。后面讲常见坑时我还会提到高频printk带来的性能问题。2. 日志级别控制内核日志分级与设备筛选逻辑日志级别不只是给日志本身贴个标签它实际上参与了“是否写入缓冲区”“是否输出到控制台”两层决策。这个分级体系如果没搞明白最容易出现的现象就是代码里明明写了printkdmesg 里也能看到但控制台屏幕上就是什么都没有。2.1 控制台输出与缓冲区记录是两回事先澄清一个大多数人都困惑过的点printk在默认配置下日志一定会写入内核环形缓冲区也就是你在dmesg里一定能看到。但是否输出到当前控制台终端取决于这条日志的级别是否低于等于当前的console_loglevel。因此我们看到的现象就是dmesg 里有日志但串口终端上没有 →console_loglevel过滤掉了这条日志dmesg 里没有日志 → 可能是log_buf被覆盖、日志级别设置异常、或者根本没执行到printk控制台有输出但 dmesg 看不到 → 这种情况很少见极个别非标准控制台驱动会绕过log_buf直接输出把这两个通道分开理解排查问题会顺畅很多。调试串口看不到日志时第一反应应该是去看console_loglevel而不是怀疑串口接错了线。2.2/proc/sys/kernel/printk的四组数字运行时最常用的控制入口是/proc/sys/kernel/printk。执行cat /proc/sys/kernel/printk你会看到类似这样的输出7 4 1 7这四个数字分别代表位置名称含义1console_loglevel当前控制台接受的最低日志级别实际是最高数值2default_message_loglevel未显式指定级别时printk的默认级别3minimum_console_loglevel控制台级别可被设置的最小值数值上限4default_console_loglevel启动时的默认控制台级别判断逻辑是当一条日志的级别数值l满足l console_loglevel时这条日志才会被输出到控制台。也就是说console_loglevel4时只有KERN_ERR3、KERN_WARNING4以及更紧急的KERN_EMERG0、KERN_ALERT1、KERN_CRIT2级别的日志才会显示在控制台上。级别数值大于 4 的信息如KERN_INFO和KERN_DEBUG只进缓冲区不上屏幕。想临时把控制台级别调到最高让所有日志都刷到串口上只需要echo 8 /proc/sys/kernel/printk注意此时console_loglevel8而有效级别最大是 7所以所有级别的日志都会被输出到控制台。这在调试启动早期问题、驱动加载问题时非常实用但生产环境不要这么干日志刷屏的代价是系统性能肉眼可见地下降。2.3 通过内核启动参数控制日志级别运行时的/proc设置会在重启后失效。如果你想让某次开机从一开始就用高详细度日志可以在内核启动参数里加loglevel8这个参数会在内核初始化早期把console_loglevel设置为 8。与之配合的还有ignore_loglevel设置后所有日志都会输出到控制台相当于无条件放开过滤器。在内核调试阶段我经常在 U-Boot 的 bootargs 里加上这两个参数省得每次进系统还要手动 echo。不过要留意ignore_loglevel是一个“把你按在水里不许起来”级别的调试武器。它无视所有级别过滤可能在极短时间内刷爆串口终端导致真正关键的早期日志被淹没在大量KERN_INFO里。我曾经在一个网络驱动的调试中用过一晚上ignore_loglevel第二天发现串口软件的回显缓冲区里塞了上百MB的数据连终端都卡死了。从那以后我只有在需要抓取特定启动阶段日志时才会短暂开启它。2.4dmesg的三个常用控制参数日志缓冲区也是可以控制的。dmesg本身控制的是用户态读取行为而内核侧对应的节点是/proc/sys/kernel/dmesg_restrict设置为 1只有具有CAP_SYSLOG权限的进程才能读取内核日志缓冲区设置为 0所有用户都能读dmesg从安全角度看内核日志里经常包含内存地址、内核栈信息、驱动内部寄存器值这些信息对攻击者做内核漏洞利用非常有帮助。所以生产环境建议开启dmesg_restrict。另外两个常见参数是参数作用dmesg -n设置控制台日志级别等价于写/proc/sys/kernel/printkdmesg -c清空内核环形缓冲区dmesg -T将时间戳转换为可读的本地时间dmesg -T在把内核日志和应用程序日志做时间关联时非常有用因为内核时间戳默认是系统启动以来的秒数不转成人类时间的话很容易对错时间点。2.5 选择日志级别时的一个判断标准我在给内核代码提交printk时常按下面这个标准选级别这行日志打印时系统是否已经处于不可恢复状态 →KERN_EMERG或KERN_ALERT当前功能是否彻底失败用户操作是否无法完成 →KERN_ERR是否发生了异常情况但系统能继续运行 →KERN_WARNING这是不是一次正常的、值得记录的状态变化 →KERN_INFO这行日志是不是仅在开发调试时需要生产环境最好永远不打印 →KERN_DEBUG其中KERN_DEBUG级别的日志默认在控制台上是完全不可见的因为console_loglevel默认是 7而KERN_DEBUG是 7但这里有一个细节默认配置下KERN_DEBUG级别日志的数据值等于 7而console_loglevel也是 7条件l console_loglevel成立意味着它其实也可能被输出到控制台。因此要真正压住调试日志最好把console_loglevel设为 4 或更低或者用dynamic_debug机制做更精细的控制而不是依赖默认级别过滤。3.printk的工作流程从调用到落盘全链路拆解这一节是我想写这篇文章的主要动机。网上讲printk的文章很多但大多停留在“会用”层面真正讲清楚它从调用到输出全过程的很少。而理解这个流程恰恰是解决各种疑难杂症的基础。3.1 调用链三步走格式化、写缓冲、输出一次完整的printk调用在内核里的处理流程可以简化为三个阶段。第一阶段是格式化。printk内部会调用vprintk把可变参数按照fmt格式化成字符串。这一步和用户态printf的原理基本一致区别在于它对格式串里的%p扩展格式有额外支持。比如%pK会对指针做地址隐藏%px会显示真实指针地址%pS可以把函数指针解析为符号名。这些扩展格式在内核日志里非常常用排错时能够直接看到是哪个函数出了问题。第二阶段是写入环形缓冲区。格式化完成后的字符串会被复制到内核的log_buf中。这个缓冲区是个无锁环形队列准确说是依赖自旋锁保护新日志会写到next_seq对应的位置然后移动写指针。如果写指针追上了读指针旧日志就会被覆盖。这就是为什么 dmesg 里有时会看到日志不连续因为缓冲区空间有限最早的日志已经被新日志冲掉了。第三阶段是控制台输出。内核会根据当前console_loglevel判断这条日志是否需要输出到控制台。如果需要就会被追加到console_seq对应的位置由console_unlock函数负责把缓冲区里等待输出的日志逐个发送给注册到系统里的每个console设备。3.2 预处理器printk_safe与死锁规避你可能听说过printk在 NMI不可屏蔽中断上下文里不能随便用。老版本内核里在 NMI 处理函数中调用printk可能导致死锁因为 NMI 中断可能打断正在持有logbuf_lock的代码路径而 NMI 处理函数里的printk尝试再次获取同一把锁于是发生了锁的递归获取——也就是死锁。后来的内核引入了printk_safe机制在 NMI 或 panic 路径中printk不会直接操作主日志缓冲区而是先把日志写入一个 per-CPU 的临时缓冲区等退出 NMI 或 panic 上下文后再慢慢把这些日志刷入主缓冲区。这样既保证了日志不丢失又避免了死锁。这个机制给我们的启示是在中断上下文、NMI 上下文里调用printk不是绝对禁止的但必须意识到它的成本与延迟并尽量把日志内容压缩到最短。靠printk在 NMI 里写长日志来调试是不太现实的。3.3console设备与console_unlock的互动内核里的console并不只有串口一个。/dev/console、VGA 文本终端、netconsole、甚至早期的earlycon本质上都是注册到内核的console驱动。printk输出日志时会遍历所有已注册的console设备把日志发给每一个。这里有一个常见认知误区多数人以为控制台只有一个。其实系统里可能同时存在多个 console例如ttyS0串口和tty0VGA同时注册。console启动参数只是指定了优先使用的 console 设备并不代表其他设备不接收日志。console_unlock是日志输出的执行者。它在持有console_lock的前提下把待输出的日志逐条取出调用con-write发送给控制台设备。如果控制台设备速度很慢比如串口用了低波特率console_unlock会持有锁相当长的时间。这就会导致一个知名问题其他 CPU 上的printk全部被阻塞整个系统的日志输出被串口拖慢。3.4early_printk内核启动早期的日志去哪了在真正的console驱动注册之前内核需要一个更原始的输出来记录启动早期的信息。这就是early_printk或earlycon存在的意义。earlycon会在非常早的阶段通常是setup_arch附近通过解析 DTB 或启动参数直接初始化一个极简的串口驱动用于输出早期启动日志。这个阶段的日志不经过完整的log_buf流程而是直接往串口寄存器里写字符因此不依赖任何锁或调度器能在极早阶段工作。调试启动早期挂死问题时earlycon几乎是必须的手段。比如你在 ARM 平台调试 U-Boot 到内核过渡阶段的串口日志如果没有earlycon内核第一行可见输出往往要等到标准串口驱动注册完成后才会出现而真正的挂死可能发生在更早的时候你就是看不到任何线索。常见的使用方式是在内核启动参数里加上earlyconuart8250,mmio32,0xfe215000这里的0xfe215000是串口控制器的物理地址具体值要根据芯片手册确定。earlycon的参数格式依赖具体的串口类型最常见的是uart8250也有amba-pl011这类变体不同平台差异较大。3.5 缓冲区的观测与调优内核环形缓冲区的大小在编译时通过CONFIG_LOG_BUF_SHIFT配置。默认值通常是 17表示2^17 128KB。如果你的系统日志量很大或者需要长时间用 dmesg 排查问题可以调大这个值。例如CONFIG_LOG_BUF_SHIFT20也就是 1MB 的缓冲区。需要注意的是log_buf在启动时一次性分配运行中无法调整。编译时设置后需要重新编译内核才能生效。高日志量场景下把缓冲区调大远比频繁dmesg -c更实用因为dmesg -c会清空历史一旦之后出问题需要回看之前的日志就来不及了。4. 实操演示驱动里如何正确使用printk铺垫了这么多原理接下来进入实操。我会用一个最小内核模块演示printk的完整使用流程包括模块代码、级别选择、编译加载以及如何在运行时调整日志级别。4.1 最小示例模块写一个简单的内核模块用不同级别打印几条日志然后观察它们在 dmesg 和控制台上的表现。// printk_demo.c #include linux/init.h #include linux/module.h #include linux/kernel.h static int __init demo_init(void) { printk(KERN_EMERG [demo] EMERG level\n); printk(KERN_ALERT [demo] ALERT level\n); printk(KERN_CRIT [demo] CRIT level\n); printk(KERN_ERR [demo] ERR level\n); printk(KERN_WARNING [demo] WARNING level\n); printk(KERN_NOTICE [demo] NOTICE level\n); printk(KERN_INFO [demo] INFO level\n); printk(KERN_DEBUG [demo] DEBUG level\n); return 0; } static void __exit demo_exit(void) { printk(KERN_INFO [demo] module exit\n); } module_init(demo_init); module_exit(demo_exit); MODULE_LICENSE(GPL);对应的 Makefileobj-m printk_demo.o KDIR : /lib/modules/$(shell uname -r)/build all: $(MAKE) -C $(KDIR) M$(PWD) modules clean: $(MAKE) -C $(KDIR) M$(PWD) clean编译make加载模块sudo insmod printk_demo.ko然后查看日志dmesg | tail -n 20你应该能看到 8 条带[demo]前缀的日志全部出现在 dmesg 中包括KERN_DEBUG。但如果看控制台屏幕默认配置下KERN_DEBUG和KERN_INFO级别的内容很可能不会显示具体要看你的console_loglevel是几。4.2 运行时调整级别观察变化把console_loglevel调到 8再卸载并重新加载模块echo 8 /proc/sys/kernel/printk sudo rmmod printk_demo sudo insmod printk_demo.ko这次控制台上应当能看到全部 8 条日志。如果你的开发机连接了串口终端效果会非常直观。再把级别降到 3echo 3 /proc/sys/kernel/printk sudo rmmod printk_demo sudo insmod printk_demo.ko此时只有KERN_EMERG、KERN_ALERT、KERN_CRIT三条会显示在控制台上其他级别都只会进入 dmesg。这就是现场调试时最常用的手法先用高日志级别跑一遍复现问题再逐步降低级别观察控制台输出的变化。4.3 发射频率控制别让日志刷爆系统我见过有的驱动在每次中断里都调用printk导致的中断延迟能到毫秒级这在高速外设驱动上是完全不可接受的。一个正确的做法是利用内核自带的限速机制printk_ratelimited(KERN_WARNING xxx device timeout, cnt%d\n, cnt);printk_ratelimited默认每秒最多打印 10 条超过部分会被自动丢弃。它内部通过ratelimit_state维护一个时间窗口防止单条热路径日志刷爆缓冲区。与之类似的还有按时间判断的写法if (time_after(jiffies, last_print HZ)) { printk(KERN_WARNING xxx\n); last_print jiffies; }这种手写限速的好处是完全可控坏处是每个驱动都要自己维护状态变量。能用内核的printk_ratelimited就用它别重复造轮子。4.4 动态调试开关dynamic_debug的妙用比printk级别控制更精细的是内核的dynamic_debug机制。它允许你动态开关某个文件、某个函数、甚至某一行代码的pr_debug即KERN_DEBUG输出而无需重新编译模块。如果代码里用的是pr_debug就可以这样做# 打开 printk_demo.c 文件里所有调试输出 echo file printk_demo.c p /sys/kernel/debug/dynamic_debug/control这个能力在生产排障场景里非常有用。生产环境默认不打调试日志一旦出现疑难问题你又不想重新编译内核或加载新模块就可以通过/sys/kernel/debug/dynamic_debug/control精准打开某个文件或函数的调试输出定位完毕后随时关闭。对于运行在内核里、无法随意重启的嵌入式设备来说这几乎是最优雅的日志开关方案。5. 常见问题与排查技巧实录这部分是我最想写的。多年内核开发过程里我在printk上栽过的跟头、帮别人排过的故障几乎都能归到下面几类。把它们整理成速查表你在现场排查时直接对照着查。5.1 症状控制台为什么一直没有输出这是遇到最多的求助帖内容。代码里写了printk(KERN_INFO ...)串口却没反应网上搜索的第一屏答案基本都是“调大 loglevel”。但真相可能有这么几种可能原因判断方法解决方案console_loglevel过滤cat /proc/sys/kernel/printk看第一位数是否小于日志级别echo 8 /proc/sys/kernel/printk控制台设备未注册dmesg 里看console注册信息是否包含你的设备检查console启动参数串口多路复用冲突系统同时存在ttyS0和tty0日志被输出到另一个设备明确指定consolettyS0,115200printk在冷路径上未执行加WARN_ON(1)测试是否触发检查代码执行路径日志被限速丢弃dmesg | grep ratelimit关闭限速或放大限制其中“控制台设备未注册”这条比较隐蔽。内核里 console 驱动的注册时机、以及串口控制台在console参数下的配置对新手来说都是黑盒。我之前调试一块 ARM 板子串口始终没有内核日志查了两天最后发现是 DTS 里stdout-path配置指向了错误的串口实例内核把日志全发到了另一个没接线的 UART 上。这类问题的排查思路是先用dmesg查看printk: console [ttyS0] enabled这类信息确认内核到底认为哪个设备是控制台。5.2 症状系统被printk拖死日志风暴引发性能雪崩printk的性能开销不能小看。尤其当控制台是低速串口时输出一条几百字节的日志可能需要几毫秒时间。如果在高速中断路径或热路径上有大量printk光是输出日志就能耗尽 CPU。我遇到过最经典的案例一个网卡驱动的中断处理函数里每条错误路径都放了printk发生一次短暂网络异常时瞬间触发了几万次中断错误日志串口 115200 波特率根本来不及输出console_unlock长时间持有锁最终导致看门狗超时重启。这类问题的标准解法是先把console_loglevel降到 1尽量让日志只在 dmesg 里记录不输出到控制台用printk_ratelimited限制单位时间内的日志数量在深入调试时再临时打开控制台输出并配合日志级别过滤只保留KERN_ERR及以上。还有一个比较进阶的配置是把启动参数里的console指定为ttynull之类的空设备或者干脆不配置物理控制台。这样日志只进缓冲区不经过任何慢速控制台设备性能损耗降到最低。5.3 症状日志乱序、丢失、显示不完整printk日志的乱序是常态。多核系统里不同 CPU 同时调用printk谁先进入锁内、谁先写入缓冲区并不严格代表日志实际发生的时间先后。如果你需要精确的事件顺序更好的方案是用trace_printk配合 ftrace后者会带上完整的时间戳和 CPU 编号。日志丢失则有两种常见原因。第一种是环形缓冲区被新日志覆盖早期日志被冲掉尤其在ignore_loglevel或dynamic_debug大量开启时第二种是printk_ratelimited限速后丢弃可在 dmesg 中搜索printk: N messages suppressed之类的提示确认。显示不完整的问题多出现在并发输出时多个 CPU 的日志交织在一起串口控制台在输出过程中没有锁保护某条日志被另一条打断。在KERN_CONT场景下尤其明显。我自己遇到过驱动里连续用多次KERN_CONT打印一个寄存器 dump结果中间混入了其他 CPU 的中断日志整个 dump 根本没法解析。后来改成一次性拼接成单行打印问题才解决。5.4 症状printk引发死锁或系统挂死在中断上下文、自旋锁临界区、NMI 上下文使用printk需要额外小心。尽管现代内核在多数场景下做了优化仍然存在几个特殊场景在中断处理函数里持有spinlock的同时调用printk而printk的输出设备驱动又需要同一个锁就可能造成死锁串口控制台的write函数内部如果使用了和你的临界区冲突的锁也会触发同样的问题NMI 上下文调用printk虽然经过printk_safe做了缓冲但如果你在 NMI 里同时操作了其他共享资源依然有风险。这类问题的排查没有捷径只能靠两点第一明确当前代码处于什么上下文第二严格控制printk只在明确的、锁无关的路径上使用。在自旋锁保护的临界区内宁可先把日志内容存到一个临时变量里出临界区后再printk也不要冒险在临界区内输出日志。5.5 症状内核启动早期没有日志很多嵌入式开发者遇到过这样的现象开发板从 U-Boot 跳转到内核后串口屏幕上要过好几秒才出现第一行日志或者直接一片空白内核似乎“静默启动”。如果内核最终能跑起来只是早期日志缺失常见原因是标准 console 驱动注册太晚。此时应该检查是否使用了earlycon并确认参数里的地址、时钟、波特率是否正确。注意有的 SoC 串口需要初始化相应的 pinmux 或时钟否则即使地址对了也无法输出。如果内核启动直接挂死且没有earlycon可能连第一行日志都看不到。这时候需要回到 U-Boot 阶段确认映像加载地址、DTS 配置、串口设置是否匹配。我在带过的一位新人身上见过一个经典案例他调了三天“内核启动挂死”最后发现 U-Boot 里bootargs没传consolettyS0,115200内核输出全走 VGA而板子根本没接显示器。5.6 症状生产环境不该泄露的信息被打印出来了printk里最容易犯的安全错误是不小心打印了敏感数据。内核日志可能通过/dev/kmsg被用户态读取也可能被netconsole发到远程日志服务器如果再叠加dmesg_restrict0任何本地用户都能看到日志内容。因此在内核日志里输出缓冲区内容、寄存器原始值、内存地址时一定要谨慎。尤其是指针地址默认情况下%p会被内核替换为hashed值这是CONFIG_KALLSYMS和kptr_restrict共同作用的结果。如果你确实需要打印原始指针做调试必须显式使用%px并且确认kptr_restrict的值不会带来安全风险cat /proc/sys/kernel/kptr_restrict设置为 2 时只有 root 才能查看原始地址且必须拥有CAP_SYSLOG权限。生产环境建议保持这个值。6. 工具链与扩展让printk输出更便于分析printk输出的原始文本日志在复杂问题面前往往不够直观。做内核调试久了我习惯配合几个工具一起用效率提升非常明显。6.1dmesg的过滤和时间转换dmesg本身支持按级别过滤。只看错误及以上级别dmesg --levelerr,crit,alert,emerg只看某个模块相关的日志dmesg | grep -i demo如果需要把内核时间戳转换成人类可读的时间dmesg -T在对比多个事件的发生顺序时我通常先把dmesg -T的输出重定向到文件然后在文件里用时间戳做关联分析。注意dmesg -T的时间基准是系统启动时刻如果系统运行了很久还需要结合uptime确认启动时间。6.2 内核动态打印调试开关前面提到的dynamic_debug值得再展开一下。它的控制文件在/sys/kernel/debug/dynamic_debug/control查看当前已开启的动态调试点cat /sys/kernel/debug/dynamic_debug/control按模块开启echo module printk_demo p /sys/kernel/debug/dynamic_debug/control按函数开启echo func demo_init p /sys/kernel/debug/dynamic_debug/control这个机制要求代码里用的是pr_debug、dev_dbg这类可动态控制宏而不是裸的printk(KERN_DEBUG)。如果你在维护一个大型驱动建议从一开始就把调试日志写成dev_dbg系列后续线上问题排查会轻松很多。6.3netconsole通过网络远程查看内核日志嵌入式开发板上没有串口线或者串口损坏是很常见的窘境。这时候可以利用netconsole把内核日志通过 UDP 发送到远程主机的指定端口上。加载方式modprobe netconsole netconsole/eth0,6666192.168.1.100/其中192.168.1.100是远程日志接收主机的 IP6666是端口。在远程主机上启动nc -u -l 6666就能实时看到开发板的内核日志。这个方案在部分场景下要留意把内核日志发送到网络引入了新的依赖点尤其在网络驱动本身出问题时netconsole可能表现得不可靠。但对“没有任何串口”的板子它是唯一的选择。6.4 日志格式化与审计实践大项目里我习惯给所有驱动日志加上统一前缀例如[eth0]、[mmc0]方便事后按模块过滤。同时约定一定要在日志里带上关键状态值和能用于复现的上下文信息比如中断号、寄存器偏移、操作码。很多线上问题难排查就是因为日志只有简简单单一句“device error”没有任何可供分析的附加信息。另一个实践是给关键路径打印加上函数名和行号printk(KERN_WARNING %s %d: unexpected status 0x%x\n, __func__, __LINE__, status);或者使用pr_warn配合KBUILD_MODNAMEpr_warn(%s: unexpected status 0x%x\n, __func__, status);pr_xxx系列宏会自动带上模块名输出格式更统一代码也更简洁。我强烈建议新代码不要直接裸写printk而是使用pr_emerg、pr_alert、pr_crit、pr_err、pr_warn、pr_notice、pr_info、pr_debug这套封装。7. 几个我亲身踩过、事后觉得值得记下来的坑最后这部分比较个人化分享几个真实项目里让我印象深刻的printk使用教训。有些坑虽然最终都定位到别的问题但printk的误用确实让排查过程变得格外痛苦。7.1 用printk调试中断上下文反被日志误导早期我在调试一个 SPI 控制器驱动时怀疑中断没有触发就在中断处理函数入口加了printk(KERN_INFO spi irq\n)。加载驱动后串口刷出了大量中断日志我以为中断正常就把精力转向了数据错位问题。结果过了很久才意识到那些中断日志大多数是printk输出时串口产生的中断触发的而不是 SPI 外设的中断。也就是说我的日志打印行为本身就在制造中断形成了“打印→串口中断→打印→串口中断”的循环把真实的中断统计完全污染了。从那以后凡是要观察中断频率、中断触发原因的调试我都不再用printk而是用/proc/interrupts配合tracepoint或者简单的计数器变量确认逻辑之后再考虑是否需要打印。7.2 生产环境忘记关调试日志日志占满存储另一个教训来自一次量产设备的问题。为了追一个偶发问题我在驱动里临时加了一行printk每次特定事件触发时打印几十字节内容。当时觉得这点量没什么就带着这行代码发版了。结果某个现场设备运行了几个月后/var/log/kern.log占满了根文件系统整机服务异常。找到根因后发现那个特定事件在实际运行环境中以极高的频率触发而我在代码里没有任何限速措施。这件事给我定了一个规矩任何临时调试日志要么用pr_debug生产默认关闭要么在代码里加#ifdef或者通过module_param做运行时开关坚决不让裸printk常驻在生产代码里。如果你确实需要保留一条低频重要日志也一定要评估它在最坏情况下每秒能触发多少次。7.3 乱加printk导致时序变化偶发 Bug 不再复现内核调试有个很玄学但又真实存在的现象加日志后Bug 反而消失了。原因很容易解释——printk改变了代码执行时序尤其是中断禁用区间、锁等待时间、DMA 完成中断的到达时间都会被影响。时序敏感的 Bug 在日志打印的干扰下不再出现或者从一个表现变成另一个表现。遇到这种“加了日志就不复现”的情况我的第一个反应是检查日志是不是改变了竞态窗口。通常的做法是把打印从热路径移到冷路径比如先在一个变量里记录事件计数定期用一条低频率日志输出汇总值而不是每次都打印。7.4 别在自旋锁里直接printk这个坑很多人知道但还是有人踩。某个驱动里开发者在持有自旋锁的临界区里直接调用printk输出一条调试信息。正常情况下没有出问题但一旦控制台输出速率突然下降比如串口被流控拉低速度console_unlock持锁时间变长其他 CPU 等待该自旋锁的线程全部卡住最终触发内核软锁up watchdog系统报BUG: soft lockup后重启。排查这类问题光靠看代码很难立刻锁定因为只有特定的时序条件才会触发。我的建议很简单自旋锁临界区内只做必要的寄存器读写和状态修改任何日志记录都放到临界区外面。即使只是把日志内容存到局部变量、临界区之后再打印也能大幅降低风险。8. 写在最后的几点个人体会printk是内核调试里最不起眼、但也是最常用的基础设施之一。它不复杂却因为运行环境的特殊性衍生出很多细节。很多人用printk踩坑并不是因为不懂函数用法而是对它的运行机制和边界条件理解不够。我个人在内核开发中的体会是日志不是越多越好而是越精准越好。一条好的内核日志应该能回答“发生了什么”“在哪个上下文”“大概什么原因”这三个问题一条糟糕的日志只会刷屏并掩盖真正有价值的线索。建立这个意识比学会printk的十种写法都更重要。从工具使用角度我建议大家至少把这几项练成肌肉记忆知道console_loglevel的含义和调法知道dmesg和/dev/kmsg的区别知道pr_debug配合dynamic_debug的用法知道在中断、NMI、自旋锁等特殊上下文里如何安全地记录日志。这些能力不会在一次调试中全部用到但会在你需要的时候刚好兜住你。如果你还在被“内核日志为什么没输出”“加了printk系统反而卡死”“不知道从哪里查日志”这些问题困扰希望这篇文章能帮你把那层窗户纸捅破。下一次再遇到内核里的诡异问题先冷静分析上下文再决定在哪一行、用什么级别、以什么频率打一条日志。把printk用对它真的是内核调试里最可靠的伙伴。 深入解析内核printk：日志级别、工作流程与调试实战
搞内核的同学几乎没有人没用过printk。它是内核里最直接的调试手段也是我们在排查宕机、死锁、驱动异常时最先想到的那根救命稻草。这篇文章我想把printk的完整工作流程、日志级别控制方式以及我自己在这上面踩过的一些坑系统梳理一遍希望对刚接触内核开发、或者已经在用但还没完全摸透它的朋友有帮助。printk能做什么一句话概括就是在内核代码任意上下文里输出一段格式化文本把它写进内核环形缓冲区ring buffer并按照配置决定是否同步输出到控制台。它解决了“内核态没有标准C库、不能直接调用printf”这个基础问题是所有内核调试信息的统一出口。无论你是写驱动、改调度器、调文件系统还是追一个神秘的系统重启问题printk都是你理解内核运行状态的第一入口。我尽量把原理讲清楚也会把真实项目里容易踩的坑直接摆出来内容比较多建议收藏后慢慢看。1. 搞懂printk的核心机制它和printf到底差在哪很多刚接触内核的人会把printk当成printf的一个“内核版本”这么理解没错但只对了一半。两者在“格式化输出”这个语义上确实一致可printk的底层运行环境比用户态的printf苛刻得多这就决定了它必须有一套完全不同的实现思路。1.1 从函数签名看起日志级别到底藏在哪printk的函数原型长这样int printk(const char *fmt, ...);乍一看和printf没什么区别但核心奥妙藏在fmt里。printk支持用KERN_xxx这样的宏作为格式串前缀用来声明这条日志的级别。比如printk(KERN_INFO Hello, kernel!\n);这里的KERN_INFO并不是打印时候的一个附加参数而是被编译器通过字符串拼接的方式“粘”到格式串的前面。预处理之后实际传给printk的格式串其实是6Hello, kernel!\n6就是日志级别对应的数字。内核在解析格式串时会先读取尖括号内的数字把它解析成这条日志的级别然后从格式串中剔除掉级别前缀再交给格式化逻辑处理。include/linux/printk.h里定义了完整的级别宏宏数值含义典型场景KERN_EMERG0系统不可用内核崩溃前的最紧急信息KERN_ALERT1必须立即处理严重硬件故障KERN_CRIT2严重错误驱动发生致命错误KERN_ERR3错误功能不可用但系统还能跑KERN_WARNING4警告有风险但影响不大KERN_NOTICE5正常但重要设备热插拔等事件KERN_INFO6信息驱动加载信息KERN_DEBUG7调试信息默认不输出到控制台这 8 个级别覆盖了从“系统马上要完蛋”到“纯吐槽式调试信息”的全部场景。级别越低数字越小紧急程度越高。注意printk还可以用KERN_CONT它表示“接着上一行继续打印”不会插入级别前缀也不会在工作流程里被当作新的一条日志。这个宏在调试多行输出时很有用但也容易造成控制台输出错乱我后面会细说。1.2 为什么内核要维护自己的输出函数用户态的printf依赖于 glibc 提供的缓冲机制、文件描述符、系统调用等一系列设施。但在内核态尤其是在中断上下文、调度器代码、时钟中断里你根本不能依赖这些用户态设施。printk的设计目标非常明确不管当前处于什么上下文也不管中断是否被禁用都要尽量可靠地把日志记录下来。为了做到这一点它不能像printf那样调用write()系统调用也不适合使用复杂的锁机制。因此内核维护了一个全局环形缓冲区__log_buf所有日志先写入这里再异步或同步地转发给控制台设备。这个设计思路和“飞机上的黑匣子”很像日志记录本身要在任何情况下都尽量可靠至于能不能实时显示出来反而是次要的。1.3printk与追踪、远程调试的关系在实际调试中printk通常不是孤立存在的。它和ftrace、kprobes、dynamic_debug这些机制互补。printk适合输出低频但关键的事件比如驱动初始化、错误路径、状态切换ftrace适合追踪高频函数调用比如调度器和网络收包路径。理解这一点能帮你在写日志时做好取舍不要什么函数入口都来一句printk否则生产环境会被日志刷爆。我还见过不少人把printk当成唯一的调试手段遇到问题就到处加打印编译、烧录、重启、看日志循环往复。这种做法效率极低。成熟的调试思路应该是先用ftrace或perf缩小范围再用printk在关键路径上做定点确认最后用kprobes在不能重新编译的现场做动态插桩。后面讲常见坑时我还会提到高频printk带来的性能问题。2. 日志级别控制内核日志分级与设备筛选逻辑日志级别不只是给日志本身贴个标签它实际上参与了“是否写入缓冲区”“是否输出到控制台”两层决策。这个分级体系如果没搞明白最容易出现的现象就是代码里明明写了printkdmesg 里也能看到但控制台屏幕上就是什么都没有。2.1 控制台输出与缓冲区记录是两回事先澄清一个大多数人都困惑过的点printk在默认配置下日志一定会写入内核环形缓冲区也就是你在dmesg里一定能看到。但是否输出到当前控制台终端取决于这条日志的级别是否低于等于当前的console_loglevel。因此我们看到的现象就是dmesg 里有日志但串口终端上没有 →console_loglevel过滤掉了这条日志dmesg 里没有日志 → 可能是log_buf被覆盖、日志级别设置异常、或者根本没执行到printk控制台有输出但 dmesg 看不到 → 这种情况很少见极个别非标准控制台驱动会绕过log_buf直接输出把这两个通道分开理解排查问题会顺畅很多。调试串口看不到日志时第一反应应该是去看console_loglevel而不是怀疑串口接错了线。2.2/proc/sys/kernel/printk的四组数字运行时最常用的控制入口是/proc/sys/kernel/printk。执行cat /proc/sys/kernel/printk你会看到类似这样的输出7 4 1 7这四个数字分别代表位置名称含义1console_loglevel当前控制台接受的最低日志级别实际是最高数值2default_message_loglevel未显式指定级别时printk的默认级别3minimum_console_loglevel控制台级别可被设置的最小值数值上限4default_console_loglevel启动时的默认控制台级别判断逻辑是当一条日志的级别数值l满足l console_loglevel时这条日志才会被输出到控制台。也就是说console_loglevel4时只有KERN_ERR3、KERN_WARNING4以及更紧急的KERN_EMERG0、KERN_ALERT1、KERN_CRIT2级别的日志才会显示在控制台上。级别数值大于 4 的信息如KERN_INFO和KERN_DEBUG只进缓冲区不上屏幕。想临时把控制台级别调到最高让所有日志都刷到串口上只需要echo 8 /proc/sys/kernel/printk注意此时console_loglevel8而有效级别最大是 7所以所有级别的日志都会被输出到控制台。这在调试启动早期问题、驱动加载问题时非常实用但生产环境不要这么干日志刷屏的代价是系统性能肉眼可见地下降。2.3 通过内核启动参数控制日志级别运行时的/proc设置会在重启后失效。如果你想让某次开机从一开始就用高详细度日志可以在内核启动参数里加loglevel8这个参数会在内核初始化早期把console_loglevel设置为 8。与之配合的还有ignore_loglevel设置后所有日志都会输出到控制台相当于无条件放开过滤器。在内核调试阶段我经常在 U-Boot 的 bootargs 里加上这两个参数省得每次进系统还要手动 echo。不过要留意ignore_loglevel是一个“把你按在水里不许起来”级别的调试武器。它无视所有级别过滤可能在极短时间内刷爆串口终端导致真正关键的早期日志被淹没在大量KERN_INFO里。我曾经在一个网络驱动的调试中用过一晚上ignore_loglevel第二天发现串口软件的回显缓冲区里塞了上百MB的数据连终端都卡死了。从那以后我只有在需要抓取特定启动阶段日志时才会短暂开启它。2.4dmesg的三个常用控制参数日志缓冲区也是可以控制的。dmesg本身控制的是用户态读取行为而内核侧对应的节点是/proc/sys/kernel/dmesg_restrict设置为 1只有具有CAP_SYSLOG权限的进程才能读取内核日志缓冲区设置为 0所有用户都能读dmesg从安全角度看内核日志里经常包含内存地址、内核栈信息、驱动内部寄存器值这些信息对攻击者做内核漏洞利用非常有帮助。所以生产环境建议开启dmesg_restrict。另外两个常见参数是参数作用dmesg -n设置控制台日志级别等价于写/proc/sys/kernel/printkdmesg -c清空内核环形缓冲区dmesg -T将时间戳转换为可读的本地时间dmesg -T在把内核日志和应用程序日志做时间关联时非常有用因为内核时间戳默认是系统启动以来的秒数不转成人类时间的话很容易对错时间点。2.5 选择日志级别时的一个判断标准我在给内核代码提交printk时常按下面这个标准选级别这行日志打印时系统是否已经处于不可恢复状态 →KERN_EMERG或KERN_ALERT当前功能是否彻底失败用户操作是否无法完成 →KERN_ERR是否发生了异常情况但系统能继续运行 →KERN_WARNING这是不是一次正常的、值得记录的状态变化 →KERN_INFO这行日志是不是仅在开发调试时需要生产环境最好永远不打印 →KERN_DEBUG其中KERN_DEBUG级别的日志默认在控制台上是完全不可见的因为console_loglevel默认是 7而KERN_DEBUG是 7但这里有一个细节默认配置下KERN_DEBUG级别日志的数据值等于 7而console_loglevel也是 7条件l console_loglevel成立意味着它其实也可能被输出到控制台。因此要真正压住调试日志最好把console_loglevel设为 4 或更低或者用dynamic_debug机制做更精细的控制而不是依赖默认级别过滤。3.printk的工作流程从调用到落盘全链路拆解这一节是我想写这篇文章的主要动机。网上讲printk的文章很多但大多停留在“会用”层面真正讲清楚它从调用到输出全过程的很少。而理解这个流程恰恰是解决各种疑难杂症的基础。3.1 调用链三步走格式化、写缓冲、输出一次完整的printk调用在内核里的处理流程可以简化为三个阶段。第一阶段是格式化。printk内部会调用vprintk把可变参数按照fmt格式化成字符串。这一步和用户态printf的原理基本一致区别在于它对格式串里的%p扩展格式有额外支持。比如%pK会对指针做地址隐藏%px会显示真实指针地址%pS可以把函数指针解析为符号名。这些扩展格式在内核日志里非常常用排错时能够直接看到是哪个函数出了问题。第二阶段是写入环形缓冲区。格式化完成后的字符串会被复制到内核的log_buf中。这个缓冲区是个无锁环形队列准确说是依赖自旋锁保护新日志会写到next_seq对应的位置然后移动写指针。如果写指针追上了读指针旧日志就会被覆盖。这就是为什么 dmesg 里有时会看到日志不连续因为缓冲区空间有限最早的日志已经被新日志冲掉了。第三阶段是控制台输出。内核会根据当前console_loglevel判断这条日志是否需要输出到控制台。如果需要就会被追加到console_seq对应的位置由console_unlock函数负责把缓冲区里等待输出的日志逐个发送给注册到系统里的每个console设备。3.2 预处理器printk_safe与死锁规避你可能听说过printk在 NMI不可屏蔽中断上下文里不能随便用。老版本内核里在 NMI 处理函数中调用printk可能导致死锁因为 NMI 中断可能打断正在持有logbuf_lock的代码路径而 NMI 处理函数里的printk尝试再次获取同一把锁于是发生了锁的递归获取——也就是死锁。后来的内核引入了printk_safe机制在 NMI 或 panic 路径中printk不会直接操作主日志缓冲区而是先把日志写入一个 per-CPU 的临时缓冲区等退出 NMI 或 panic 上下文后再慢慢把这些日志刷入主缓冲区。这样既保证了日志不丢失又避免了死锁。这个机制给我们的启示是在中断上下文、NMI 上下文里调用printk不是绝对禁止的但必须意识到它的成本与延迟并尽量把日志内容压缩到最短。靠printk在 NMI 里写长日志来调试是不太现实的。3.3console设备与console_unlock的互动内核里的console并不只有串口一个。/dev/console、VGA 文本终端、netconsole、甚至早期的earlycon本质上都是注册到内核的console驱动。printk输出日志时会遍历所有已注册的console设备把日志发给每一个。这里有一个常见认知误区多数人以为控制台只有一个。其实系统里可能同时存在多个 console例如ttyS0串口和tty0VGA同时注册。console启动参数只是指定了优先使用的 console 设备并不代表其他设备不接收日志。console_unlock是日志输出的执行者。它在持有console_lock的前提下把待输出的日志逐条取出调用con-write发送给控制台设备。如果控制台设备速度很慢比如串口用了低波特率console_unlock会持有锁相当长的时间。这就会导致一个知名问题其他 CPU 上的printk全部被阻塞整个系统的日志输出被串口拖慢。3.4early_printk内核启动早期的日志去哪了在真正的console驱动注册之前内核需要一个更原始的输出来记录启动早期的信息。这就是early_printk或earlycon存在的意义。earlycon会在非常早的阶段通常是setup_arch附近通过解析 DTB 或启动参数直接初始化一个极简的串口驱动用于输出早期启动日志。这个阶段的日志不经过完整的log_buf流程而是直接往串口寄存器里写字符因此不依赖任何锁或调度器能在极早阶段工作。调试启动早期挂死问题时earlycon几乎是必须的手段。比如你在 ARM 平台调试 U-Boot 到内核过渡阶段的串口日志如果没有earlycon内核第一行可见输出往往要等到标准串口驱动注册完成后才会出现而真正的挂死可能发生在更早的时候你就是看不到任何线索。常见的使用方式是在内核启动参数里加上earlyconuart8250,mmio32,0xfe215000这里的0xfe215000是串口控制器的物理地址具体值要根据芯片手册确定。earlycon的参数格式依赖具体的串口类型最常见的是uart8250也有amba-pl011这类变体不同平台差异较大。3.5 缓冲区的观测与调优内核环形缓冲区的大小在编译时通过CONFIG_LOG_BUF_SHIFT配置。默认值通常是 17表示2^17 128KB。如果你的系统日志量很大或者需要长时间用 dmesg 排查问题可以调大这个值。例如CONFIG_LOG_BUF_SHIFT20也就是 1MB 的缓冲区。需要注意的是log_buf在启动时一次性分配运行中无法调整。编译时设置后需要重新编译内核才能生效。高日志量场景下把缓冲区调大远比频繁dmesg -c更实用因为dmesg -c会清空历史一旦之后出问题需要回看之前的日志就来不及了。4. 实操演示驱动里如何正确使用printk铺垫了这么多原理接下来进入实操。我会用一个最小内核模块演示printk的完整使用流程包括模块代码、级别选择、编译加载以及如何在运行时调整日志级别。4.1 最小示例模块写一个简单的内核模块用不同级别打印几条日志然后观察它们在 dmesg 和控制台上的表现。// printk_demo.c #include linux/init.h #include linux/module.h #include linux/kernel.h static int __init demo_init(void) { printk(KERN_EMERG [demo] EMERG level\n); printk(KERN_ALERT [demo] ALERT level\n); printk(KERN_CRIT [demo] CRIT level\n); printk(KERN_ERR [demo] ERR level\n); printk(KERN_WARNING [demo] WARNING level\n); printk(KERN_NOTICE [demo] NOTICE level\n); printk(KERN_INFO [demo] INFO level\n); printk(KERN_DEBUG [demo] DEBUG level\n); return 0; } static void __exit demo_exit(void) { printk(KERN_INFO [demo] module exit\n); } module_init(demo_init); module_exit(demo_exit); MODULE_LICENSE(GPL);对应的 Makefileobj-m printk_demo.o KDIR : /lib/modules/$(shell uname -r)/build all: $(MAKE) -C $(KDIR) M$(PWD) modules clean: $(MAKE) -C $(KDIR) M$(PWD) clean编译make加载模块sudo insmod printk_demo.ko然后查看日志dmesg | tail -n 20你应该能看到 8 条带[demo]前缀的日志全部出现在 dmesg 中包括KERN_DEBUG。但如果看控制台屏幕默认配置下KERN_DEBUG和KERN_INFO级别的内容很可能不会显示具体要看你的console_loglevel是几。4.2 运行时调整级别观察变化把console_loglevel调到 8再卸载并重新加载模块echo 8 /proc/sys/kernel/printk sudo rmmod printk_demo sudo insmod printk_demo.ko这次控制台上应当能看到全部 8 条日志。如果你的开发机连接了串口终端效果会非常直观。再把级别降到 3echo 3 /proc/sys/kernel/printk sudo rmmod printk_demo sudo insmod printk_demo.ko此时只有KERN_EMERG、KERN_ALERT、KERN_CRIT三条会显示在控制台上其他级别都只会进入 dmesg。这就是现场调试时最常用的手法先用高日志级别跑一遍复现问题再逐步降低级别观察控制台输出的变化。4.3 发射频率控制别让日志刷爆系统我见过有的驱动在每次中断里都调用printk导致的中断延迟能到毫秒级这在高速外设驱动上是完全不可接受的。一个正确的做法是利用内核自带的限速机制printk_ratelimited(KERN_WARNING xxx device timeout, cnt%d\n, cnt);printk_ratelimited默认每秒最多打印 10 条超过部分会被自动丢弃。它内部通过ratelimit_state维护一个时间窗口防止单条热路径日志刷爆缓冲区。与之类似的还有按时间判断的写法if (time_after(jiffies, last_print HZ)) { printk(KERN_WARNING xxx\n); last_print jiffies; }这种手写限速的好处是完全可控坏处是每个驱动都要自己维护状态变量。能用内核的printk_ratelimited就用它别重复造轮子。4.4 动态调试开关dynamic_debug的妙用比printk级别控制更精细的是内核的dynamic_debug机制。它允许你动态开关某个文件、某个函数、甚至某一行代码的pr_debug即KERN_DEBUG输出而无需重新编译模块。如果代码里用的是pr_debug就可以这样做# 打开 printk_demo.c 文件里所有调试输出 echo file printk_demo.c p /sys/kernel/debug/dynamic_debug/control这个能力在生产排障场景里非常有用。生产环境默认不打调试日志一旦出现疑难问题你又不想重新编译内核或加载新模块就可以通过/sys/kernel/debug/dynamic_debug/control精准打开某个文件或函数的调试输出定位完毕后随时关闭。对于运行在内核里、无法随意重启的嵌入式设备来说这几乎是最优雅的日志开关方案。5. 常见问题与排查技巧实录这部分是我最想写的。多年内核开发过程里我在printk上栽过的跟头、帮别人排过的故障几乎都能归到下面几类。把它们整理成速查表你在现场排查时直接对照着查。5.1 症状控制台为什么一直没有输出这是遇到最多的求助帖内容。代码里写了printk(KERN_INFO ...)串口却没反应网上搜索的第一屏答案基本都是“调大 loglevel”。但真相可能有这么几种可能原因判断方法解决方案console_loglevel过滤cat /proc/sys/kernel/printk看第一位数是否小于日志级别echo 8 /proc/sys/kernel/printk控制台设备未注册dmesg 里看console注册信息是否包含你的设备检查console启动参数串口多路复用冲突系统同时存在ttyS0和tty0日志被输出到另一个设备明确指定consolettyS0,115200printk在冷路径上未执行加WARN_ON(1)测试是否触发检查代码执行路径日志被限速丢弃dmesg | grep ratelimit关闭限速或放大限制其中“控制台设备未注册”这条比较隐蔽。内核里 console 驱动的注册时机、以及串口控制台在console参数下的配置对新手来说都是黑盒。我之前调试一块 ARM 板子串口始终没有内核日志查了两天最后发现是 DTS 里stdout-path配置指向了错误的串口实例内核把日志全发到了另一个没接线的 UART 上。这类问题的排查思路是先用dmesg查看printk: console [ttyS0] enabled这类信息确认内核到底认为哪个设备是控制台。5.2 症状系统被printk拖死日志风暴引发性能雪崩printk的性能开销不能小看。尤其当控制台是低速串口时输出一条几百字节的日志可能需要几毫秒时间。如果在高速中断路径或热路径上有大量printk光是输出日志就能耗尽 CPU。我遇到过最经典的案例一个网卡驱动的中断处理函数里每条错误路径都放了printk发生一次短暂网络异常时瞬间触发了几万次中断错误日志串口 115200 波特率根本来不及输出console_unlock长时间持有锁最终导致看门狗超时重启。这类问题的标准解法是先把console_loglevel降到 1尽量让日志只在 dmesg 里记录不输出到控制台用printk_ratelimited限制单位时间内的日志数量在深入调试时再临时打开控制台输出并配合日志级别过滤只保留KERN_ERR及以上。还有一个比较进阶的配置是把启动参数里的console指定为ttynull之类的空设备或者干脆不配置物理控制台。这样日志只进缓冲区不经过任何慢速控制台设备性能损耗降到最低。5.3 症状日志乱序、丢失、显示不完整printk日志的乱序是常态。多核系统里不同 CPU 同时调用printk谁先进入锁内、谁先写入缓冲区并不严格代表日志实际发生的时间先后。如果你需要精确的事件顺序更好的方案是用trace_printk配合 ftrace后者会带上完整的时间戳和 CPU 编号。日志丢失则有两种常见原因。第一种是环形缓冲区被新日志覆盖早期日志被冲掉尤其在ignore_loglevel或dynamic_debug大量开启时第二种是printk_ratelimited限速后丢弃可在 dmesg 中搜索printk: N messages suppressed之类的提示确认。显示不完整的问题多出现在并发输出时多个 CPU 的日志交织在一起串口控制台在输出过程中没有锁保护某条日志被另一条打断。在KERN_CONT场景下尤其明显。我自己遇到过驱动里连续用多次KERN_CONT打印一个寄存器 dump结果中间混入了其他 CPU 的中断日志整个 dump 根本没法解析。后来改成一次性拼接成单行打印问题才解决。5.4 症状printk引发死锁或系统挂死在中断上下文、自旋锁临界区、NMI 上下文使用printk需要额外小心。尽管现代内核在多数场景下做了优化仍然存在几个特殊场景在中断处理函数里持有spinlock的同时调用printk而printk的输出设备驱动又需要同一个锁就可能造成死锁串口控制台的write函数内部如果使用了和你的临界区冲突的锁也会触发同样的问题NMI 上下文调用printk虽然经过printk_safe做了缓冲但如果你在 NMI 里同时操作了其他共享资源依然有风险。这类问题的排查没有捷径只能靠两点第一明确当前代码处于什么上下文第二严格控制printk只在明确的、锁无关的路径上使用。在自旋锁保护的临界区内宁可先把日志内容存到一个临时变量里出临界区后再printk也不要冒险在临界区内输出日志。5.5 症状内核启动早期没有日志很多嵌入式开发者遇到过这样的现象开发板从 U-Boot 跳转到内核后串口屏幕上要过好几秒才出现第一行日志或者直接一片空白内核似乎“静默启动”。如果内核最终能跑起来只是早期日志缺失常见原因是标准 console 驱动注册太晚。此时应该检查是否使用了earlycon并确认参数里的地址、时钟、波特率是否正确。注意有的 SoC 串口需要初始化相应的 pinmux 或时钟否则即使地址对了也无法输出。如果内核启动直接挂死且没有earlycon可能连第一行日志都看不到。这时候需要回到 U-Boot 阶段确认映像加载地址、DTS 配置、串口设置是否匹配。我在带过的一位新人身上见过一个经典案例他调了三天“内核启动挂死”最后发现 U-Boot 里bootargs没传consolettyS0,115200内核输出全走 VGA而板子根本没接显示器。5.6 症状生产环境不该泄露的信息被打印出来了printk里最容易犯的安全错误是不小心打印了敏感数据。内核日志可能通过/dev/kmsg被用户态读取也可能被netconsole发到远程日志服务器如果再叠加dmesg_restrict0任何本地用户都能看到日志内容。因此在内核日志里输出缓冲区内容、寄存器原始值、内存地址时一定要谨慎。尤其是指针地址默认情况下%p会被内核替换为hashed值这是CONFIG_KALLSYMS和kptr_restrict共同作用的结果。如果你确实需要打印原始指针做调试必须显式使用%px并且确认kptr_restrict的值不会带来安全风险cat /proc/sys/kernel/kptr_restrict设置为 2 时只有 root 才能查看原始地址且必须拥有CAP_SYSLOG权限。生产环境建议保持这个值。6. 工具链与扩展让printk输出更便于分析printk输出的原始文本日志在复杂问题面前往往不够直观。做内核调试久了我习惯配合几个工具一起用效率提升非常明显。6.1dmesg的过滤和时间转换dmesg本身支持按级别过滤。只看错误及以上级别dmesg --levelerr,crit,alert,emerg只看某个模块相关的日志dmesg | grep -i demo如果需要把内核时间戳转换成人类可读的时间dmesg -T在对比多个事件的发生顺序时我通常先把dmesg -T的输出重定向到文件然后在文件里用时间戳做关联分析。注意dmesg -T的时间基准是系统启动时刻如果系统运行了很久还需要结合uptime确认启动时间。6.2 内核动态打印调试开关前面提到的dynamic_debug值得再展开一下。它的控制文件在/sys/kernel/debug/dynamic_debug/control查看当前已开启的动态调试点cat /sys/kernel/debug/dynamic_debug/control按模块开启echo module printk_demo p /sys/kernel/debug/dynamic_debug/control按函数开启echo func demo_init p /sys/kernel/debug/dynamic_debug/control这个机制要求代码里用的是pr_debug、dev_dbg这类可动态控制宏而不是裸的printk(KERN_DEBUG)。如果你在维护一个大型驱动建议从一开始就把调试日志写成dev_dbg系列后续线上问题排查会轻松很多。6.3netconsole通过网络远程查看内核日志嵌入式开发板上没有串口线或者串口损坏是很常见的窘境。这时候可以利用netconsole把内核日志通过 UDP 发送到远程主机的指定端口上。加载方式modprobe netconsole netconsole/eth0,6666192.168.1.100/其中192.168.1.100是远程日志接收主机的 IP6666是端口。在远程主机上启动nc -u -l 6666就能实时看到开发板的内核日志。这个方案在部分场景下要留意把内核日志发送到网络引入了新的依赖点尤其在网络驱动本身出问题时netconsole可能表现得不可靠。但对“没有任何串口”的板子它是唯一的选择。6.4 日志格式化与审计实践大项目里我习惯给所有驱动日志加上统一前缀例如[eth0]、[mmc0]方便事后按模块过滤。同时约定一定要在日志里带上关键状态值和能用于复现的上下文信息比如中断号、寄存器偏移、操作码。很多线上问题难排查就是因为日志只有简简单单一句“device error”没有任何可供分析的附加信息。另一个实践是给关键路径打印加上函数名和行号printk(KERN_WARNING %s %d: unexpected status 0x%x\n, __func__, __LINE__, status);或者使用pr_warn配合KBUILD_MODNAMEpr_warn(%s: unexpected status 0x%x\n, __func__, status);pr_xxx系列宏会自动带上模块名输出格式更统一代码也更简洁。我强烈建议新代码不要直接裸写printk而是使用pr_emerg、pr_alert、pr_crit、pr_err、pr_warn、pr_notice、pr_info、pr_debug这套封装。7. 几个我亲身踩过、事后觉得值得记下来的坑最后这部分比较个人化分享几个真实项目里让我印象深刻的printk使用教训。有些坑虽然最终都定位到别的问题但printk的误用确实让排查过程变得格外痛苦。7.1 用printk调试中断上下文反被日志误导早期我在调试一个 SPI 控制器驱动时怀疑中断没有触发就在中断处理函数入口加了printk(KERN_INFO spi irq\n)。加载驱动后串口刷出了大量中断日志我以为中断正常就把精力转向了数据错位问题。结果过了很久才意识到那些中断日志大多数是printk输出时串口产生的中断触发的而不是 SPI 外设的中断。也就是说我的日志打印行为本身就在制造中断形成了“打印→串口中断→打印→串口中断”的循环把真实的中断统计完全污染了。从那以后凡是要观察中断频率、中断触发原因的调试我都不再用printk而是用/proc/interrupts配合tracepoint或者简单的计数器变量确认逻辑之后再考虑是否需要打印。7.2 生产环境忘记关调试日志日志占满存储另一个教训来自一次量产设备的问题。为了追一个偶发问题我在驱动里临时加了一行printk每次特定事件触发时打印几十字节内容。当时觉得这点量没什么就带着这行代码发版了。结果某个现场设备运行了几个月后/var/log/kern.log占满了根文件系统整机服务异常。找到根因后发现那个特定事件在实际运行环境中以极高的频率触发而我在代码里没有任何限速措施。这件事给我定了一个规矩任何临时调试日志要么用pr_debug生产默认关闭要么在代码里加#ifdef或者通过module_param做运行时开关坚决不让裸printk常驻在生产代码里。如果你确实需要保留一条低频重要日志也一定要评估它在最坏情况下每秒能触发多少次。7.3 乱加printk导致时序变化偶发 Bug 不再复现内核调试有个很玄学但又真实存在的现象加日志后Bug 反而消失了。原因很容易解释——printk改变了代码执行时序尤其是中断禁用区间、锁等待时间、DMA 完成中断的到达时间都会被影响。时序敏感的 Bug 在日志打印的干扰下不再出现或者从一个表现变成另一个表现。遇到这种“加了日志就不复现”的情况我的第一个反应是检查日志是不是改变了竞态窗口。通常的做法是把打印从热路径移到冷路径比如先在一个变量里记录事件计数定期用一条低频率日志输出汇总值而不是每次都打印。7.4 别在自旋锁里直接printk这个坑很多人知道但还是有人踩。某个驱动里开发者在持有自旋锁的临界区里直接调用printk输出一条调试信息。正常情况下没有出问题但一旦控制台输出速率突然下降比如串口被流控拉低速度console_unlock持锁时间变长其他 CPU 等待该自旋锁的线程全部卡住最终触发内核软锁up watchdog系统报BUG: soft lockup后重启。排查这类问题光靠看代码很难立刻锁定因为只有特定的时序条件才会触发。我的建议很简单自旋锁临界区内只做必要的寄存器读写和状态修改任何日志记录都放到临界区外面。即使只是把日志内容存到局部变量、临界区之后再打印也能大幅降低风险。8. 写在最后的几点个人体会printk是内核调试里最不起眼、但也是最常用的基础设施之一。它不复杂却因为运行环境的特殊性衍生出很多细节。很多人用printk踩坑并不是因为不懂函数用法而是对它的运行机制和边界条件理解不够。我个人在内核开发中的体会是日志不是越多越好而是越精准越好。一条好的内核日志应该能回答“发生了什么”“在哪个上下文”“大概什么原因”这三个问题一条糟糕的日志只会刷屏并掩盖真正有价值的线索。建立这个意识比学会printk的十种写法都更重要。从工具使用角度我建议大家至少把这几项练成肌肉记忆知道console_loglevel的含义和调法知道dmesg和/dev/kmsg的区别知道pr_debug配合dynamic_debug的用法知道在中断、NMI、自旋锁等特殊上下文里如何安全地记录日志。这些能力不会在一次调试中全部用到但会在你需要的时候刚好兜住你。如果你还在被“内核日志为什么没输出”“加了printk系统反而卡死”“不知道从哪里查日志”这些问题困扰希望这篇文章能帮你把那层窗户纸捅破。下一次再遇到内核里的诡异问题先冷静分析上下文再决定在哪一行、用什么级别、以什么频率打一条日志。把printk用对它真的是内核调试里最可靠的伙伴。