klog: [ssss.mmm] millisecond timestamps from the PIT

- interrupts::uptime_ms(): monotonic ms since boot — the 100 Hz PIT
  tick (10 ms) plus interpolation from the PIT's live 1.19 MHz
  down-counter (read twice around the tick load; a count jump means a
  tick fired between reads) for true sub-ms resolution.  TICKS widened
  AtomicU16 -> AtomicU64 (u16 wrapped after ~11 min).
- PIT_READY gates interpolation until interrupts::init configures the
  timer, so early-boot lines are deterministically [0000.000] instead
  of uninitialised-PIT noise; klog clamps timestamps monotonic.
- The CMOS RTC cannot provide milliseconds (1 Hz BCD device, seconds
  only) — millis come from the PIT.
- klog stores ms per line at append time; dump format is now
  '[0000.123] 000000  === rsnix boot ===' (user-specified format).

Verified in QEMU: first line [0000.000], Phase-2 lines show real
monotonic ms (fs: vfs ready at [0000.519], self-test [0000.524]),
per-dump monotonicity, boot.log persists timestamps, test-disk round
trip fsck-clean.

1 files changed, 24 insertions, 6 deletions

diff --git a/rsnix/src/klog.rs b/rsnix/src/klog.rs
index 1e23460..0c7dc06 100644
--- a/rsnix/src/klog.rs
+++ b/rsnix/src/klog.rs
@@ -32,6 +32,10 @@ struct Ring {
     count: usize,
     /// Slot the next line will be written to (oldest once full).
     next: usize,
+    /// Highest timestamp seen, so the log stays monotonic even before
+    /// the timer is running (early-boot PIT reads are uninitialised).
+    last_ms: u64,
+    ms: [u64; MAX_LINES],
     lens: [u8; MAX_LINES],
     bytes: [[u8; MAX_LINE]; MAX_LINES],
 }
@@ -41,6 +45,8 @@ static mut RING: Ring = Ring {
     dropped: 0,
     count: 0,
     next: 0,
+    last_ms: 0,
+    ms: [0; MAX_LINES],
     lens: [0; MAX_LINES],
     bytes: [[0; MAX_LINE]; MAX_LINES],
 };
@@ -49,10 +55,16 @@ fn ring() -> &'static mut Ring {
     unsafe { &mut *core::ptr::addr_of_mut!(RING) }
 }
 
-/// Append one line to the ring (line-oriented; newlines are stripped).
-/// Truncated at MAX_LINE bytes.  Never allocates, never logs.
-pub fn append(line: &str) {
+/// Append one line to the ring with its timestamp in ms (line-oriented;
+/// newlines are stripped).  Truncated at MAX_LINE bytes.  Never
+/// allocates, never logs.  Timestamps are clamped to be monotonic.
+pub fn append(line: &str, mut ms: u64) {
     let r = ring();
+    if ms > r.last_ms {
+        r.last_ms = ms;
+    } else {
+        ms = r.last_ms;
+    }
     let b = line.as_bytes();
     let n = b.len().min(MAX_LINE);
     if r.count == MAX_LINES {
@@ -60,6 +72,7 @@ pub fn append(line: &str) {
     } else {
         r.count += 1;
     }
+    r.ms[r.next] = ms;
     r.bytes[r.next][..n].copy_from_slice(&b[..n]);
     r.lens[r.next] = n as u8;
     r.next = (r.next + 1) % MAX_LINES;
@@ -68,11 +81,14 @@ pub fn append(line: &str) {
 
 /// Append the formatted output of a `serial_println!` — the macro hook.
 /// `fmt::Write` may deliver the line in several chunks, so accumulate
-/// into one line buffer first, then append the whole line.
+/// into one line buffer first, then append the whole line.  The
+/// timestamp is taken when the line is emitted (monotonic ms since
+/// boot, from the PIT tick + live-counter interpolation).
 pub fn append_fmt(args: core::fmt::Arguments<'_>) {
+    let ms = crate::interrupts::uptime_ms();
     let mut line = LineBuf::new();
     let _ = core::fmt::write(&mut line, args);
-    append(line.as_str());
+    append(line.as_str(), ms);
 }
 
 struct LineBuf {
@@ -124,7 +140,9 @@ pub fn dump() -> String {
         let idx = (start + i) % MAX_LINES;
         let n = r.lens[idx] as usize;
         let text = core::str::from_utf8(&r.bytes[idx][..n]).unwrap_or("");
-        out += &alloc::format!("{:06}  {}\n", first + i as u64, text);
+        let s = r.ms[idx] / 1000;
+        let m = r.ms[idx] % 1000;
+        out += &alloc::format!("[{:04}.{:03}] {:06}  {}\n", s, m, first + i as u64, text);
     }
     out
 }