LWN: printk()的难点以及解决方案

点击上方蓝色“Linux News搬运工”关注我们~

Why printk() is so complicated (and how to fix it)

By Jonathan Corbet

LPC

内核的printk()函数在普通人想象中应该是个非常简单的函数，只要处理好字符串格式化然后输出到kernel log里就好。其实这里隐藏着非常多的复杂问题，28年过去了，kernel开发者对printk()仍然非常不满意。在2019 Linux Plumbers Conference会议上，John Ogness介绍了printk()的实现复杂在什么地方，以及近期的相关工作。

这里的核心问题是kernel代码必须要能在任何上下文（context）都可以调用printk()。在atomic context调用的话需要确保printk()不能导致阻塞，而在non-maskable interrupts (NMIs)上下文调用的话甚至连spinlock也不能用了。同时，系统出错时printk()的输出内容非常重要，开发者不愿意丢掉任何一行信息，哪怕系统就要crash或者hang住了。这些信息要在console设备上打印出来，通常是一个串口，或者是经过显卡显示在屏幕上，或者通过网络连接送出来。此外，printk()不应该干扰系统的正常执行过程。

他总结说，printk()看起来简单并且到处都在用，而它的底层实现其实跟系统的方方面面都搅在一起。

The path to the present

Ogness介绍了printk()的发展史，可以参见他的ppt（https://www.linuxplumbersconf.org/event/4/contributions/290/attachments/276/463/lpc2019_jogness_printk.pdf）。第一版kernel v0.0.1发布时就包含了printk()，当时这个函数是同步行为（synchronous），会直接把信息利用一些汇编代码写入TTY端口。这种行为很可靠，不过无法扩展，今后kernel开始支持多CPU之后就必须要更改这里的行为了。

内核 0.99.7a版本里就增加了console registration（注册机制）。在0.99.13k版本里增加了“log level”设置。在2.4.0里面增加了bust_spinlocks()机制，用来避免系统crash以至于无法正常工作的时候还要进行不必要的等待spinlock操作。从2.4.10开始，printk()也支持异步（asynchronous）工作模式了。2.6.24版本之前，printk()时不时会导致偶发的特别高的延迟，在这个版本里面大家会在latency tracer里面忽略printk()，避免干扰人们的分析。3.4版本里增加了structured logging，sequence numbers，以及/dev/kmsg接口。4.10里面增加了"safe buffers"机制，用来在NMI context上下文来做输出。在4.15版本里，修复了一个bug可能导致CPU不停地输出信息。在5.0版本里，加入了caller identifier（调用者标记）功能。

也就是说这么多年来printk()一直在持续改进，不过仍然有很多遗留问题。其中之一就是关于用来保护ring buffer的raw spinlock，它没法在NMI上下文调用，因此printk()必须要先输出到不依赖lock的safe buffer里。这样会导致message最终被copy到真正的ring buffer的时候更新的timestamp不精确，也可能会导致message丢失，或者导致CPU异常offline的时候buffer没有被刷出去。

此外console驱动这边也有麻烦，因为它不仅很慢，并且还是在关中断模式下调用的。大多数console device设计时都没有考虑过kernel panic的场景，在这种最需要它的场景下表现得不够可靠。

其他还有个问题是printk()对各个级别的log一视同仁。某些频繁输出的信息如果被错误设置成urgent级别，可能会导致latency问题，从而让大家会调整level来导致丢失其他的urgent信息。虽然我们修复了一个CPU被卡住持续输出log的bug，不过最后一个CPU来接管log输出的时候也可能会被大量工作塞满。这时可能每个printk()调用都会费不少时间。而bust_spinlocks()机制其实就是忽略所有lock，寄希望于系统仍能正常工作。他觉得应该还有更好的方案解决这个问题。

The better way

Ogness认为过去多年printk()所面临的这些问题现在已经聚焦在了“非侵入性”（Non-interference，不干扰系统运行）和“可靠性”这两方面的矛盾了。大家已经明白了没法在同一个地方满足这两方面的需求。那么一个比较好的方案就是把它们分开。非侵入性的实现，要求让printk()变得可以被抢占，ring buffer要在各个context下都可靠，还有把console处理移到专用的kernel thread上去。而可靠性要求，则需要提供一个synchronous channel来放重要的信息，以及一个“atomic console"概念，还有要着重处理"emergency messages"紧急消息。

