kernel: the boot transcript on screen, every line timestamped

Without serial and without working USB storage, a slow real-hardware
boot is undiagnosable — 'stabbing in the dark'. Two changes end that:

The log renderer stamps every line with boot-relative seconds
([  12.045] ...), so every surface — serial, debugcon, and now the
screen — is a readable timeline. And the framebuffer console registers
as an ordinary log sink at boot: kernel AND userspace lines (device
bring-up, fat mounts, logger announcements) show live on screen until
the display service claims the framebuffer, which flips the console's
suppression and silences the sink automatically — the display-owns-the-
screen design is unchanged in normal operation; the console now simply
narrates the part of boot that happens before there IS a display.

On the machine that motivated this, the next boot will show by eye
where the minutes go — including whether the USB chain ever brings
storage up, and whether screen drawing itself crawls (the latent
non-write-combining framebuffer suspect: if these very lines paint
slowly, that's the answer).
This commit is contained in:
Daniel Samson
2026-07-21 19:09:34 +01:00
parent ffa45edc8b
commit a91365b3d9
2 changed files with 19 additions and 4 deletions
+12 -4
View File
@@ -126,7 +126,7 @@ fn appendLocked(pid: u32, name: []const u8, level: abi.KlogLevel, now: u64, byte
const line_complete = newline != null or level != .raw;
if (line.len != 0 or line_complete)
_ = ring.append(pid, name, level, now, line, line.len > abi.klog_maximum_message);
render(pid, name, level, line, line_complete);
render(pid, name, level, now, line, line_complete);
rest = if (newline) |i| rest[i + 1 ..] else rest[rest.len..];
}
}
@@ -136,7 +136,7 @@ fn appendLocked(pid: u32, name: []const u8, level: abi.KlogLevel, now: u64, byte
/// own "name: " prefixes until the std.log migration). Leveled (std.log)
/// records get a kernel-rendered "<name>: " prefix at line start — err/warn/
/// debug also get their level spelled out.
fn render(pid: u32, name: []const u8, level: abi.KlogLevel, line: []const u8, line_complete: bool) void {
fn render(pid: u32, name: []const u8, level: abi.KlogLevel, now: u64, line: []const u8, line_complete: bool) void {
if (sink_count == 0) return;
if (line.len == 0 and !line_complete) return;
// Compose the whole rendered piece first and emit it in ONE sink call per
@@ -149,6 +149,14 @@ fn render(pid: u32, name: []const u8, level: abi.KlogLevel, line: []const u8, li
used += 1;
at_line_start = true;
}
if (at_line_start) {
// Every line starts with its boot-relative time: the live transcript
// (serial AND the on-screen boot console) is a readable timeline —
// which is how a slow real-hardware boot gets diagnosed by eye.
const seconds = now / 1_000_000_000;
const millis = (now / 1_000_000) % 1000;
used += (std.fmt.bufPrint(buffer[used..], "[{d:>4}.{d:0>3}] ", .{ seconds, millis }) catch buffer[used..used]).len;
}
if (at_line_start and level != .raw) {
used += place(buffer[used..], name);
used += place(buffer[used..], ": ");
@@ -169,8 +177,8 @@ fn render(pid: u32, name: []const u8, level: abi.KlogLevel, line: []const u8, li
open_line_pid = pid;
}
/// newline + name + ": warning: " + a full payload line + newline.
const render_buffer_size = 1 + abi.maximum_process_name + 11 + abi.klog_maximum_message + 1;
/// newline + timestamp + name + ": warning: " + a full payload line + newline.
const render_buffer_size = 1 + 16 + abi.maximum_process_name + 11 + abi.klog_maximum_message + 1;
fn place(destination: []u8, bytes: []const u8) usize {
const n = @min(destination.len, bytes.len);