From a91365b3d919ed066796b79ddcf0e816f9c0c979 Mon Sep 17 00:00:00 2001
From: Daniel Samson <12231216+daniel-samson@users.noreply.github.com>
Date: Tue, 21 Jul 2026 19:09:34 +0100
Subject: [PATCH] kernel: the boot transcript on screen, every line timestamped
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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).
---
 system/kernel/kernel.zig |  7 +++++++
 system/kernel/log.zig    | 16 ++++++++++++----
 2 files changed, 19 insertions(+), 4 deletions(-)

diff --git a/system/kernel/kernel.zig b/system/kernel/kernel.zig
index 4806f7c..6bfa459 100644
--- a/system/kernel/kernel.zig
+++ b/system/kernel/kernel.zig
@@ -162,6 +162,13 @@ fn kmain(boot_information: *const BootInformation) noreturn {
     // uncached crawl). Routine boot output goes only to the log; this console now exists for
     // early-boot and fatal (`fatal`/panic) output, until the display service takes over.
     console.init(fb);
+    // The console joins the log sinks: the boot transcript — kernel AND
+    // userspace lines, each timestamped by the renderer — shows on screen
+    // until the display service claims the framebuffer (which flips the
+    // console's `suppressed` and silences this sink). On a machine with no
+    // serial this is the only live view of the boot, and a slow boot becomes
+    // diagnosable by eye: the timeline is right there.
+    if (console.present()) log.addSink(console.write);
     log.write(if (console.present())
         "/system/kernel: framebuffer ready (early-boot + fatal fallback; the display service drives it in normal operation)\n"
     else
diff --git a/system/kernel/log.zig b/system/kernel/log.zig
index ce1d418..b5c3d63 100644
--- a/system/kernel/log.zig
+++ b/system/kernel/log.zig
@@ -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);