两个目标都依赖printk()的ring buffer。这个buffer有多个同时进行的reader，仅有一个writer。这个buffer在一片连续内存里，通过一个特别的可以在一个CPU上获取多次的spinlock（"CPU lock"）来保护着。这个锁他觉得更像是以前旧版本kernel里非常著名的那个big kernel lock。

printk()开发时也按照kernel开发里面比较好的工作模式来做，首先创建了一个新的ring buffer来解决当前方案里的问题。这个ring buffer是完全不用锁保护的，支持多个reader和writer，在任意上下文进行访问。metadata则会通过一个单独的描述机制来记录，包括记录时间戳以及message的序列号等。这个ring buffer有很多优势，不过也非常复杂，使用了至少9对memory-barrier操作，很难写好相关的文档，也很难review，他也没觉得这里实现的支持多个writer（导致复杂性大增）有什么现实需求。

新增了每个console都有一个独立的kernel thread，用来把printk()调用者和console相关处理工作分隔开。每个console现在都可以按自己的速度尽快打印，每个都有自己独立的log level设置。这样就把console的责任简化了很多，不过还是有一些lock相关的问题，以及大家有点怀疑这种基于线程的实现方式是否能保证任何情况都把message输出出去。不过Ogness提醒说，可靠性是靠其它机制保证的，这里每个console的独立线程是用来改善非侵入性（non-interference）需求的机制。

对于可靠性，他的计划是增加一个"atomic console"概念。支持这个功能的console都会有一个write_atomic()功能函数，可以在任何上下文调用都不会出错。这个函数内部实现是完全同步的操作，也就是说会大大拖慢系统，因此只有emergency（紧急）信息才应该用它。不过好处就是不再需要bust_spinlocks()，也不需要依赖oops_in_progress这个全局变量了。

这里的难点在于在console驱动里面正确实现write_atomic()。他基于8250 UART实现了一个console驱动，工作量不小。肯定会有不少系统上完全没有atomic-console功能，这样就需要其他一些方案了，例如创建一个特殊的console来写入一块内存区域，或者试着在atomic context上下文之外才进行synchronous打印，或者干脆就回退到原来的方案进行打印。

之所要使用atomic console，主要是为了能正确处理“emergency message”。这里最大的问题就是要判断哪些消息是重要信息。log level有点算是一个灰色地带，不是一个可靠的翻案。还有其他一些情况下printk()的输出是非常重要的，正确的实现方法应该是跟BUG()等这些函数关联起来。

Ogness指出这个工作在今年2月份开始，目前的版本是8月份发布的。上面提到的绝大多数功能都已经实现出来了，开发者们可以上手把玩一下了。

Further discussion

后来的一个session，LWN编辑没能参加。Ogness发出来的总结（https://lwn.net/ml/linux-kernel/87k1acz5rx.fsf@linutronix.de/）里面包含了大家达成一致的一些观点。他也感谢大家参与这个会议，认为“省下了需要用来读写邮件的几百个小时”。

从上述总结来看，后面会用Petr Mladek实现的另一种ring buffer方案，这个ring buffer实现更加简单，review也更容易做。Ogness把他的工作也移植到这个ring buffer上，证明是可行的。而每个console独立的内核线程会继续使用。

这里提到的“emergency message"概念，最后被“emergency state”观点取代了，它可以反应整个系统的状态。当kernel在这个状态市，所有信息都会通过尽可能地使用write_atomic()函数来输出出来。CPU lock会继续使用，不过目的变成了当系统在emergency state状态时，同步（synchronize）所有console线程。

还有其他一些改动，包括增加了pr_flush()函数，用来等待直到所有信息都被输出给console了。目前修改后的patch还没有发出来，不过会很快了。

[Your editor thanks the Linux Foundation, LWN's travel sponsor, for supporting his travel to this event.]