Operating Systems · Kernel Engineering

Kernel Logging: The Ring Buffer Behind printk

Why kernel messages are written to a fixed circular buffer instead of a file, how records are framed, and what happens when the console cannot keep up with the producer.

Kernel code cannot open a file, cannot allocate a buffer whose size it does not know in advance, and frequently runs in contexts where blocking is illegal. Yet it must be able to report what it is doing, including while handling an interrupt or after a fault has already corrupted state. The mechanism that satisfies those constraints is a fixed-size circular buffer in kernel memory, written to by any context without sleeping, and drained by readers that may be slow, absent, or dead.

Why the log cannot be a file

A userspace logger writes to a file descriptor and lets the filesystem handle durability. Every step of that is unavailable to the kernel. Opening a file needs a path lookup, which may need to read a directory from storage, which may need to block. Writing needs page allocation, which can fail or trigger reclaim, which can call back into filesystem code. Any of these can occur while the caller holds a spinlock, or inside an interrupt handler where scheduling is not permitted at all.

The buffer approach removes all of it. The log is memory that exists before anything else does, allocated during early boot from a static array or from a reserved region. Writing to it is a copy plus a couple of index updates under a lock, or under per-CPU buffers with no shared lock at all. No allocation, no blocking, no dependency on the filesystem being mounted. The cost is that the log has a fixed maximum size and old records are destroyed as new ones arrive, which is exactly the behaviour wanted for a diagnostic channel: the most recent history is more valuable than the complete one.

The size is fixed at boot, commonly in the low hundreds of kilobytes for a general-purpose kernel and larger on systems where the log is the only record of what happened. Two knobs set it: a kernel parameter that requests an explicit size, and a build-time option that supplies the default when no request is made. There is no supported way to grow the buffer afterwards; a system that needs more announces it at boot or accepts the smaller default, and a resize attempt is not a matter of growing an array but of replacing a structure every earlier reference points into.

Record framing

The buffer is not a byte stream. Each entry carries a header before its text: a sequence number, a timestamp, the facility and level encoded in a single word, and the length of the message body. The sequence number is monotonic and never wraps in practice within a boot; readers use it to detect that they lost records, because a reader slower than the producer will find that the oldest entries it had not yet consumed have been overwritten. The alternative (silently returning whatever survives) makes a gap indistinguishable from a quiet period, which is precisely the situation where the log matters most.

The level is a small integer, and the set is fixed: emergency, alert, critical, error, warning, notice, informational, debug. It is carried through the whole path, because the console filter compares it against a threshold and the reader may filter on it as well. A message printed with the wrong level is not merely mislabelled; it either floods the console or is invisible.

A record has a maximum length. Anything longer is split across several entries, each with its own header and continuation flag, so a reader reassembling the text can tell where a record genuinely ended. On current kernels the ceiling on the text of one record is one kilobyte, a quarter of the common page size, which keeps a single write from monopolising the buffer.

The text is formatted into memory that printk owns, never into the caller’s stack. The producer reserves space for the record in the ring and formats directly into that reserved region, so a call costs no allocation and no large stack frame. That is why a %s with an unbounded string is a real hazard: the formatting truncates at the record boundary rather than overflowing, but the truncation is silent, and the part that mattered may be the part that was cut. Kernel format strings deliberately omit %f, because floating point is not usable in kernel context on many architectures; a message that needs a fractional value prints it as scaled integers.

#include <linux/kernel.h>
#include <linux/module.h>

static int __init log_demo_init(void)
{
	/* Level is encoded in the format prefix; KERN_WARNING is "4". */
	pr_warn("demo: buffer holds %u bytes\n", 4096u);

	/* Ratelimited: suppresses repeats from a hot path. */
	pr_info_ratelimited("demo: repeated message\n");
	return 0;
}

The console problem

Writing to the ring buffer is cheap. Getting the text onto a serial port or a framebuffer is not: a polled UART transmits one character at a time at a fixed rate, so a 100-character line occupies the CPU for a duration proportional to the baud rate. At 115200 baud, a single character takes on the order of 87 microseconds, and a hundred characters nearly nine milliseconds. A thousand messages during a device probe become seconds of stalled boot.

