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.

3 files changed, 89 insertions, 17 deletions

diff --git a/rsnix/src/interrupts.rs b/rsnix/src/interrupts.rs
index 2b82a3d..c176276 100644
--- a/rsnix/src/interrupts.rs
+++ b/rsnix/src/interrupts.rs
@@ -2,7 +2,7 @@
 // Interrupt handling: IDT, PIC remap, ISR dispatch.
 // ---------------------------------------------------------------------------
 use core::arch::asm;
-use core::sync::atomic::{AtomicU16, Ordering};
+use core::sync::atomic::{AtomicBool, AtomicU16, AtomicU64, Ordering};
 
 // ---------------------------------------------------------------------------
 // IDT entry and table
@@ -91,11 +91,17 @@ fn eoi(irq: u8) {
 
 const PIT_CMD: u16 = 0x43;
 const PIT_CH0: u16 = 0x40;
-const PIT_FREQ: u64 = 1_193_182;
+const PIT_FREQ: u64 = 1_193_182; // PIT clock: 1.193182 MHz
+const PIT_HZ: u64 = 100;
 
-/// Set up PIT channel 0 in mode 2 (rate generator) at `hz` (1–1000ish).
-fn pit_set_rate(hz: u64) {
-    let divisor = (PIT_FREQ / hz) as u16;
+/// Counter divisor loaded for the ~100 Hz tick (matches `pit_set_rate`).
+pub const PIT_DIVISOR: u16 = (PIT_FREQ / PIT_HZ) as u16;
+
+/// Set up PIT channel 0 in mode 2 (rate generator) at the fixed 100 Hz
+/// tick rate — the divisor must stay `PIT_DIVISOR`, which `uptime_ms`
+/// relies on for interpolation.
+fn pit_set_rate() {
+    let divisor = PIT_DIVISOR;
     unsafe {
         // Mode 2, channel 0, lobyte/hibyte, binary
         asm!("out dx, al", in("dx") PIT_CMD,  in("al") 0b0011_0100u8,
@@ -107,6 +113,45 @@ fn pit_set_rate(hz: u64) {
     }
 }
 
+/// Latch and read the PIT channel 0 down-counter (0..=PIT_DIVISOR).
+/// In mode 2 the counter counts down and reloads on reaching 0, so it
+/// only ever jumps *up* when a tick fires.
+fn pit_count() -> u16 {
+    unsafe {
+        asm!("out dx, al", in("dx") PIT_CMD, in("al") 0x00u8,
+            options(nomem, nostack, preserves_flags));
+        let lo: u8;
+        let hi: u8;
+        asm!("in al, dx", out("al") lo, in("dx") PIT_CH0,
+            options(nomem, nostack, preserves_flags));
+        asm!("in al, dx", out("al") hi, in("dx") PIT_CH0,
+            options(nomem, nostack, preserves_flags));
+        u16::from_le_bytes([lo, hi])
+    }
+}
+
+/// True once the PIT tick is configured (`interrupts::init`).  Before
+/// that the PIT counter is uninitialised, so `uptime_ms` reports 0
+/// (early-boot messages are all at [0000.000], which is truthful — the
+/// clock hasn't started).
+static PIT_READY: AtomicBool = AtomicBool::new(false);
+
+/// Monotonic milliseconds since boot: the 100 Hz tick (10 ms each) plus
+/// interpolation from the PIT's live 1.19 MHz down-counter for the
+/// sub-10 ms fraction.  The countdown is read twice around the tick
+/// load: if it jumped up, a tick fired between the reads.
+pub fn uptime_ms() -> u64 {
+    if !PIT_READY.load(Ordering::Relaxed) {
+        return 0;
+    }
+    let c1 = pit_count();
+    let ticks = TICKS.load(Ordering::Relaxed);
+    let c2 = pit_count();
+    let ticks = if c2 > c1 { ticks + 1 } else { ticks };
+    let c = u64::from(c2.min(PIT_DIVISOR));
+    ticks * (1000 / PIT_HZ) + (u64::from(PIT_DIVISOR) - c) * 1000 / PIT_FREQ
+}
+
 // ---------------------------------------------------------------------------
 // Lock-free SPSC ring buffer for keyboard scancodes
 // ---------------------------------------------------------------------------
@@ -286,8 +331,10 @@ pub fn read_scancode() -> Option<u8> {
     KEYBUF.pop()
 }
 
-/// Global tick counter (incremented by timer IRQ, ~100 Hz).
-pub static TICKS: AtomicU16 = AtomicU16::new(0);
+/// Global tick counter (incremented by timer IRQ, ~100 Hz).  u64 so
+/// uptime never wraps; `uptime_ms` interpolates the PIT counter for the
+/// sub-tick fraction.
+pub static TICKS: AtomicU64 = AtomicU64::new(0);
 
 /// Initialise the IDT, remap the PIC, set up the PIT, and enable interrupts.
 pub fn init() {
@@ -326,7 +373,8 @@ pub fn init() {
         remap_pic();
 
         // Set up PIT timer at ~100 Hz.
-        pit_set_rate(100);
+        pit_set_rate();
+        PIT_READY.store(true, Ordering::Relaxed);
 
         // Unmask timer (IRQ0 → bit 0) and keyboard (IRQ1 → bit 1) on master.
         let mut mask: u8;
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
 }
diff --git a/rsnix/src/vt.rs b/rsnix/src/vt.rs
index 709ea71..53821b7 100644
--- a/rsnix/src/vt.rs
+++ b/rsnix/src/vt.rs
@@ -224,7 +224,13 @@ fn put_byte(b: u8) {
 }
 
 fn param(i: usize, default: usize) -> usize {
-    unsafe { if i < NPARAMS { PARAMS[i] } else { default } }
+    unsafe {
+        if i < NPARAMS {
+            PARAMS[i]
+        } else {
+            default
+        }
+    }
 }
 
 /// Place a printable glyph at the cursor and advance (wrapping/scrolling).
@@ -409,7 +415,7 @@ fn newline() {
 /// only the newly-exposed rows.
 const SCROLL_BATCH: usize = 16;
 static mut PENDING_SCROLLS: usize = 0;
-static mut LAST_SYNC_TICK: u16 = 0;
+static mut LAST_SYNC_TICK: u64 = 0;
 
 /// Shift the logical grid up one row; defer the framebuffer shift.
 fn scroll_up() {
@@ -424,7 +430,7 @@ fn scroll_up() {
         // Batch: sync when enough scrolls piled up, or when the stream
         // pauses (~40 ms at the 100 Hz timer) so interactive output still
         // appears promptly.
-        const TICK_LIMIT: u16 = 4;
+        const TICK_LIMIT: u64 = 4;
         let now = crate::interrupts::TICKS.load(core::sync::atomic::Ordering::Relaxed);
         if PENDING_SCROLLS >= SCROLL_BATCH || now.wrapping_sub(LAST_SYNC_TICK) > TICK_LIMIT {
             sync_scroll();