Every line of the log opens with one head, time first, counted from the CPU counter's zero

bootloader/src/loaderlog.rs

@@ -224,5 +224,5 @@ fn unique_guid(bs: &BootServices, handle: Handle) -> Option<[u8; 16]> {
 /// Why there is no log, and that the boot goes on without one.
 fn refused(why: fmt::Arguments) {
     // The console directly: there is no file, and this says why.
-    uefi_services::println!("{}Loader log: {why}. This boot's loader lines are on the screen only", crate::stamp::now());
+    uefi_services::println!("{} Loader log: {why}. This boot's loader lines are on the screen only", crate::stamp::now());
 }

bootloader/src/main.rs

@@ -743,7 +743,7 @@ fn end_this_pass(system_table: &SystemTable<Boot>, exit_event: Option<Event>) ->
 fn main(handle: Handle, mut system_table: SystemTable<Boot>) -> Status {
     // First, so this reading is firmware's time and none of the loader's.
     let entry_counter = arch::counter();
-    let counter_hz = stamp::start(entry_counter);
+    let counter_hz = stamp::start();
     let exit_event = uefi_services::init(&mut system_table).unwrap();
     // First, because it covers everything below it: firmware starts a
     // five-minute countdown when it loads an image and resets the machine if
@@ -813,7 +813,7 @@ fn main(handle: Handle, mut system_table: SystemTable<Boot>) -> Status {
     loaderlog::open(&system_table, &log_guid, finding.is_none() && !retry);
     println!("{}", loaderlog::BEGINS_AT);
     match counter_hz {
-        Some(hz) => println!("Loader clock: each line opens with the ms since this loader's entry, at the counter's stated {hz} Hz"),
+        Some(hz) => println!("Loader clock: each line opens with the seconds since the counter's zero, at the counter's stated {hz} Hz"),
         None => println!("Loader clock: this CPU states no counter rate, so no line carries the time it was said"),
     }
     if let Err(e) = cleared {

bootloader/src/stamp.rs

@@ -1,50 +1,40 @@
-//! The head of every line the loader says: how far into the loader it was
-//! said, in milliseconds since `main`'s first statement, by the CPU's counter
-//! at the rate the CPU states ([`crate::arch::counter_hz`]). No wall clock: a
-//! line is placed against the loader's own start and nothing else.
+//! The head of every line the loader says: the log's one head
+//! (`toyos_abi::log::Head`), whose time is the seconds since the CPU's counter
+//! last started — power-on, or the reset since — at the rate the CPU states
+//! ([`crate::arch::counter_hz`]). The kernel's records and every program's
+//! line count from the same zero, so a loader line and the kernel's first
+//! record are placed against each other. No wall clock.
 //!
-//! A CPU that states no rate gets lines with no head, and [`start`]'s caller
-//! says so once.
+//! A CPU that states no rate gets lines whose time is `toyos_abi::log::UNTIMED`,
+//! and [`start`]'s caller says so once.
 
 use core::fmt;
 use core::sync::atomic::{AtomicU64, Ordering};
 
-/// The counter at the loader's entry, and its rate; zero until [`start`].
-static ENTRY: AtomicU64 = AtomicU64::new(0);
+use toyos_abi::log::{Head, Severity, LOADER};
+
+/// The counter's rate; zero until [`start`], and for a CPU that states none.
 static HZ: AtomicU64 = AtomicU64::new(0);
 
-/// Take `entry` as every stamp's zero, and return the rate stamps are
-/// converted at, or `None` where the CPU states none.
-pub fn start(entry: u64) -> Option<u64> {
+/// Read the rate stamps are converted at, and return it, or `None` where the
+/// CPU states none.
+pub fn start() -> Option<u64> {
     let hz = crate::arch::counter_hz();
-    ENTRY.store(entry, Ordering::Relaxed);
     HZ.store(hz.unwrap_or(0), Ordering::Relaxed);
     hz
 }
 
-/// Now, as a line's head.
-pub fn now() -> Stamp {
+/// Now, as a line's head. The loader runs on the boot CPU alone, the kernel's
+/// `cpu0`.
+pub fn now() -> Head<'static> {
     let hz = HZ.load(Ordering::Relaxed);
-    let ticks = crate::arch::counter()
-        .checked_sub(ENTRY.load(Ordering::Relaxed))
-        .expect("the counter ran backwards since the loader's entry");
-    Stamp((hz != 0).then(|| (u128::from(ticks) * 1_000 / u128::from(hz)) as u64))
+    let at_ns = (hz != 0).then(|| (u128::from(crate::arch::counter()) * 1_000_000_000 / u128::from(hz)) as u64);
+    Head { wall: "", at_ns, cpu: Some(0), who: LOADER, severity: Severity::Info, tid: 0, pid: None }
 }
 
 /// One line, stamped, to the console and then to `loader.log`.
 pub fn say(args: fmt::Arguments) {
-    let stamp = now();
-    uefi_services::println!("{stamp}{args}");
-    crate::loaderlog::line(format_args!("{stamp}{args}"));
-}
-
-pub struct Stamp(Option<u64>);
-
-impl fmt::Display for Stamp {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        match self.0 {
-            Some(ms) => write!(f, "{ms:>5} ms "),
-            None => Ok(()),
-        }
-    }
+    let head = now();
+    uefi_services::println!("{head} {args}");
+    crate::loaderlog::line(format_args!("{head} {args}"));
 }

issues/a-programs-line-on-a-screen-names-no-cpu.md

@@ -7,10 +7,10 @@ opened: 2026-10-04
 # A program's line on a screen names no CPU
 
 The owner asked for the seconds since boot and the CPU in front of every
-line a screen shows. A kernel record's line carries both: `[kernel 1.193 cpu0
+line a screen shows. A kernel record's line carries both: `[ 1.193 cpu0 kernel
 alert tid=3]`. A program's line carries only the time:
-`{1.234 warn soundserver}` on `/system/bin/console` and on `cargo run`'s
-terminal. The reason is the record. `toyos::log::region::Body`, the record a
+`[ 1.234 soundserver warn]` on `/system/bin/console`, on `cargo run`'s
+terminal and in `/log`. The reason is the record. `toyos::log::region::Body`, the record a
 program writes into its ring, has `at_ns`, `pid`, `tid` and a severity and no
 CPU, so `logkeeper` has no CPU to give `toyos_logstream::ProgramLine`.
 

issues/the-kernel-console-split-does-not-re-arm-across-a-guest-reset.md

@@ -7,7 +7,8 @@ opened: 2026-09-28
 # The kernel console split does not re-arm across a guest reset
 
 `src/kernelconsole.rs`'s `KernelConsole` withholds the virtio port's bytes
-until the first `[kernel ` head and passes every byte after it: `held` is
+until the kernel's first record (`toyos_logstream::kernel_opening`) and
+passes every byte after it: `held` is
 `None` from then on. A guest reset inside one QEMU process does not re-arm it.
 `tests/common/update.rs`'s `Rig::boot` boots the Headless profile, whose
 stdio is that port, with `takes_the_reset`, and each `reboot` resets that
@@ -27,7 +28,8 @@ Nothing reds on it. The update tests look for a needle past an offset in the
 console (`owed`, `reboot_until`), and firmware lines beside the needle do not
 stop it matching. Every update test passed in #572's round-2 and round-3
 nightlies. If the firmware does write its handoff line there,
-`Loader log: … so [kernel …` is a line `Serial::interleaved` reports as a torn
+`Loader log: … so [ 1.234 cpu0 kernel] …` is a line `Serial::interleaved`
+reports as a torn
 kernel line.
 
 ## Exit condition

issues/the-loaders-lines-carry-no-time-on-an-x86-cpu-that-states-no-tsc-rate.md

@@ -6,9 +6,16 @@ opened: 2026-10-04
 
 # The loader's lines carry no time on an x86 CPU that states no TSC rate
 
-`bootloader/src/stamp.rs` converts the cycle counter at the rate CPUID leaves
-15H/16H state (`toyos_tsc::stated_hz`), and a CPU that states neither gets
-unstamped lines and one `Loader clock: this CPU states no counter rate` line.
+Every line of the log opens with its time since the CPU's counter last started
+(`toyos_abi::log::Head`). The loader converts the counter at the rate CPUID
+leaves 15H/16H state (`bootloader/src/stamp.rs`, `toyos_tsc::stated_hz`), and
+the kernel does the same for its records until it has measured the TSC against
+the HPET (`kernel/src/clock.rs`'s `stamp`). A CPU that states neither leaf gets
+`--.---` (`toyos_abi::log::UNTIMED`) in place of the time on every loader line,
+one `Loader clock: this CPU states no counter rate` line, and `--.---` on every
+kernel record before `clock: HPET at …` — `boot:`, `ACPI:`, the interrupt
+controller's and the per-CPU area's among them. The records after it carry
+their time from the same zero.
 
 Every AMD part is one. InstLatx64's recorded CPUID dumps
 (`github.com/InstLatx64/InstLatx64`, `AuthenticAMD/`) read leaf 0's EAX, the
@@ -17,17 +24,18 @@ Zen 3+ (`0A40F41_K19_Rembrandt_01_CPUID`), Zen 4 (`0A60F12_K19_Raphael_01_CPUID`
 and Zen 5 (`0B00F21_K20_Turin_01_CPUID`, `0B20F40_K20_StrixPoint_06_CPUID`,
 `0B40F40_K20_GraniteRidge_02_CPUID`): neither leaf exists there. QEMU's
 `qemu64` states neither either, and under the `guest / suite` check's
-`-cpu host` whether a line is stamped is the runner's CPU's to decide.
+`-cpu host` whether a line is timed is the runner's CPU's to decide.
 
 A second rate source is the fix, and the choice of one is open: the
 `EFI_TIMESTAMP_PROTOCOL`'s stated frequency, the ACPI PM timer or the HPET, each
-a calibration the loader then pays for before its first stamped line.
+a calibration the loader then pays for before its first timed line.
 
-Until then no guest test sees the stamp on the screen: `screen_loader_clears`
-(`tests/toyos.rs`) matches the screen's first line with or without its head,
-because no x86 guest stamps one. The fix is where that test starts asserting
-the head on the screen.
+Until then no guest test asserts a time on the screen: `screen_loader_clears`
+(`tests/toyos.rs`) measures the screen's first line, head and all, whose head
+reads `--.---` under `qemu64` and whatever the runner's CPU states under
+`-cpu host`. The fix is where that test starts asserting a time in it.
 
-Exit: a loader line carries its milliseconds on an x86-64 CPU that states
-neither leaf 15H's ratio nor leaf 16H's base frequency, and `screen_loader_clears`
-asserts that line's head on the screen.
+Exit: a loader line and a kernel record written before `clock: HPET at …` carry
+their time on an x86-64 CPU that states neither leaf 15H's ratio nor leaf 16H's
+base frequency, and `screen_loader_clears` asserts that line's time on the
+screen.

kernel/loom/src/lib.rs

@@ -193,6 +193,12 @@ pub mod log_registry;
 #[path = "../../src/log/read.rs"]
 pub mod log_read;
 
+/// What `read.rs` names as `super::stamp`, which in the kernel is
+/// `crate::log::stamp`.
+#[cfg(not(feature = "loom"))]
+#[path = "../../src/log/stamp.rs"]
+pub mod stamp;
+
 /// What `read.rs`'s log-only walks name as `super::shards()`: none, since no
 /// test here drives them; the walks a test drives take their shards.
 #[cfg(not(feature = "loom"))]

kernel/loom/tests/log_body_words.rs

@@ -18,7 +18,7 @@
 #![cfg(not(feature = "loom"))]
 
 use kernel_loom::log_shard::Shard;
-use toyos_abi::log::{LogRecord, Severity, FLAG_EARLY, MAX_RECORD_MESSAGE};
+use toyos_abi::log::{LogRecord, Severity, FLAG_UNTIMED, MAX_RECORD_MESSAGE};
 
 /// A record whose every field is distinct, so a swap between two of them fails
 /// rather than being absorbed.
@@ -32,7 +32,7 @@ fn record(seq: u64, len: usize) -> LogRecord {
     r.len = len as u16;
     r.elided = 0x5678;
     r.severity = Severity::Alert as u8;
-    r.flags = FLAG_EARLY;
+    r.flags = FLAG_UNTIMED;
     for (i, b) in r.msg[..len].iter_mut().enumerate() {
         *b = b'a' + (i % 26) as u8;
     }

kernel/src/clock.rs

@@ -1,24 +1,63 @@
 //! The machine's clocks: monotonic since boot, read off the CPU's free-running
 //! counter at the period the architecture's boot gives [`set_counter`] (on
-//! x86-64, measured against the HPET); and wall-clock, read from the
+//! x86-64, measured against the HPET); wall-clock, read from the
 //! architecture's RTC exactly once — a CMOS read can block for up to a
 //! second — in [`init_wall`], and answered after as that reading plus
-//! [`nanos_since_boot`].
+//! [`nanos_since_boot`]; and the log's stamp ([`stamp`]), the same clock
+//! counted from the counter's zero, which is where every line of the log —
+//! the loader's, the kernel's and every program's — counts from.
 
 use core::sync::atomic::{AtomicBool, AtomicU64, Ordering::{Acquire, Relaxed, Release}};
 
 use crate::arch::cpu;
+use crate::log::LogStamp;
 use crate::time::Instant;
 
 static TSC_BOOT: AtomicU64 = AtomicU64::new(0);
 static TSC_PERIOD_FS: AtomicU64 = AtomicU64::new(0);
+/// The counter's zero to `TSC_BOOT`, in nanoseconds.
+static STAMP_AT_BOOT: AtomicU64 = AtomicU64::new(0);
+/// One counter tick at the rate the CPU states, in femtoseconds; zero where it
+/// states none, or before [`state`].
+static STATED_FS: AtomicU64 = AtomicU64::new(0);
+
+/// Take the rate the CPU states, the loader's, for the stamps the log carries
+/// before [`set_counter`]. The kernel's entry calls this before its first record.
+pub fn state() {
+    let stated = cpu::stated_counter_hz().map_or(0, |hz| 1_000_000_000_000_000 / hz);
+    STATED_FS.store(stated, Relaxed);
+}
 
 /// Start the clock on the counter: its reading at boot and its measured period.
 /// The architecture's boot calls this once, after it has the period.
+///
+/// **The stamps go on from where the stated rate left them**: a record before
+/// this read the counter at that rate, so the stamp at `boot` is that reading,
+/// and no record after this one is stamped earlier than one before it.
 pub fn set_counter(boot: u64, period_fs: u64) {
+    let stated = STATED_FS.load(Relaxed);
+    let at_boot = ticks_to_nanos(boot, if stated != 0 { stated } else { period_fs });
+    STAMP_AT_BOOT.store(at_boot, Relaxed);
     TSC_BOOT.store(boot, Relaxed);
     TSC_PERIOD_FS.store(period_fs, Relaxed);
-    publish_page(boot, period_fs);
+    publish_page(boot, period_fs, at_boot);
+}
+
+fn ticks_to_nanos(ticks: u64, period_fs: u64) -> u64 {
+    ((ticks as u128 * period_fs as u128) / 1_000_000) as u64
+}
+
+/// Now as a log line's time: nanoseconds since the counter's zero — power-on,
+/// or the reset since — at the clock's rate, and before [`set_counter`] at the
+/// rate the CPU states. `None` where it states none and the clock has not
+/// started: no rate reads the counter yet. Never panics, as
+/// [`nanos_since_boot`].
+pub fn stamp() -> Option<LogStamp> {
+    if calibrated() {
+        return Some(LogStamp::since_zero(STAMP_AT_BOOT.load(Relaxed).saturating_add(nanos_since_boot())));
+    }
+    let stated = STATED_FS.load(Relaxed);
+    (stated != 0).then(|| LogStamp::since_zero(ticks_to_nanos(cpu::counter(), stated)))
 }
 
 /// The clock page's frame, or 0 before [`set_counter`]: the one every address space
@@ -28,7 +67,7 @@ static PAGE_PHYS: AtomicU64 = AtomicU64::new(0);
 /// Lay the calibration out on a frame of its own, for every process to read
 /// the clock this module reads without asking it. Laid out before any address
 /// space can map it, and never written again.
-fn publish_page(counter_at_boot: u64, period_fs: u64) {
+fn publish_page(counter_at_boot: u64, period_fs: u64, stamp_at_boot: u64) {
     use toyos_abi::clock::{ClockPage, CLOCK_MAGIC};
     let bytes = crate::mm::PAGE_2M as usize;
     // Held for the machine's life: every process maps it.
@@ -42,7 +81,7 @@ fn publish_page(counter_at_boot: u64, period_fs: u64) {
         core::ptr::write_bytes(frame.ptr(), 0, bytes);
         core::ptr::write_volatile(
             frame.ptr() as *mut ClockPage,
-            ClockPage { magic: CLOCK_MAGIC, counter_at_boot, period_fs },
+            ClockPage { magic: CLOCK_MAGIC, counter_at_boot, period_fs, stamp_at_boot },
         );
     }
     PAGE_PHYS.store(frame.phys(), Release);
@@ -75,9 +114,7 @@ pub fn calibrated() -> bool {
 /// reads it from inside a bracket where panicking would reenter the log.
 /// Saturating, not wrapping: a trailing CPU reads as oldest, not lying newest after a 584-year wrap.
 pub fn nanos_since_boot() -> u64 {
-    let delta = cpu::counter().saturating_sub(TSC_BOOT.load(Relaxed));
-    let period_fs = TSC_PERIOD_FS.load(Relaxed);
-    ((delta as u128 * period_fs as u128) / 1_000_000) as u64
+    ticks_to_nanos(cpu::counter().saturating_sub(TSC_BOOT.load(Relaxed)), TSC_PERIOD_FS.load(Relaxed))
 }
 
 /// The same reading as an [`Instant`], the type arithmetic on it is allowed in.
@@ -109,7 +146,7 @@ pub fn counter_ticks(nanos: u64) -> u64 {
 /// Zero while the period is unknown, so a span taken on a machine that never
 /// calibrated reads as no time rather than as an invented one.
 pub fn nanos_of_ticks(ticks: u64) -> u64 {
-    ((ticks as u128 * TSC_PERIOD_FS.load(Relaxed) as u128) / 1_000_000) as u64
+    ticks_to_nanos(ticks, TSC_PERIOD_FS.load(Relaxed))
 }
 
 /// Polls `ready` until it holds or `nanos` pass; `false` is the deadline.

kernel/src/deadline.rs

@@ -244,7 +244,7 @@ fn expire() -> ! {
          CPU's timer last found the kernel:\n{KernelPcs}The tail of the log ring follows — which \
          is what nothing was draining.\n",
         BOUND_MS.load(Relaxed),
-        crate::clock::nanos_since_boot() / 1_000_000,
+        crate::clock::stamp().expect("the deadline polls only once the clock runs").nanos() / 1_000_000,
         phase(),
     ));
     // The seal first, because the USB stop `reset_now` makes before it writes

kernel/src/drivers/panic_console/mod.rs

@@ -19,6 +19,7 @@ use core::sync::atomic::{AtomicBool, AtomicU32, AtomicU64, AtomicUsize, Ordering
 use toyos_abi::boot::{KernelArgs, MemoryMapEntry};
 
 use crate::log;
+use crate::log::LogStamp;
 use crate::panic_reboot::Bound;
 use crate::time::{Budget, Cadence, Duration};
 use crate::mm::policy::MmioPolicy;
@@ -152,7 +153,7 @@ impl Rendered {
         Self { text: [0; SNAPSHOT_CAP], marks: [0; MARK_BYTES], len: 0, lines: 0 };
 
     /// Render the newest records stamped in `from..=to` that fit; returns the byte count. Records older than the buffer holds are dropped.
-    fn render(&mut self, from: u64, to: u64) -> usize {
+    fn render(&mut self, from: LogStamp, to: LogStamp) -> usize {
         self.marks = [0; MARK_BYTES];
         self.lines = 0;
         self.len = 0;
@@ -579,7 +580,7 @@ fn capture_into(refresh: bool) {
     // panic path may take no lock. `SNAPSHOT` is written only here, under
     // `CAPTURE`, after `CAPTURE_ACCESS` admitted a writer and before publication.
     let into = unsafe { &mut *SNAPSHOT.0.get() };
-    CAPTURE_ACCESS.publish(into.render(0, u64::MAX) > 0);
+    CAPTURE_ACCESS.publish(into.render(LogStamp::ZERO, LogStamp::MAX) > 0);
 }
 
 /// This CPU's claim on `SNAPSHOT`; tokens never collide, unclaimed-0 and `EARLY_CAPTOR` included.
@@ -604,7 +605,7 @@ fn live_tail() -> View<'static> {
     // SAFETY: sound as `capture`'s `SNAPSHOT` write — `LIVE` is reached only
     // from here, every caller holds `PAINTING`; one block, not two, so render and view can't disagree.
     let into: &'static mut Rendered = unsafe { &mut *LIVE.0.get() };
-    into.render(0, u64::MAX);
+    into.render(LogStamp::ZERO, LogStamp::MAX);
     let rendered: &'static Rendered = into;
     rendered.view()
 }
@@ -761,7 +762,7 @@ fn repaint() {
 ///
 /// [`boot_checkpoint`] without the userland check — the keystroke is the
 /// consent. A single paint is not a report, so this arms a hold that [`hold_report`] answers.
-pub fn paint_report(from: u64, to: u64) {
+pub fn paint_report(from: LogStamp, to: LogStamp) {
     // SAFETY: sound as `capture`'s `SNAPSHOT` write — `REPORT` is reached
     // only from here and `report_text`; the dump reschedules every CPU, so only one is in flight.
     let into = unsafe { &mut *REPORT.0.get() };

kernel/src/log/console.rs

@@ -347,11 +347,11 @@ impl<F: FnMut(&[u8])> core::fmt::Write for Line<F> {
     }
 }
 
-/// Render one record as the console line; `logkeeper`'s `/log` sink renders the same line with a different prefix.
+/// Render one record as the console line; `logkeeper`'s `/log` sink renders the same line with its wall clock.
 pub fn write_line(record: &LogRecord, emit: impl FnMut(&[u8])) {
     use core::fmt::Write;
     let mut line = Line::new(emit);
-    let _ = write!(line, "{}", record.tagged("kernel"));
+    let _ = write!(line, "{record}");
     line.finish();
 }