From 6447eb12948d37b74adae2fdbf1db5a9d7b363d5 Mon Sep 17 00:00:00 2001 From: salmonik Date: Sat, 1 Aug 2026 14:21:11 +0200 Subject: klog: [ssss.mmm] millisecond timestamps from the PIT MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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. --- CONTEXT.md | 13 +++++++++- rsnix/src/interrupts.rs | 64 ++++++++++++++++++++++++++++++++++++++++++------- rsnix/src/klog.rs | 30 ++++++++++++++++++----- rsnix/src/vt.rs | 12 +++++++--- 4 files changed, 101 insertions(+), 18 deletions(-) diff --git a/CONTEXT.md b/CONTEXT.md index 86822d1..fd83245 100644 --- a/CONTEXT.md +++ b/CONTEXT.md @@ -259,7 +259,18 @@ Workspace of four crates, all built for the `x86_64-unknown-uefi` target: lines (128 chars each, ~16 KB), fed by `serial_println!` (one choke point — every boot/low-level message captured for free). Sequence numbers per line + wrap/drop accounting; a dump header reports how - many lines were lost to wrap. Exposed as the `/dev/klog` char + many lines were lost to wrap. Each line carries a `[ssss.mmm]` + timestamp — monotonic ms since boot from `interrupts::uptime_ms()`: + 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 jump = a + tick fired between reads) for true sub-ms resolution; `TICKS` widened + to u64 so uptime never wraps. **The CMOS RTC cannot provide + milliseconds** — it is a 1 Hz BCD device (seconds only) — so the + millis come from the PIT. Early-boot lines are `[0000.000]` + (PIT not yet configured; `PIT_READY` gates interpolation), and + timestamps are clamped monotonic in the ring. + + Exposed as the `/dev/klog` char device; the shell `klog` command is a thin alias for `cat /dev/klog` (same filters/redirection), so `klog -t 5`, `klog -g fat`, and `klog WRITING /disk/…/boot.log` (persists the boot log) 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 { 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(); -- cgit v1.2.3