The kernel separates the two. Producers write to the ring and, if a console is registered, attempt to hand the record to it. If the console’s lock is already held (by a CPU that is in the middle of printing, or by a CPU that died while holding it), the producer does not wait. It marks the record as pending console output and returns. A dedicated kernel thread later walks the ring and prints whatever was deferred. This is why a system that has crashed hard can show an incomplete log on the console while the full text is present in the buffer and recoverable afterwards.

Two mechanisms govern the flood. The first is a rate limit: printk_ratelimit throttles all callers against one shared state, while the _ratelimited print variants give each call site a state of its own, so two hot paths do not consume each other’s allowance. Either form reports how many messages it suppressed once the burst is over. The second is a global limit on how many messages per unit time may reach the console, with the excess queued. Both exist because the failure mode they prevent is worse than the messages they drop: a driver printing on every packet can turn a slow network into an unresponsive machine, and a filesystem printing on every block can turn a full disk into a hang.

Early boot has its own path. Before the console infrastructure is initialised, messages go to an early console (a serial port configured from the command line, or a firmware-provided output), which is polled and blocking by necessity. This is the only window in which printing is genuinely synchronous, and it is also where a message about a very early failure can appear. After the real console takes over, the ring is replayed to it so that the early messages are not lost.

Reading the log back out

Userspace reads the buffer through syslog(2), the call that predates the syslog daemon and shares its name. The command set includes reading and clearing the buffer, reading and clearing in one operation, querying how much is unread, and setting the console level threshold. dmesg is a thin wrapper over the first of these. The call returns records in order, and a reader that keeps its own copy of the last sequence number it saw can request only what is new since then, which is how a logger avoids re-reading the whole buffer on each poll.

/dev/kmsg offers a second path with different semantics: it is a character device that can be opened, read, and written. Reading yields one record per read, in the same format, and the file position tracks the sequence number so that a reader can seek to a specific record. Writing to it injects a message into the log with a chosen facility and level, which is how userspace can contribute to the kernel’s record without a system call of its own.

The buffer is also mirrored to /proc/kmsg, which is single-reader: the first process to open it consumes records and later readers see nothing new. That behaviour is a leftover from the era when one daemon owned the log, and it is why a second reader of /proc/kmsg appears to hang. /dev/kmsg has no such restriction.

The console threshold deserves attention because it is the usual cause of “the message is in dmesg but never appeared on the console”. The default threshold on a general-purpose kernel is 7, and the comparison is strict: a message reaches the console when its level is numerically lower than the threshold, so everything except debug output prints by default, boot chatter included. Distributions and boot loaders commonly lower it, a boot-time setting can raise or lower it further, and a command-line option for quiet boot drops it to 4, which suppresses warnings as well because 4 is not strictly less than 4. Changing the threshold with a boot parameter or at runtime changes only what reaches the console, never what enters the buffer. Confusing the two filters (the buffer’s, which does not exist, and the console’s, which does) is the most common misunderstanding of the subsystem.

What the buffer cannot do

It cannot survive a reboot, which is why persistent logging is done by a userspace daemon that reads the buffer continuously and writes to storage. Records produced after that daemon stops reading, or after storage becomes unavailable, exist only in memory and disappear. A crash that prevents the daemon from flushing leaves the last records visible only on the console, if a console was attached and fast enough.

It also cannot be trusted to be complete in a crash. The buffer is written without ordering guarantees against the console, so the console output may lag the buffer, and a panic that stops the machine mid-drain leaves the console truncated at an arbitrary point. The buffer contents, if they can be recovered (by a crash dump mechanism such as the one described in kexec and crash dump capture) are more complete than the console was. That is the practical argument for capturing memory rather than relying on a serial line.

The producer side has one further constraint that matters when reading a report: a message is often the only record that a code path ran. Tracing mechanisms that record function entry and exit, described in dynamic tracing by rewriting instructions, produce their output through this same buffer, so a log that is truncated by a slow console loses trace data as well as messages.

References

  1. Linux kernel documentation: printk — Linux kernel documentation
  2. proc(5) — Linux man-pages project
  3. syslog(2) — Linux man-pages project