From 9edbfb6ec62c243075e2571767119aa712cc8b80 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 09:04:07 +0200 Subject: [PATCH 1/7] Diary step 1: the trace ring is read by SYS_TRACE_READ on the trace right, and ships its reader The trace ring had LLDB as its only reader. It is now written through the log's slot protocol, stamped with each CPU's raw counter, and read by SYS_TRACE_READ (125) on Rights::TRACE through the log's own walk and cursor. toyos-trace decodes a record and prints its line, and /system/bin/trace, granted `trace` in system.toml, prints the diary. - The log's Shard becomes Ring, the slot protocol over any number of body words whose first is the stamp: the log's Shard is one, each CPU's diary ring (8192 slots of 32 bytes, 2 MiB at eight CPUs) another. A zeroed ring is an empty one (the count is of numbers issued, the first being FIRST_SEQ), so Shard::initialize_zeroed goes, BOOT_SHARD moves from .data to .bss and the kernel file shrinks by 526,080 bytes. - The log's walk, drain_ordered and Cursor, takes its rings and any Stream, so the log's read and the diary's are one read_rings, and both syscalls one read_on_cursor. - A record is reserved, stamped and published under one IrqGuard on the CPU the guard holds, so a ring is in stamp order and an interrupt's record has its own slot. The LLDB symbol and the hand-pinned kind numbers go: the kinds are toyos_abi::trace::Kind, numbered from one. - Every task record named a scheduler key as its pid and tid: TaskKey is a counter, never TaskId::pack, so no record ever named its thread. The core's task TraceKinds now carry SchedPayload::name, which the kernel's payload answers with TaskId::pack. TraceKind's Block, IdleExit and Irq, which nothing constructed, go, and so does Kind::SchedIdle. - SYS_DEBUG's TRACE_FLOOD (14, test kernel) writes a run of Mark records and answers the ticks they took with interrupts closed. - Tests: decoder host tests; trace_read on the T14's shared boot and on AArch64's virt_smp; trace_flood on the trace_record_cost metal row. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- Cargo.lock | 7 + Cargo.toml | 1 + ...teness-and-records-no-slow-system-call.md} | 23 +- issues/diagnostics/toyos-explains-itself.md | 4 +- .../toyos-beats-linuxs-latency-on-the-t14.md | 2 +- kernel/loom/src/lib.rs | 19 +- kernel/loom/tests/log_body_words.rs | 2 +- kernel/loom/tests/log_cursor.rs | 17 +- kernel/loom/tests/log_record.rs | 8 +- kernel/loom/tests/log_wake.rs | 2 +- kernel/loom/tests/log_zeroed_init.rs | 27 +- kernel/loom/tests/loom_retire.rs | 4 + kernel/pure/sched/cpu.rs | 27 +- kernel/pure/sched/hw.rs | 24 +- kernel/pure/sched/task.rs | 5 + kernel/sim/src/invariants.rs | 2 +- kernel/sim/src/payload.rs | 4 + kernel/src/irq_ring.rs | 2 +- kernel/src/log/console.rs | 8 +- kernel/src/log/mod.rs | 11 +- kernel/src/log/read.rs | 62 ++-- kernel/src/log/shard.rs | 221 +++++++------- kernel/src/log/user.rs | 48 ++- kernel/src/sched/payload.rs | 5 + kernel/src/syscall/dispatch.rs | 14 + kernel/src/syscall/machine.rs | 34 ++- kernel/src/trace.rs | 284 +++++++----------- kernel/src/user_ptr.rs | 2 + src/sourcegate.rs | 1 - system.toml | 6 + tests/toyos-rust-tests/Cargo.lock | 8 + tests/toyos-rust-tests/Cargo.toml | 2 + tests/toyos-rust-tests/src/bin/trace_flood.rs | 77 +++++ tests/toyos-rust-tests/src/bin/trace_read.rs | 192 ++++++++++++ tests/toyos.rs | 41 ++- tests/virtsmpcase/system.toml | 15 +- toyos-abi/src/clock.rs | 15 +- toyos-abi/src/handle.rs | 5 +- toyos-abi/src/lib.rs | 1 + toyos-abi/src/syscall.rs | 41 ++- toyos-abi/src/trace.rs | 170 +++++++++++ toyos-trace/Cargo.toml | 10 + toyos-trace/src/lib.rs | 255 ++++++++++++++++ toyos/src/syscap.rs | 12 + userland/Cargo.lock | 16 + userland/Cargo.toml | 1 + userland/trace/Cargo.toml | 13 + userland/trace/src/main.rs | 72 +++++ 48 files changed, 1377 insertions(+), 445 deletions(-) rename issues/diagnostics/{nothing-in-the-machine-can-read-the-trace-ring.md => the-diary-computes-no-lateness-and-records-no-slow-system-call.md} (73%) create mode 100644 tests/toyos-rust-tests/src/bin/trace_flood.rs create mode 100644 tests/toyos-rust-tests/src/bin/trace_read.rs create mode 100644 toyos-abi/src/trace.rs create mode 100644 toyos-trace/Cargo.toml create mode 100644 toyos-trace/src/lib.rs create mode 100644 userland/trace/Cargo.toml create mode 100644 userland/trace/src/main.rs diff --git a/Cargo.lock b/Cargo.lock index 459db388e8b..100fff19ce7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1421,6 +1421,13 @@ version = "0.1.0" name = "toyos-tmpdir" version = "0.1.0" +[[package]] +name = "toyos-trace" +version = "0.1.0" +dependencies = [ + "toyos-abi", +] + [[package]] name = "toyos-transport" version = "0.1.0" diff --git a/Cargo.toml b/Cargo.toml index 9c8e75f44c8..a2475dc24b6 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -58,6 +58,7 @@ members = [ "toyos-symbols", "toyos-tco", "toyos-tmpdir", + "toyos-trace", "toyos-untrusted", "toyos-update", "toyos-userbound", diff --git a/issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md b/issues/diagnostics/the-diary-computes-no-lateness-and-records-no-slow-system-call.md similarity index 73% rename from issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md rename to issues/diagnostics/the-diary-computes-no-lateness-and-records-no-slow-system-call.md index 0a346c25365..97d3c0c3491 100644 --- a/issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md +++ b/issues/diagnostics/the-diary-computes-no-lateness-and-records-no-slow-system-call.md @@ -4,14 +4,15 @@ kind: track opened: 2026-07-30 --- -# Nothing inside the machine can read the trace ring, and nothing samples RIP +# The diary computes no lateness, and records no window, shootdown or slow system call -`kernel/src/trace.rs` is a per-CPU ring of `RING_CAPACITY` 24-byte `repr(C)` -records, enabled from `main.rs` at boot and written by the timer, the -scheduler, `irq_ring` and every `kernel::sched::hw::TraceEvent` the core emits. -Its one reader is LLDB: `p &TRACE_RINGS` and then `memory read`, which is why -the discriminants are fixed by hand and held there by const assertions. A -booted machine can ask itself nothing: no syscall, no tool, no gate. +`kernel/src/trace.rs` is the diary: a ring per CPU of 32-byte +`toyos_abi::trace` records, written always through the log's slot protocol +and stamped with the CPU's raw counter, by the timer, the scheduler, +`irq_ring` and every `kernel::sched::hw::TraceEvent` the core emits. +`SYS_TRACE_READ` reads it on the `trace` right, `toyos-trace` decodes it, and +`/system/bin/trace` prints it. Nothing reads a lateness off it, and nothing +samples RIP. Part of `issues/diagnostics/toyos-explains-itself.md`. @@ -25,11 +26,16 @@ anything more is built on it. test in which a spawned child's wake precedes its pick, a second cursor is undisturbed, loss is counted after a flood, and a process without the right is ended; and on the T14, the ticks a record costs, measured by a boot that - writes a million records. + writes a million records. Built; the T14 reading is owed, and the + `trace_record_cost` row takes it. 2. **Timer and thread lateness**, computed by a reader from the arm, fire and pick events, with no tracer in the kernel. **Exit**, on the T14: the 50 ms for which `hold_once` keeps both windows open once a boot (`kernel/src/windows.rs`) reads back as at least that much lateness. + A deadline's wake is recorded as a `timer-fire` naming no task + (`fire_deadlines` in `kernel/pure/sched/cpu.rs`), so a reader cannot say + which sleeper a fire woke; and a `wake` is the owning CPU's handling of a + post, so the span from a post on another CPU to it is in no record. 3. **Windows over a threshold, shootdown records, and slow system calls.** A system call over the threshold is recorded with its number and its program, in the shipped kernel: **"Always on"** (owner, 2026-10-03). @@ -51,7 +57,6 @@ The proposal's other lines, accepted with it: - The ring stays always written in the shipping kernel. - Reading it needs a new `trace` right. -- The LLDB reading path and its pinned numbers go. - A T14 judge may read a binary trace file, the decoder printing the lines a pull request quotes. - The profiling sample shares the ring. diff --git a/issues/diagnostics/toyos-explains-itself.md b/issues/diagnostics/toyos-explains-itself.md index 8033a58663e..34d149b8165 100644 --- a/issues/diagnostics/toyos-explains-itself.md +++ b/issues/diagnostics/toyos-explains-itself.md @@ -9,7 +9,7 @@ opened: 2026-10-04 ToyOS answers what it is doing, what it did and what it is made of from inside itself, with programs it ships. Today the answers are scattered: the log carries numbers in prose (`irq:`, `tlb:`, `PMM:`, `sched:`, `syscalls:`), -the trace ring has LLDB as its only reader, nothing reads RAPL or C-state +the diary computes no lateness, nothing reads RAPL or C-state residency, a process's memory is a byte sum that reads 0 under contention, and a user symbol is resolved by the kernel. Each pillar's own track carries its steps and its exits; this track holds the @@ -55,7 +55,7 @@ rest were not put to him. | Pillar | Its track | |---|---| | Log | `issues/kernel/logging-records-from-every-producer-and-a-kernel-that-waits-on-nobody.md`; the sinks half of `issues/design-debt/redesign-the-log-subsystem.md` | -| Diary | `issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md` | +| Diary | `issues/diagnostics/the-diary-computes-no-lateness-and-records-no-slow-system-call.md` | | Counters, sizes | this file | | Profile | behind the diary's judgement; `issues/hardware/a-frozen-toyos-waits-for-a-hand-on-the-power-button.md` | | Accounting | `issues/kernel/nothing-charges-kernel-memory-to-a-process.md`, `issues/kernel/a-processs-memory-is-a-byte-total-that-reads-zero-under-contention.md`, `issues/diagnostics/blocked-time-is-invisible-while-the-park-lasts.md` | diff --git a/issues/kernel/toyos-beats-linuxs-latency-on-the-t14.md b/issues/kernel/toyos-beats-linuxs-latency-on-the-t14.md index 09b21cc81db..2c6ad055319 100644 --- a/issues/kernel/toyos-beats-linuxs-latency-on-the-t14.md +++ b/issues/kernel/toyos-beats-linuxs-latency-on-the-t14.md @@ -41,7 +41,7 @@ and of the thread it wakes under Linux's loaded longest on those seven CPUs, 503 µs. Nothing takes that reading of ToyOS today: `latency_wake` reads one thread's p99 and `mask_windows` each CPU's longest masked windows. Two files owe it: step 2 of -`issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md`, a +`issues/diagnostics/the-diary-computes-no-lateness-and-records-no-slow-system-call.md`, a reader that computes timer and thread lateness from the ring, and `issues/hardware/no-program-measures-toyos-against-linux-on-one-machine.md`, one program that reads lateness past a 1 ms timer under both systems. diff --git a/kernel/loom/src/lib.rs b/kernel/loom/src/lib.rs index 2185a7ac7ee..f3e3b305aa6 100644 --- a/kernel/loom/src/lib.rs +++ b/kernel/loom/src/lib.rs @@ -193,24 +193,11 @@ pub mod log_registry; #[path = "../../src/log/read.rs"] pub mod log_read; -// The shards `read.rs` walks: in the kernel cpu0's and every AP's published -// one, here whichever the calling test thread installed. -#[cfg(not(feature = "loom"))] -std::thread_local! { - static SHARDS: core::cell::Cell<[Option<&'static shard::Shard>; toyos_abi::log::MAX_LOG_SHARDS]> = - const { core::cell::Cell::new([None; toyos_abi::log::MAX_LOG_SHARDS]) }; -} - -/// What `read.rs` names as `super::shards()`. +/// 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"))] pub fn shards() -> [Option<&'static shard::Shard>; toyos_abi::log::MAX_LOG_SHARDS] { - SHARDS.with(core::cell::Cell::get) -} - -/// Install the shards this thread's walks see. No kernel counterpart. -#[cfg(not(feature = "loom"))] -pub fn install_shards(shards: [Option<&'static shard::Shard>; toyos_abi::log::MAX_LOG_SHARDS]) { - SHARDS.with(|cell| cell.set(shards)); + [None; toyos_abi::log::MAX_LOG_SHARDS] } #[path = "../../src/sched/reap_gate.rs"] diff --git a/kernel/loom/tests/log_body_words.rs b/kernel/loom/tests/log_body_words.rs index 30b62b7cb5c..3d5a0dac500 100644 --- a/kernel/loom/tests/log_body_words.rs +++ b/kernel/loom/tests/log_body_words.rs @@ -62,7 +62,7 @@ fn round_trip(len: usize) { assert_eq!(got.message(), want.message(), "the message"); // And the key the merge orders by is the one the copy carries, read through // the other reader over the same words. - assert_eq!(shard.at_ns(seq), Some(want.at_ns), "at_ns through the key reader"); + assert_eq!(shard.stamp(seq), Some(want.at_ns), "at_ns through the key reader"); } /// Every field, at the three lengths the word arithmetic can disagree about: diff --git a/kernel/loom/tests/log_cursor.rs b/kernel/loom/tests/log_cursor.rs index 839da661d42..6b311135164 100644 --- a/kernel/loom/tests/log_cursor.rs +++ b/kernel/loom/tests/log_cursor.rs @@ -19,16 +19,13 @@ use kernel_loom::log_read::{drain_ordered, Cursor, RecordSink}; use kernel_loom::log_shard::{Shard, FIRST_SEQ, SHARD_RECORDS}; use toyos_abi::log::{LogCursor, LogRecord, MAX_LOG_SHARDS}; -/// A shard for the life of the test binary, which a walk names as `'static`. +/// A shard for the life of the test binary, which a walk names as `'static`: zeroed, as the kernel allocates an AP's. fn shard() -> &'static Shard { // SAFETY: a `Shard` is not zero-sized; the block is never freed. let ptr = unsafe { alloc_zeroed(Layout::new::()) }.cast::(); assert!(!ptr.is_null()); - // SAFETY: fresh, zeroed, aligned and private to this test until it returns. - unsafe { - Shard::initialize_zeroed(ptr); - &*ptr - } + // SAFETY: fresh, zeroed, aligned and never freed; zeroed is an empty shard. + unsafe { &*ptr } } /// Commits `count` records to `shard`, each stamped with its own number. @@ -66,11 +63,10 @@ fn a_cursors_loss_claim_is_not_read() { emit(lapped, SHARD_RECORDS as u64 + OVERWRITTEN); let mut shards = [None; MAX_LOG_SHARDS]; shards[0] = Some(lapped); - kernel_loom::install_shards(shards); let mut cursor = LogCursor { lost: u64::MAX, ..LogCursor::new() }; - let mut walk = Cursor::from_reader(&cursor).expect("a cursor at every shard's start is taken"); - drain_ordered(&mut walk, &mut Full); + let mut walk = Cursor::from_reader(&cursor, &shards).expect("a cursor at every shard's start is taken"); + drain_ordered(&shards, &mut walk, &mut Full); walk.write_into(&mut cursor); assert_eq!(cursor.lost, OVERWRITTEN); } @@ -84,12 +80,11 @@ fn a_cursor_ahead_of_a_shard_is_refused() { emit(published, RECORDS); let mut shards = [None; MAX_LOG_SHARDS]; shards[0] = Some(published); - kernel_loom::install_shards(shards); let taken = |shard: usize, next: u64| { let mut cursor = LogCursor::new(); cursor.next[shard] = next; - Cursor::from_reader(&cursor).is_some() + Cursor::from_reader(&cursor, &shards).is_some() }; let head = FIRST_SEQ + RECORDS; assert!(taken(0, head), "a cursor caught up with a published shard"); diff --git a/kernel/loom/tests/log_record.rs b/kernel/loom/tests/log_record.rs index c1149dc1f03..baf3dc098fa 100644 --- a/kernel/loom/tests/log_record.rs +++ b/kernel/loom/tests/log_record.rs @@ -261,7 +261,7 @@ fn a_reader_racing_a_recycle_gets_nothing_rather_than_a_mixture() { assert_whole(&got, FIRST_SEQ); } // Its key is the same question asked of the second reader. - if let Some(at_ns) = shard.at_ns(FIRST_SEQ) { + if let Some(at_ns) = shard.stamp(FIRST_SEQ) { assert_eq!( at_ns, record(FIRST_SEQ).at_ns, @@ -351,7 +351,7 @@ fn a_key_and_the_record_it_names_come_from_one_generation() { }); // Racing the recycle: nothing, or this generation's own key. - if let Some(at_ns) = shard.at_ns(target) { + if let Some(at_ns) = shard.stamp(target) { assert_eq!( at_ns, record(target).at_ns, @@ -360,10 +360,10 @@ fn a_key_and_the_record_it_names_come_from_one_generation() { } w.join().unwrap(); - assert_eq!(shard.at_ns(target), Some(record(target).at_ns)); + assert_eq!(shard.stamp(target), Some(record(target).at_ns)); // And the key the merge orders by is the one the copy it then makes // carries, which is the property the two readers exist to share. let got = shard.read(target).expect("committed once the writer has joined"); - assert_eq!(shard.at_ns(target), Some(got.at_ns)); + assert_eq!(shard.stamp(target), Some(got.at_ns)); }); } diff --git a/kernel/loom/tests/log_wake.rs b/kernel/loom/tests/log_wake.rs index e8567160a37..b41bacf726d 100644 --- a/kernel/loom/tests/log_wake.rs +++ b/kernel/loom/tests/log_wake.rs @@ -91,7 +91,7 @@ fn a_commit_and_an_arm_cannot_both_miss() { // `klogd`'s park decision, and nothing else of its body: `true` is "do // not park". - let dont_park = arm_waiter(&m.waiter, || m.shard.at_ns(FIRST_SEQ).is_some()); + let dont_park = arm_waiter(&m.waiter, || m.shard.stamp(FIRST_SEQ).is_some()); p.join().unwrap(); diff --git a/kernel/loom/tests/log_zeroed_init.rs b/kernel/loom/tests/log_zeroed_init.rs index be7d25c56f5..64506d3e458 100644 --- a/kernel/loom/tests/log_zeroed_init.rs +++ b/kernel/loom/tests/log_zeroed_init.rs @@ -1,17 +1,15 @@ //! Host-fast regression for the AP shard's allocation path. //! //! Loom atomics are deliberately not byte-zeroable, so this test runs with -//! `--no-default-features` and exercises the real `core` layout and the real -//! in-place constructor used after `alloc_zeroed`. +//! `--no-default-features` and exercises the real `core` layout of a shard +//! that `alloc_zeroed` made and nothing constructed. //! //! **The gate below therefore runs under exactly one of this crate's two //! invocations, and the other one runs nothing from this file.** That is the -//! shape, not an accident — but it was silent until 2026-08-14, when CI ran -//! only the default invocation and this file's `running 0 tests` looked -//! identical to a pass. `cargo run -- --ci host` runs both commands -//! now, and every other `loom::model` file is gated `cfg(feature = "loom")`, -//! so a bare `--no-default-features` run at the crate root exercises none of -//! them either — the second command names this target explicitly instead. +//! shape, not an accident. `cargo run -- --ci host` runs both commands, and +//! every other `loom::model` file is gated `cfg(feature = "loom")`, so a bare +//! `--no-default-features` run at the crate root exercises none of them either +//! — the second command names this target explicitly instead. #![cfg(not(feature = "loom"))] @@ -24,17 +22,8 @@ fn a_zero_allocated_ap_shard_issues_first_seq_first() { let layout = Layout::new::(); let ptr = unsafe { alloc_zeroed(layout) }.cast::(); assert!(!ptr.is_null()); - - // Negative witness: allocation alone leaves the first field — `head` by - // the layout assertion in `shard.rs` — at zero. Publishing that pointer - // directly is the reviewed defect and would issue the empty-state number. - let zero_head = unsafe { ptr.cast::().read() }; - assert_eq!(zero_head, 0); - assert_ne!(zero_head, FIRST_SEQ); - - // SAFETY: `ptr` is a fresh, aligned, zeroed allocation and remains private - // to this test until initialization completes. - unsafe { Shard::initialize_zeroed(ptr) }; + // SAFETY: a fresh, aligned, zeroed allocation, which is an empty shard, + // private to this test. let shard = unsafe { &*ptr }; assert_eq!(shard.head(), FIRST_SEQ); diff --git a/kernel/loom/tests/loom_retire.rs b/kernel/loom/tests/loom_retire.rs index aecaf9b6116..77d7ade8b29 100644 --- a/kernel/loom/tests/loom_retire.rs +++ b/kernel/loom/tests/loom_retire.rs @@ -339,6 +339,10 @@ struct Payload; impl SchedPayload for Payload { type Ctx = (); type ShareLock = LoomLock; + + fn name(&self) -> u64 { + 0 + } } /// The full message set (`crate::msg::Msg`), as opposed to the reduced [`Msg`] diff --git a/kernel/pure/sched/cpu.rs b/kernel/pure/sched/cpu.rs index 0c9738cbca1..11a43055fe5 100644 --- a/kernel/pure/sched/cpu.rs +++ b/kernel/pure/sched/cpu.rs @@ -920,13 +920,14 @@ impl CpuSched { return; } let key = task.key(); + let name = task.ext().name(); let urgency = if task.is_rt() { Urgency::Preempt } else { Urgency::Normal }; let transit = task.migrate(self.id, dst, now); - self.trace(env, now, TraceKind::Migrate { task: key, to: dst }); + self.trace(env, now, TraceKind::Migrate { task: key, name, to: dst }); let handle = env.cpus.get(dst); if handle.post_owned( Msg::Adopt { task: transit }, @@ -1061,7 +1062,7 @@ impl CpuSched { return; }; let task = entry.task.wake(self.id, cause, entry.class, now); - self.trace(env, now, TraceKind::Wake { task: key }); + self.trace(env, now, TraceKind::Wake { task: key, name: task.ext().name() }); self.place(task, env, now); } @@ -1073,7 +1074,7 @@ impl CpuSched { ) { let key = task.key(); let ready = task.adopt(self.id, now); - self.trace(env, now, TraceKind::Adopt { task: key }); + self.trace(env, now, TraceKind::Adopt { task: key, name: ready.ext().name() }); // Killed while in flight lands in the dying list rather than the run // queue, through `place`. The retire chase still terminates and for a // sharper reason: whoever ends up owning the task *dispatches* it, and @@ -1106,7 +1107,7 @@ impl CpuSched { entry.class, now, ); - self.trace(env, now, TraceKind::Wake { task: key }); + self.trace(env, now, TraceKind::Wake { task: key, name: task.ext().name() }); self.place(task, env, now); } Claim::PrePark => panic!("a parked task cannot be pre-park"), @@ -1117,7 +1118,7 @@ impl CpuSched { if let Some(ready) = self.rq.remove(key) { // Out of the fair queue and into the dying list. No refcount // movement: it was runnable in the queue and it is runnable here. - self.trace(env, now, TraceKind::Wake { task: key }); + self.trace(env, now, TraceKind::Wake { task: key, name: ready.ext().name() }); self.keep_dying(ready, now); return; } @@ -1585,6 +1586,7 @@ impl<'c, 'e, H: Hw, P: PreemptGuard> SchedPass<'c, 'e, H, P, Undisposed> { .take() .expect("dispose_block without a running task"); let key = current.key(); + let name = current.ext().name(); let class = ticket.class(); let task = current.park( &ticket, @@ -1603,7 +1605,7 @@ impl<'c, 'e, H: Hw, P: PreemptGuard> SchedPass<'c, 'e, H, P, Undisposed> { }, ); self.cpu - .trace(self.env, self.now, TraceKind::ParkCommit { task: key }); + .trace(self.env, self.now, TraceKind::ParkCommit { task: key, name }); self.dispose() } @@ -1636,11 +1638,12 @@ impl<'c, 'e, H: Hw, P: PreemptGuard> SchedPass<'c, 'e, H, P, Undisposed> { .take() .expect("dispose_exit without a running task"); let key = current.key(); + let name = current.ext().name(); let dead = current.die(self.cpu.id, self.now); dead.share().leave_runnable(self.env.frontier); self.cpu.dispose_dead(dead, self.env); self.cpu - .trace(self.env, self.now, TraceKind::Retire { task: key }); + .trace(self.env, self.now, TraceKind::Retire { task: key, name }); self.dispose() } @@ -1836,6 +1839,7 @@ impl SchedPass<'_, '_, H, P, Disposed> { if let Some(corpse) = self.cpu.dying.pop_front() { let task = corpse.task; let key = task.key(); + let name = task.ext().name(); self.cpu.running = Some(task.dispatch(self.cpu.id, self.now)); // An aged corpse is borrowing the CPU from the RT band, so it // borrows a chunk and not a quantum. With the band empty it is @@ -1847,7 +1851,7 @@ impl SchedPass<'_, '_, H, P, Disposed> { QUANTUM_NS }); self.cpu - .trace(self.env, self.now, TraceKind::Schedule { task: key }); + .trace(self.env, self.now, TraceKind::Schedule { task: key, name }); return; } } @@ -1857,11 +1861,12 @@ impl SchedPass<'_, '_, H, P, Disposed> { if let Some((vruntime, task)) = self.cpu.rq.pop_next() { self.env.frontier.advance(vruntime); let key = task.key(); + let name = task.ext().name(); self.cpu.running = Some(task.dispatch(self.cpu.id, self.now)); self.cpu.aged_grant = false; self.cpu.quantum_end = self.now.after(QUANTUM_NS); self.cpu - .trace(self.env, self.now, TraceKind::Schedule { task: key }); + .trace(self.env, self.now, TraceKind::Schedule { task: key, name }); } } @@ -2418,6 +2423,10 @@ mod tests { impl SchedPayload for TestPayload { type Ctx = (); type ShareLock = TestLock; + + fn name(&self) -> u64 { + 0 + } } #[derive(Default)] diff --git a/kernel/pure/sched/hw.rs b/kernel/pure/sched/hw.rs index 8c7cd832f0c..defdd656803 100644 --- a/kernel/pure/sched/hw.rs +++ b/kernel/pure/sched/hw.rs @@ -41,14 +41,12 @@ impl Nanos { /// per-CPU binary trace ring and the simulator's recorder. /// /// Vocabulary, not wire format: this is a Rust enum with no layout guarantee. -/// `kernel/src/trace.rs`'s `Record` is the wire form, and `trace::record` is the -/// total mapping onto it. /// /// There is deliberately **no** converter from a captured kernel ring back into /// a sim run. A `Scenario` is a workload — which queue each thread blocks on, /// what makes its condition true, how long it runs — and the ring records none -/// of that; it records an observed schedule, from a 4096-entry buffer that -/// wraps, so a capture is a tail with no initial state to replay from. +/// of that; it records an observed schedule, from a buffer that wraps, so a +/// capture is a tail with no initial state to replay from. #[derive(Clone, Copy, PartialEq, Eq, Debug)] pub struct TraceEvent { pub ts: Nanos, @@ -58,18 +56,16 @@ pub struct TraceEvent { #[derive(Clone, Copy, PartialEq, Eq, Debug)] pub enum TraceKind { - /// `task` was picked and dispatched. - Schedule { task: TaskKey }, - Wake { task: TaskKey }, - Block { task: TaskKey }, + /// `task` was picked and dispatched; every `name` is its payload's + /// [`crate::sched::task::SchedPayload::name`]. + Schedule { task: TaskKey, name: u64 }, + Wake { task: TaskKey, name: u64 }, /// Two-phase wait commit parked the task. - ParkCommit { task: TaskKey }, - Migrate { task: TaskKey, to: CpuId }, - Adopt { task: TaskKey }, - Retire { task: TaskKey }, + ParkCommit { task: TaskKey, name: u64 }, + Migrate { task: TaskKey, name: u64, to: CpuId }, + Adopt { task: TaskKey, name: u64 }, + Retire { task: TaskKey, name: u64 }, IdleEnter, - IdleExit, - Irq, TimerFire, } diff --git a/kernel/pure/sched/task.rs b/kernel/pure/sched/task.rs index 05a1fa399a5..c229b8413e6 100644 --- a/kernel/pure/sched/task.rs +++ b/kernel/pure/sched/task.rs @@ -33,6 +33,11 @@ pub trait SchedPayload: Sized + Send + 'static { /// environment because the scheduler core may not implement a lock itself /// (see [`CellLock`]). type ShareLock: CellLock + Send; + + /// The environment's own name for the task, which a [`crate::sched::hw::TraceEvent`] + /// carries beside its key: a key is never reused and names nothing outside + /// the core. + fn name(&self) -> u64; } /// Shorthand for the share type a payload implies. diff --git a/kernel/sim/src/invariants.rs b/kernel/sim/src/invariants.rs index 1576906f8bc..cb926f110a8 100644 --- a/kernel/sim/src/invariants.rs +++ b/kernel/sim/src/invariants.rs @@ -308,7 +308,7 @@ fn check_retires(vm: &mut Vm<'_>) { let fresh = s.trace[vm.trace_cursor..] .iter() .filter_map(|ev| match ev.kind { - kernel::sched::hw::TraceKind::Migrate { task, to } => Some((task, to.0)), + kernel::sched::hw::TraceKind::Migrate { task, to, .. } => Some((task, to.0)), _ => None, }) .collect(); diff --git a/kernel/sim/src/payload.rs b/kernel/sim/src/payload.rs index e34fb1a64fd..3cf83438218 100644 --- a/kernel/sim/src/payload.rs +++ b/kernel/sim/src/payload.rs @@ -89,4 +89,8 @@ pub struct SimCtx { impl SchedPayload for SimPayload { type Ctx = SimCtx; type ShareLock = SimShareLock; + + fn name(&self) -> u64 { + self.key.0 + } } diff --git a/kernel/src/irq_ring.rs b/kernel/src/irq_ring.rs index a71e5204c1c..f6849eddbca 100644 --- a/kernel/src/irq_ring.rs +++ b/kernel/src/irq_ring.rs @@ -10,7 +10,7 @@ use crate::arch::percpu; use crate::scheduler::MAX_CPUS; /// Interrupt sources that drive scheduling; exhaustive, so a new variant requires updating every `match`. -/// The discriminant is `trace::Kind::IrqDrain`'s top byte, pinned for the reason `Kind` is. +/// The discriminant is `trace::Kind::IrqDrain`'s top byte. #[derive(Clone, Copy, PartialEq, Eq, Debug)] pub enum IrqSource { Xhci = 2, diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index d175c33aaa7..5c819b5ab52 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -125,7 +125,7 @@ const CHUNK: u64 = 8; pub fn drain_locked(guard: &mut BackendGuard) { let mut cursor = DRAINED.take(); let mut sink = Registers { out: guard }; - drain_ordered(&mut cursor, &mut sink); + drain_ordered(&super::shards(), &mut cursor, &mut sink); DRAINED.put(&cursor); } @@ -134,7 +134,7 @@ pub fn drain_locked(guard: &mut BackendGuard) { fn discard_pending() { let mut cursor = DRAINED.take(); let mut sink = Discard; - drain_ordered(&mut cursor, &mut sink); + drain_ordered(&super::shards(), &mut cursor, &mut sink); DRAINED.put(&cursor); LOST.store(DRAINED.lost(), Ordering::Relaxed); } @@ -143,7 +143,7 @@ fn discard_pending() { fn drain_records(wire: &SleepGuard<'_, ()>, budget: u64) -> u64 { let mut cursor = DRAINED.take(); let mut sink = Wire { wire, records: 0, budget }; - drain_ordered(&mut cursor, &mut sink); + drain_ordered(&super::shards(), &mut cursor, &mut sink); let records = sink.records; DRAINED.put(&cursor); RECORDS.fetch_add(records, Ordering::Relaxed); @@ -158,7 +158,7 @@ fn drain_records(wire: &SleepGuard<'_, ()>, budget: u64) -> u64 { pub unsafe fn drain_bypassed(uart: &mut PanicUart) { let mut cursor = DRAINED.take(); let mut sink = Raw { uart }; - drain_ordered(&mut cursor, &mut sink); + drain_ordered(&super::shards(), &mut cursor, &mut sink); DRAINED.put(&cursor); } diff --git a/kernel/src/log/mod.rs b/kernel/src/log/mod.rs index 7dcea32f8e7..c6c9067b9ce 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -47,10 +47,9 @@ pub fn shard_for(cpu: u32) -> &'static Shard { // SAFETY: a `Shard` is not zero-sized; the block is never freed. let ptr = unsafe { alloc::alloc::alloc_zeroed(layout) }.cast::(); assert!(!ptr.is_null(), "log: no memory for cpu{cpu}'s shard"); - // SAFETY: fresh, zeroed and aligned for a `Shard`, and not yet published; - // then live and initialised for the machine's life, as `publish` needs. + // SAFETY: fresh, zeroed and aligned for a `Shard`, which zeroed is an + // empty one, live for the machine's life as `publish` needs. unsafe { - Shard::initialize_zeroed(ptr); registry::publish(registry::kernel_slots(), cpu, ptr); &*ptr } @@ -106,12 +105,6 @@ pub fn shards() -> [Option<&'static Shard>; MAX_LOG_SHARDS] { out } -/// Shards answerable right now: counted once published, not merely declared; -/// it only ever grows, and never past `MAX_LOG_SHARDS`. -pub fn shard_count() -> u32 { - shards().iter().filter(|shard| shard.is_some()).count() as u32 -} - /// Builds a record's message bytes in place for [`emit`]; one pass and one /// sink, since the console line is rendered from this record through the one /// formatter in `toyos-abi`. diff --git a/kernel/src/log/read.rs b/kernel/src/log/read.rs index ad3e658760d..549d7bc0049 100644 --- a/kernel/src/log/read.rs +++ b/kernel/src/log/read.rs @@ -1,17 +1,34 @@ //! Two record readers, each correct for one caller: [`snapshot_committed`] -//! (newest first, lock-free, never blocks) and [`drain_ordered`] (oldest -//! first in sequence order per shard, stopping at the first uncommitted -//! record). +//! (the log's, newest first, lock-free, never blocks) and [`drain_ordered`] +//! (any [`Stream`]'s, oldest first in sequence order per ring, stopping at the +//! first uncommitted record). use toyos_abi::log::{LogRecord, MAX_LOG_SHARDS}; -use super::shard::{Shard, FIRST_SEQ}; +use super::shard::{Ring, Shard, FIRST_SEQ}; /// Accepts one record; `false` means it was not taken and ends the walk. -pub trait RecordSink { - fn put(&mut self, record: &LogRecord) -> bool; +pub trait RecordSink { + fn put(&mut self, record: &R) -> bool; } +/// A ring whose slots decode as one kind of record. +pub trait Stream { + type Record; + /// Record `seq`, or `None` if the ring cannot answer for it. + fn record(&self, seq: u64) -> Option; +} + +impl Stream for Shard { + type Record = LogRecord; + fn record(&self, seq: u64) -> Option { + self.read(seq) + } +} + +/// One ring per CPU a cursor can name; `None` is a CPU this machine lacks. +pub type Rings = [Option<&'static Ring>; MAX_LOG_SHARDS]; + #[derive(Clone, Copy)] struct Descent { shard: Option<&'static Shard>, @@ -38,7 +55,7 @@ impl Descent { while self.next >= self.floor { let seq = self.next; self.next = seq - 1; - let Some(at_ns) = shard.at_ns(seq) else { continue }; + let Some(at_ns) = shard.stamp(seq) else { continue }; if at_ns > to { continue; } @@ -67,10 +84,13 @@ impl Cursor { /// A caller's `LogCursor` as a walk, or `None` for a position past the number its shard issues /// next; its `lost` is never read, so the walk counts this read's loss alone. - pub fn from_reader(cursor: &toyos_abi::log::LogCursor) -> Option { + pub fn from_reader( + cursor: &toyos_abi::log::LogCursor, + rings: &Rings, + ) -> Option { // An unpublished shard is held to the head it is published with, so no cursor is ahead of one that appears mid-walk. - let issued = |shard: Option<&'static Shard>| shard.map_or(FIRST_SEQ, Shard::head); - let ahead = cursor.next.iter().zip(super::shards()).any(|(&next, shard)| next > issued(shard)); + let issued = |ring: &Option<&'static Ring>| ring.map_or(FIRST_SEQ, Ring::head); + let ahead = cursor.next.iter().zip(rings).any(|(&next, ring)| next > issued(ring)); (!ahead).then_some(Self { next: cursor.next, lost: 0 }) } @@ -81,7 +101,7 @@ impl Cursor { } /// Clamps this shard's position to what it can still answer for, counting the gap as loss. - fn open(&mut self, i: usize, shard: Option<&'static Shard>) -> Option { + fn open(&mut self, i: usize, shard: Option<&'static Ring>) -> Option { let shard = shard?; let oldest = shard.oldest_readable(); // Clamped to `FIRST_SEQ`: a zeroed cursor from the syscall boundary must not read as having missed everything. @@ -90,7 +110,7 @@ impl Cursor { self.lost += oldest.saturating_sub(want); let want = want.max(oldest); *self.next.get_mut(i)? = want; - shard.at_ns(want) + shard.stamp(want) } } @@ -154,10 +174,16 @@ impl Published { } } -/// Every record this cursor has not seen, oldest first merged by `at_ns`; a -/// stalled shard is skipped, not waited for. -pub fn drain_ordered(cursor: &mut Cursor, out: &mut impl RecordSink) -> usize { - let shards = super::shards(); +/// Every record this cursor has not seen in `shards`, oldest first merged by +/// stamp; a stalled shard is skipped, not waited for. +pub fn drain_ordered( + shards: &Rings, + cursor: &mut Cursor, + out: &mut impl RecordSink< as Stream>::Record>, +) -> usize +where + Ring: Stream, +{ let mut cand = [None; MAX_LOG_SHARDS]; for (i, slot) in cand.iter_mut().enumerate() { *slot = cursor.open(i, shards[i]); @@ -178,7 +204,7 @@ pub fn drain_ordered(cursor: &mut Cursor, out: &mut impl RecordSink) -> usize { // `match`, not `if let`: the empty arm explains itself below. #[allow(clippy::single_match)] - match shard.read(cursor.next[i]) { + match shard.record(cursor.next[i]) { Some(record) => { if !out.put(&record) { return emitted; @@ -220,7 +246,7 @@ pub fn any_committed(cursor: &Cursor) -> bool { .any(|(i, shard)| match shard { Some(shard) => { let want = cursor.next[i].max(FIRST_SEQ).max(shard.oldest_readable()); - shard.at_ns(want).is_some() + shard.stamp(want).is_some() } None => false, }) diff --git a/kernel/src/log/shard.rs b/kernel/src/log/shard.rs index 4d800c58890..3f22a5e0ef6 100644 --- a/kernel/src/log/shard.rs +++ b/kernel/src/log/shard.rs @@ -1,4 +1,9 @@ //! One CPU's ring of whole records: writers and readers never observe a torn record. +//! +//! [`Ring`] is the slot protocol, over any number of body words whose first is +//! the record's stamp; the log's [`Shard`] and `crate::trace`'s rings are both +//! one. A zeroed ring is an empty one, so a ring needs no constructor run on +//! zeroed storage and a `static` of one is `.bss`. //! Compiled a second time by `kernel-loom`, which shims only the atomics and `arch::percpu_fetch_add`. #[cfg(not(feature = "loom"))] @@ -63,61 +68,61 @@ fn msg_words(len: u16) -> usize { (len as usize).min(MSG_BYTES).div_ceil(8) } -/// First sequence number any shard issues; never 0, since a zeroed slot reads as sequence 0. +/// First sequence number any ring issues; never 0, since a zeroed slot reads as sequence 0. pub const FIRST_SEQ: u64 = 1; // A slot mid-write, holding no record a reader may accept; `u64::MAX` is unreachable as a real sequence number. // The only state this word carries, not a separate flag that could disagree with it. const WRITING: u64 = u64::MAX; -/// One record's storage, laid out exactly as [`LogRecord`]; every word is atomic because a reader may load while a writer stores. -#[repr(C, align(64))] -pub struct Slot { +/// One record's storage: every word is atomic because a reader may load while a writer stores. +#[repr(C)] +pub struct Slot { /// State word: a sequence number, [`WRITING`], or zero for untouched. seq: AtomicU64, - /// Identity words then message, little-endian; packed by [`header`], unpacked by [`Shard::read`]. - body: [AtomicU64; BODY_WORDS], + /// The record's words; the first is its stamp, which a merge across rings orders by. + body: [AtomicU64; W], } -// Layout assertions are skipped under loom: its atomics carry tracking state and are wider than the real ones. -#[cfg(not(feature = "loom"))] -const _: () = assert!(core::mem::size_of::() == RECORD_BYTES); -#[cfg(not(feature = "loom"))] -const _: () = assert!(core::mem::align_of::() == 64); -#[cfg(not(feature = "loom"))] -const _: () = assert!(core::mem::offset_of!(Slot, seq) == 0); -const _: () = assert!(core::mem::offset_of!(LogRecord, at_ns) == core::mem::size_of::()); +/// The ring's reservation count alone on its cache line, so the slots after it start on one. +#[repr(C, align(64))] +struct Issued(AtomicU64); -/// One CPU's records. +/// One CPU's records, `N` slots of `W` body words. #[repr(C, align(64))] -pub struct Shard { - /// Next sequence number this shard will issue (a reservation count, not a commit count); only the owning CPU writes it. - head: AtomicU64, - slots: [Slot; SHARD_RECORDS], +pub struct Ring { + /// Sequence numbers this ring has handed out, so zero is an empty ring; only the owning CPU writes it. + issued: Issued, + slots: [Slot; N], } +/// The log's ring: a [`LogRecord`] a slot, laid out exactly as one. +pub type Shard = Ring; + +// Layout assertions are skipped under loom: its atomics carry tracking state and are wider than the real ones. +#[cfg(not(feature = "loom"))] +const _: () = assert!(core::mem::size_of::>() == RECORD_BYTES); #[cfg(not(feature = "loom"))] -const _: () = assert!(core::mem::offset_of!(Shard, head) == 0); +const _: () = assert!(core::mem::offset_of!(Shard, slots) == 64); +const _: () = assert!(core::mem::offset_of!(LogRecord, at_ns) == core::mem::size_of::()); -impl Shard { +impl Ring { + /// An empty ring: every word zero. #[cfg(not(feature = "loom"))] pub const fn new() -> Self { - // `EMPTY` is never written or borrowed; its only use is the array repeat below. - #[allow(clippy::declare_interior_mutable_const)] - const EMPTY: Slot = Slot { - seq: AtomicU64::new(0), - body: [const { AtomicU64::new(0) }; BODY_WORDS], - }; - Self { head: AtomicU64::new(FIRST_SEQ), slots: [EMPTY; SHARD_RECORDS] } + Self { + issued: Issued(AtomicU64::new(0)), + slots: [const { Slot { seq: AtomicU64::new(0), body: [const { AtomicU64::new(0) }; W] } }; N], + } } - /// Loom's atomics have no `const` constructor, so this builds shards at run time. + /// Loom's atomics have no `const` constructor, so this builds rings at run time. // No `Default` beside it: the kernel's arm must stay `const`, which `Default::default` cannot be. #[allow(clippy::new_without_default)] #[cfg(feature = "loom")] pub fn new() -> Self { Self { - head: AtomicU64::new(FIRST_SEQ), + issued: Issued(AtomicU64::new(0)), slots: core::array::from_fn(|_| Slot { seq: AtomicU64::new(0), body: core::array::from_fn(|_| AtomicU64::new(0)), @@ -125,136 +130,130 @@ impl Shard { } } - /// How many records this shard has ever reserved (`Acquire`, paired with the commit store). + /// The next sequence number this ring will issue (a reservation count, not a commit count; `Acquire`, paired with the commit store). pub fn head(&self) -> u64 { - self.head.load(Ordering::Acquire) + self.issued.0.load(Ordering::Acquire) + FIRST_SEQ } - /// Oldest sequence number this shard can still answer for. + /// Oldest sequence number this ring can still answer for. pub fn oldest_readable(&self) -> u64 { - self.head().saturating_sub(SHARD_RECORDS as u64).max(FIRST_SEQ) - } - - /// Finish constructing a shard obtained from zeroed allocation, in place: returning a [`Shard`] by value would put 512 KiB on the caller's stack. - /// # Safety - /// `ptr` must point to a zeroed, aligned, unpublished allocation for one [`Shard`], and be called exactly once. - #[cfg(not(feature = "loom"))] - pub unsafe fn initialize_zeroed(ptr: *mut Self) { - // SAFETY: writes only the word not already correct in zeroed storage, in place, under the caller's contract. - unsafe { - // `addr_of_mut!`, not `&mut (*ptr).head`: the rest of the allocation is not yet a valid `Shard`. - core::ptr::addr_of_mut!((*ptr).head).write(AtomicU64::new(FIRST_SEQ)); - } + self.head().saturating_sub(N as u64).max(FIRST_SEQ) } - /// Take the next sequence number, on the CPU that owns this shard. + /// Take the next sequence number, on the CPU that owns this ring. /// # Safety - /// Caller must be the owning CPU, and `guard` must stay live through the matching [`Shard::commit`]. + /// Caller must be the owning CPU, and `guard` must stay live through the matching [`Ring::publish`]. pub unsafe fn reserve(&self, guard: &crate::arch::IrqGuard) -> u64 { - crate::arch::percpu_fetch_add(&self.head, guard) + crate::arch::percpu_fetch_add(&self.issued.0, guard) + FIRST_SEQ } - /// Write a record's body into the slot `seq` names and publish it. + /// Write a record's body words into the slot `seq` names through `write`, which stores `Relaxed`, and publish it. /// # Safety - /// `seq` must come from this shard's own [`Shard::reserve`] with the same live `guard`, and this must be the first call for `seq`. - pub unsafe fn commit( + /// `seq` must come from this ring's own [`Ring::reserve`] with the same live `guard`, and this must be the first call for `seq`. + pub unsafe fn publish( &self, seq: u64, - record: &LogRecord, _guard: &crate::arch::IrqGuard, + write: impl FnOnce(&[AtomicU64; W]), ) { debug_assert!( - self.head().saturating_sub(seq) < SHARD_RECORDS as u64, - "reservation {seq} was lapped inside its publication bracket: an IF-ignoring path emitted a whole shard generation before this commit" + self.head().saturating_sub(seq) < N as u64, + "reservation {seq} was lapped inside its publication bracket: an IF-ignoring path emitted a whole ring generation before this commit" ); - let slot = &self.slots[(seq % SHARD_RECORDS as u64) as usize]; + let slot = &self.slots[(seq % N as u64) as usize]; // Mark the slot `WRITING` before the body write, so a racing reader's re-check cannot see a false match. slot.seq.store(WRITING, Ordering::Relaxed); fence(Ordering::Release); // Relaxed: the fence above and the release store below order the whole body against the sequence number. - let len = record.len.min(MSG_BYTES as u16); - for (word, value) in slot.body.iter().zip(header(record, len)) { - word.store(value, Ordering::Relaxed); - } - let words = msg_words(len); - for i in 0..words { - let mut bytes = [0u8; 8]; - bytes.copy_from_slice(&record.msg[i * 8..i * 8 + 8]); - slot.body[HEADER_WORDS + i].store(u64::from_le_bytes(bytes), Ordering::Relaxed); - } + write(&slot.body); // Last store: this publishes the record. slot.seq.store(seq, PUBLISH); } - /// Timestamp of record `seq`, under [`Shard::read`]'s validity test, without copying the body. - /// Exists so a merge across shards can hold one candidate each without a whole [`LogRecord`] per shard. - pub fn at_ns(&self, seq: u64) -> Option { + /// What `load` makes of record `seq`'s words, which it loads `Relaxed`, or `None` if this ring cannot answer for it. + pub fn load(&self, seq: u64, load: impl FnOnce(&[AtomicU64; W]) -> T) -> Option { + // Both bounds needed: `head` alone counts reservations, so `seq < head` admits a slot not yet committed. if seq < self.oldest_readable() || seq >= self.head() { return None; } - let slot = &self.slots[(seq % SHARD_RECORDS as u64) as usize]; + let slot = &self.slots[(seq % N as u64) as usize]; + // No ABA: slot `j` only ever holds numbers congruent to `j` mod `N`, and `seq` never wraps, so a stale value can't match. if slot.seq.load(Ordering::Acquire) != seq { return None; } - let at_ns = slot.body[0].load(Ordering::Relaxed); + // A writer may be storing here now; the re-check below discards a torn result. + let loaded = load(&slot.body); + // Re-check is total: a writer marks `WRITING` before touching the body, so a match here means nothing wrote in between. fence(Ordering::Acquire); if slot.seq.load(Ordering::Relaxed) != seq { return None; } - Some(at_ns) + Some(loaded) } - /// Copy record `seq` out, or `None` if this shard cannot answer for it. - pub fn read(&self, seq: u64) -> Option { - // Both bounds needed: `head` alone counts reservations, so `seq < head` admits a slot not yet committed. - if seq < self.oldest_readable() || seq >= self.head() { - return None; - } - let slot = &self.slots[(seq % SHARD_RECORDS as u64) as usize]; - // No ABA: slot `j` only ever holds numbers congruent to `j` mod `SHARD_RECORDS`, and `seq` never wraps, so a stale value can't match. - if slot.seq.load(Ordering::Acquire) != seq { - return None; - } - - // Atomic loads: a writer may be storing here now; the re-check below discards a torn result. - let identity = slot.body[1].load(Ordering::Relaxed); - let shape = slot.body[2].load(Ordering::Relaxed); - // `len` may be garbage mid-recycle; clamping keeps the read in bounds. - let len = ((shape >> 16) as u16).min(MSG_BYTES as u16); - let mut record = LogRecord { - seq, - at_ns: slot.body[0].load(Ordering::Relaxed), - pid: identity as u32, - tid: (identity >> 32) as u32, - cpu: shape as u16, - len, - elided: (shape >> 32) as u16, - severity: (shape >> 48) as u8, - flags: (shape >> 56) as u8, - msg: [0; MAX_RECORD_MESSAGE], - }; - for i in 0..msg_words(len) { - let bytes = slot.body[HEADER_WORDS + i].load(Ordering::Relaxed).to_le_bytes(); - record.msg[i * 8..i * 8 + 8].copy_from_slice(&bytes); - } + /// Stamp of record `seq`, under [`Ring::load`]'s validity test, without copying the rest. + /// Exists so a merge across rings can hold one candidate each without a whole record per ring. + pub fn stamp(&self, seq: u64) -> Option { + self.load(seq, |body| body[0].load(Ordering::Relaxed)) + } +} - // Re-check is total: a writer marks `WRITING` before touching the body, so a match here means nothing wrote in between. - fence(Ordering::Acquire); - if slot.seq.load(Ordering::Relaxed) != seq { - return None; +impl Shard { + /// Write a record's body into the slot `seq` names and publish it. + /// # Safety + /// [`Ring::publish`]'s. + pub unsafe fn commit(&self, seq: u64, record: &LogRecord, guard: &crate::arch::IrqGuard) { + // SAFETY: the caller's contract is `publish`'s. + unsafe { + self.publish(seq, guard, |body| { + let len = record.len.min(MSG_BYTES as u16); + for (word, value) in body.iter().zip(header(record, len)) { + word.store(value, Ordering::Relaxed); + } + for i in 0..msg_words(len) { + let mut bytes = [0u8; 8]; + bytes.copy_from_slice(&record.msg[i * 8..i * 8 + 8]); + body[HEADER_WORDS + i].store(u64::from_le_bytes(bytes), Ordering::Relaxed); + } + }) } + } - Some(record) + /// Copy record `seq` out, or `None` if this shard cannot answer for it. + pub fn read(&self, seq: u64) -> Option { + self.load(seq, |body| { + let identity = body[1].load(Ordering::Relaxed); + let shape = body[2].load(Ordering::Relaxed); + // `len` may be garbage mid-recycle; clamping keeps the read in bounds. + let len = ((shape >> 16) as u16).min(MSG_BYTES as u16); + let mut record = LogRecord { + seq, + at_ns: body[0].load(Ordering::Relaxed), + pid: identity as u32, + tid: (identity >> 32) as u32, + cpu: shape as u16, + len, + elided: (shape >> 32) as u16, + severity: (shape >> 48) as u8, + flags: (shape >> 56) as u8, + msg: [0; MAX_RECORD_MESSAGE], + }; + for i in 0..msg_words(len) { + let bytes = body[HEADER_WORDS + i].load(Ordering::Relaxed).to_le_bytes(); + record.msg[i * 8..i * 8 + 8].copy_from_slice(&bytes); + } + record + }) } } -// `Shard` is `Sync` by auto-derivation (every word is `AtomicU64`); no hand-written `unsafe impl` needed. +// `Ring` is `Sync` by auto-derivation (every word is `AtomicU64`); no hand-written `unsafe impl` needed. /// Is a reader parked on this machine's records? Kept as one flag so the producer's fast path avoids a locked read-modify-write. #[cfg(not(feature = "loom"))] diff --git a/kernel/src/log/user.rs b/kernel/src/log/user.rs index dfdd429ecda..be121825fcf 100644 --- a/kernel/src/log/user.rs +++ b/kernel/src/log/user.rs @@ -1,16 +1,17 @@ -//! Kernel side of `SYS_LOG_READ` and its readiness source. +//! Kernel side of `SYS_LOG_READ` and its readiness source, and the read `SYS_TRACE_READ` shares. //! -//! No per-reader state in a read: a cursor is the caller's own sequence numbers, copied in, refused if ahead of a shard, walked, and copied back with this read's loss; readers coexist uncoordinated. Requires [`Rights::LOG`] on a `SysCap`, not ambient. +//! No per-reader state in a read: a cursor is the caller's own sequence numbers, copied in, refused if ahead of a ring, walked, and copied back with this read's loss; readers coexist uncoordinated. Requires [`Rights::LOG`] on a `SysCap`, not ambient. //! //! [`Rights::LOG`]: toyos_abi::handle::Rights::LOG -use toyos_abi::log::{LogCursor, LogRecord, RECORD_BYTES}; +use toyos_abi::log::{LogCursor, LogRecord}; use toyos_abi::syscall::SyscallError; use crate::watch::Watch; use crate::user_ptr::UserBytesMut; -use super::read::{drain_ordered, Cursor, RecordSink}; +use super::read::{drain_ordered, Cursor, RecordSink, Rings, Stream}; +use super::shard::Ring; /// What a log poll waits on: edge-triggered, since a reader's position is its own cursor and the kernel holds none. pub static WATCH: Watch = Watch::new(); @@ -22,19 +23,21 @@ pub fn post_readiness() { WATCH.post(); } -// Fixed `RECORD_BYTES` stride, never packed: the caller indexes by shift, so the kernel does no length arithmetic. -struct UserRecords<'a, 'b> { +// Fixed stride, never packed: the caller indexes by shift, so the kernel does no length arithmetic. +struct UserRecords<'a, 'b, R> { out: &'a mut UserBytesMut<'b>, written: usize, capacity: usize, + bytes: fn(&R) -> &[u8], } -impl RecordSink for UserRecords<'_, '_> { - fn put(&mut self, record: &LogRecord) -> bool { +impl RecordSink for UserRecords<'_, '_, R> { + fn put(&mut self, record: &R) -> bool { if self.written >= self.capacity { return false; } - self.out.write_at(self.written * RECORD_BYTES, record.as_bytes()); + let bytes = (self.bytes)(record); + self.out.write_at(self.written * bytes.len(), bytes); self.written += 1; true } @@ -46,21 +49,36 @@ pub fn read( out: &mut UserBytesMut, capacity: usize, ) -> Result { - let shards = super::shard_count(); - // Refused, not truncated: a capacity below one record per shard cannot hold what a single call may have to merge. + read_rings(&super::shards(), cursor, out, capacity, LogRecord::as_bytes) +} + +/// Copies records `cursor` has not seen in `rings` into `out`, oldest first, +/// each as `bytes` writes it; never blocks. +pub fn read_rings( + rings: &Rings, + cursor: &mut LogCursor, + out: &mut UserBytesMut, + capacity: usize, + bytes: fn(& as Stream>::Record) -> &[u8], +) -> Result +where + Ring: Stream, +{ + let shards = rings.iter().flatten().count() as u32; + // Refused, not truncated: a capacity below one record per ring cannot hold what a single call may have to merge. if capacity == 0 || capacity < shards as usize { return Err(SyscallError::InvalidArgument); } - let Some(mut walk) = Cursor::from_reader(cursor) else { + let Some(mut walk) = Cursor::from_reader(cursor, rings) else { return Err(SyscallError::InvalidArgument); }; - let mut sink = UserRecords { out, written: 0, capacity }; - drain_ordered(&mut walk, &mut sink); + let mut sink = UserRecords { out, written: 0, capacity, bytes }; + drain_ordered(rings, &mut walk, &mut sink); let written = sink.written; walk.write_into(cursor); - // Written unconditionally, so a caller starting from a zeroed cursor learns the shard count from the first reply. + // Written unconditionally, so a caller starting from a zeroed cursor learns the ring count from the first reply. cursor.shards = shards; Ok(written) } diff --git a/kernel/src/sched/payload.rs b/kernel/src/sched/payload.rs index c4be530acd2..b0fa2532d47 100644 --- a/kernel/src/sched/payload.rs +++ b/kernel/src/sched/payload.rs @@ -70,6 +70,11 @@ pub struct KernelPayload { impl SchedPayload for KernelPayload { type Ctx = KernelCtx; type ShareLock = KernelLock; + + /// The thread, as `TaskId::pack` packs it: what a diary record names. + fn name(&self) -> u64 { + self.id.pack() + } } /// State word values for `task_sched_state` (the `ps` column). diff --git a/kernel/src/syscall/dispatch.rs b/kernel/src/syscall/dispatch.rs index d2f3ef0c66a..c8262860101 100644 --- a/kernel/src/syscall/dispatch.rs +++ b/kernel/src/syscall/dispatch.rs @@ -42,6 +42,7 @@ use super::ipc::{ }; use super::machine::{ sys_counters, sys_device_inventory, sys_log_read, sys_reboot, sys_sched_info, sys_shutdown, sys_sysinfo, + sys_trace_read, MAX_INVENTORY_RECORDS, }; #[cfg(feature = "test-actuators")] @@ -464,6 +465,15 @@ pub(crate) fn syscall_dispatch(num: u64, a1: u64, a2: u64, a3: u64, a4: u64) -> // it copies in the caller's cursor. sys_log_read(&ctx, RawHandle(a1 as u32), UserAddr::new(a2), &mut out, a4 as usize) } + SYS_TRACE_READ => { + let Some(bytes) = (a4 as usize).checked_mul(toyos_abi::trace::RECORD_BYTES) else { + return SyscallError::InvalidArgument.to_u64(); + }; + let Some(mut out) = ctx.user_bytes_mut(UserAddr::new(a3), bytes as u64) else { + return bad_addr; + }; + sys_trace_read(&ctx, RawHandle(a1 as u32), UserAddr::new(a2), &mut out, a4 as usize) + } SYS_ACCEPT => sys_accept(RawHandle(a1 as u32)), SYS_HANDLE_SEND => { if a3 as usize > MAX_TRANSFER_HANDLES { @@ -606,6 +616,10 @@ pub(crate) fn syscall_dispatch(num: u64, a1: u64, a2: u64, a3: u64, a4: u64) -> // bound and its stale answer are the shipped paths. DA::COUNTERS_DEAF => crate::counters::deaf::stage(a2), DA::COUNTERS_HEAR => crate::counters::deaf::end(), + DA::TRACE_FLOOD => match Untrusted::new(a2).at_most(DA::TRACE_FLOOD_MOST) { + Ok(count) => crate::trace::flood(count), + Err(_) => SyscallError::InvalidArgument.to_u64(), + }, _ => SyscallError::InvalidArgument.to_u64(), }, SYS_SCHED_INFO => match ctx.copy_out(UserAddr::new(a1), &sys_sched_info()) { diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index df469aa4150..3b22b8355ab 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -1,6 +1,6 @@ //! What a process may learn about the machine, and the two things it may do to it. //! -//! [`sys_log_read`], the roster half of [`sys_sysinfo`], and both of +//! [`sys_log_read`], [`sys_trace_read`], the roster half of [`sys_sysinfo`], and both of //! [`sys_shutdown`] and [`sys_reboot`] each require a `SysCap` bit from //! `/system/bin/supervisor`'s `system.toml`; `SYS_SYSINFO`'s header is ambient, and //! [`sys_sched_info`] demands nothing. @@ -18,8 +18,6 @@ use toyos_abi::syscall::*; use super::handles::demand_syscap; /// Copies kernel log records into the caller's buffer; requires a `SysCap` carrying [`Rights::LOG`]. -/// -/// A copy-out failure after a successful read costs the caller those records; the cursor round-trips through the caller's own memory. pub(super) fn sys_log_read( ctx: &SyscallContext, syscap: RawHandle, @@ -27,14 +25,38 @@ pub(super) fn sys_log_read( out: &mut UserBytesMut, capacity: usize, ) -> u64 { - if let Err(e) = demand_syscap(syscap, Rights::LOG) { + read_on_cursor(ctx, syscap, Rights::LOG, cursor_ptr, |cursor| log::user::read(cursor, out, capacity)) +} + +/// Copies the diary's records into the caller's buffer; requires a `SysCap` carrying [`Rights::TRACE`]. +pub(super) fn sys_trace_read( + ctx: &SyscallContext, + syscap: RawHandle, + cursor_ptr: UserAddr, + out: &mut UserBytesMut, + capacity: usize, +) -> u64 { + read_on_cursor(ctx, syscap, Rights::TRACE, cursor_ptr, |cursor| crate::trace::read(cursor, out, capacity)) +} + +/// A read of records on a cursor the caller holds, under `need`. +/// +/// A copy-out failure after a successful read costs the caller those records; the cursor round-trips through the caller's own memory. +fn read_on_cursor( + ctx: &SyscallContext, + syscap: RawHandle, + need: Rights, + cursor_ptr: UserAddr, + read: impl FnOnce(&mut C) -> Result, +) -> u64 { + if let Err(e) = demand_syscap(syscap, need) { return e.refuse(); } - let mut cursor = match ctx.copy_in::(cursor_ptr) { + let mut cursor = match ctx.copy_in::(cursor_ptr) { Ok(cursor) => cursor, Err(e) => return e.to_u64(), }; - let count = match log::user::read(&mut cursor, out, capacity) { + let count = match read(&mut cursor) { Ok(count) => count, Err(e) => return e.to_u64(), }; diff --git a/kernel/src/trace.rs b/kernel/src/trace.rs index 5038d1d2f32..49f1d67622a 100644 --- a/kernel/src/trace.rs +++ b/kernel/src/trace.rs @@ -1,214 +1,114 @@ -//! Kernel event tracing — per-CPU ring buffer of scheduler/timer/IRQ events, -//! dumped from LLDB on a wedged kernel via the `TRACE_RINGS` symbol. -//! Writer is single-CPU but tolerates interrupt recursion via `fetch_add` on -//! the head index; payload writes are non-atomic, so a reader may see a torn -//! record for the most recent entry. +//! The diary: a ring per CPU of `toyos_abi::trace` records, written always from +//! the timer, the scheduler, `irq_ring` and every +//! `kernel::sched::hw::TraceEvent` the core emits, and read by +//! `SYS_TRACE_READ` on `Rights::TRACE`. //! -//! [`Record`] is the `repr(C)` wire form of `kernel::sched::hw::TraceEvent`; -//! [`record`] maps one onto the other and is `Machine::trace`. +//! Each ring is the log's slot protocol ([`crate::log::shard::Ring`]) and is +//! read through the log's walk, so a record is published whole or not at all +//! and a reader's cursor is its own. A record is reserved, stamped with the +//! CPU's raw counter and published under one `IrqGuard`, so a CPU's ring is in +//! stamp order and an interrupt's record lands in a slot of its own. +//! +//! [`record`] maps a `TraceEvent` onto its [`Kind`] and is `Machine::trace`. -use core::cell::UnsafeCell; -use core::sync::atomic::{AtomicU64, Ordering}; +use core::sync::atomic::{AtomicBool, Ordering}; use kernel::sched::hw::{TraceEvent, TraceKind}; +pub use toyos_abi::trace::Kind; +use toyos_abi::trace::{TraceCursor, TraceRecord, NO_THREAD}; +use toyos_abi::syscall::SyscallError; -use crate::arch::percpu; - -pub const RING_CAPACITY: usize = 4096; - -/// Event kind discriminant, stable — do not reorder; read by LLDB as a raw `u16`. -#[repr(u16)] -#[derive(Clone, Copy, PartialEq, Eq)] -pub enum Kind { - /// `pid`/`tid` name the incoming task; `data` = 0. - SchedPick = 1, - SchedIdle = 2, // data = next_deadline_ms_low - Preempt = 3, // data = 0 - Block = 4, // data = 0 - Wake = 5, // data = 0 - TimerArm = 6, // data = nanos (low 32) - TimerStop = 7, // data = 0 - TimerFire = 8, // data = 0 - Mark = 9, // data = user-defined - IdleEnter = 10, // data = 0 — about to halt; the armed deadline is in TimerArm - IdleExit = 11, // data = 0 — ring observed cpu woke from halt - /// Burst summary of Ring 0 timer fires since the last kernel→user transition; `data` = fire count. - /// Batched so a demand-paging burst does not drown the ring buffer. - TimerFireBurst = 12, - /// `data` = IrqSource discriminant in the top byte, latency in µs in the low 24 bits. - /// Distinct from [`Kind::Irq`]: this is consumption, not entry. - IrqDrain = 13, - /// The two-phase wait commit parked the task. - ParkCommit = 14, - /// `data` = destination cpu id. - Migrate = 15, - Adopt = 16, - Retire = 17, - /// The core observed an interrupt. `data` = 0. - Irq = 18, -} - -// Must list every `Kind` variant; `every_kind_is_pinned` below enforces completeness. -// Renumbering would silently relabel events in traces already captured off metal, which cannot be re-read. -const _: () = { - assert!(Kind::SchedPick as u16 == 1); - assert!(Kind::SchedIdle as u16 == 2); - assert!(Kind::Preempt as u16 == 3); - assert!(Kind::Block as u16 == 4); - assert!(Kind::Wake as u16 == 5); - assert!(Kind::TimerArm as u16 == 6); - assert!(Kind::TimerStop as u16 == 7); - assert!(Kind::TimerFire as u16 == 8); - assert!(Kind::Mark as u16 == 9); - assert!(Kind::IdleEnter as u16 == 10); - assert!(Kind::IdleExit as u16 == 11); - assert!(Kind::TimerFireBurst as u16 == 12); - assert!(Kind::IrqDrain as u16 == 13); - assert!(Kind::ParkCommit as u16 == 14); - assert!(Kind::Migrate as u16 == 15); - assert!(Kind::Adopt as u16 == 16); - assert!(Kind::Retire as u16 == 17); - assert!(Kind::Irq as u16 == 18); -}; - -// No wildcard arm: adding a `Kind` variant must break this compile, not silently match. -#[allow(dead_code)] -const fn every_kind_is_pinned(kind: Kind) { - match kind { - Kind::SchedPick - | Kind::SchedIdle - | Kind::Preempt - | Kind::Block - | Kind::Wake - | Kind::TimerArm - | Kind::TimerStop - | Kind::TimerFire - | Kind::Mark - | Kind::IdleEnter - | Kind::IdleExit - | Kind::TimerFireBurst - | Kind::IrqDrain - | Kind::ParkCommit - | Kind::Migrate - | Kind::Adopt - | Kind::Retire - | Kind::Irq => (), - } -} +use crate::arch::{cpu, percpu, IrqGuard}; +use crate::log::read::{Rings, Stream}; +use crate::log::shard::Ring; +use crate::user_ptr::UserBytesMut; -/// Wire record: `repr(C)`, 24 bytes; field order chosen for LLDB hexdump reading. -#[repr(C)] -pub struct Record { - pub timestamp_ns: u64, - pub kind: u16, - pub cpu: u8, - pub _pad: u8, - pub pid: u32, - pub tid: u32, - pub data: u32, -} +/// Records per CPU: 256 KiB of 32-byte slots, 2 MiB at eight CPUs. +const SLOTS: usize = 8192; -const _: () = assert!(core::mem::size_of::() == 24); - -const EMPTY_EVENT: Record = Record { - timestamp_ns: 0, - kind: 0, - cpu: 0, - _pad: 0, - pid: 0, - tid: 0, - data: 0, -}; - -#[repr(C, align(64))] -pub struct TraceRing { - pub head: AtomicU64, // monotonic; slot index = head % RING_CAPACITY - pub events: UnsafeCell<[Record; RING_CAPACITY]>, -} +/// A slot's words past its sequence number: the stamp; the kind, CPU and +/// data; the pid and tid. +const WORDS: usize = 3; -// SAFETY: atomic slot allocation partitions writers; torn reads on the newest entry are tolerated. -unsafe impl Sync for TraceRing {} +type TraceRing = Ring; -impl TraceRing { - const fn new() -> Self { - Self { - head: AtomicU64::new(0), - events: UnsafeCell::new([EMPTY_EVENT; RING_CAPACITY]), - } - } -} +const _: () = assert!(core::mem::size_of::() == 64 + SLOTS * toyos_abi::trace::RECORD_BYTES); -#[no_mangle] -pub static TRACE_RINGS: [TraceRing; crate::sched::MAX_CPUS] = [ - TraceRing::new(), TraceRing::new(), TraceRing::new(), TraceRing::new(), - TraceRing::new(), TraceRing::new(), TraceRing::new(), TraceRing::new(), -]; +static RINGS: [TraceRing; crate::sched::MAX_CPUS] = [const { TraceRing::new() }; crate::sched::MAX_CPUS]; -/// Globally enable/disable tracing. Starts off; set to true once clock is up. -static ENABLED: core::sync::atomic::AtomicBool = core::sync::atomic::AtomicBool::new(false); +/// Off until the clock is up, so no record is stamped before the counter it is read against is. +static ENABLED: AtomicBool = AtomicBool::new(false); pub fn enable() { ENABLED.store(true, Ordering::Release); } -/// Records a trace event on the current CPU; wait-free and safe from any context, no-op until `enable()` is called. +/// Records an event on the current CPU against the thread running there; wait-free and safe from any context. #[inline] pub fn trace(kind: Kind, data: u32) { - let tid = percpu::current_tid().map_or(u32::MAX, |t| t.raw()); - let pid = percpu::current_pid().map_or(u32::MAX, |p| p.raw()); - push(percpu::cpu_id(), crate::clock::nanos_since_boot(), kind, pid, tid, data); + push(kind, None, data); } -// `cpu` is explicit, not `cpu_id()`, because a wrong value is the only way to break the ring's per-CPU single-writer property. +/// Reserve, stamp and publish under one guard, on the ring of the CPU the guard holds us to. #[inline] -fn push(cpu: u32, timestamp_ns: u64, kind: Kind, pid: u32, tid: u32, data: u32) { +fn push(kind: Kind, task: Option<(u32, u32)>, data: u32) { if !ENABLED.load(Ordering::Relaxed) { return; } - let cpu = cpu as usize; - if cpu >= crate::sched::MAX_CPUS { return; } - let ring = &TRACE_RINGS[cpu]; - let slot = ring.head.fetch_add(1, Ordering::Relaxed) as usize % RING_CAPACITY; - - // SAFETY: fetch_add gives each IRQ-vs-kernel writer on this CPU a distinct slot. + let guard = IrqGuard::close(); + let at = percpu::cpu_id(); + let Some(ring) = RINGS.get(at as usize) else { return }; + let (pid, tid) = task.unwrap_or_else(|| { + ( + percpu::current_pid().map_or(NO_THREAD, |p| p.raw()), + percpu::current_tid().map_or(NO_THREAD, |t| t.raw()), + ) + }); + // SAFETY: the guard holds this CPU, which owns `ring`, through the publish. unsafe { - let slot_ptr = (*ring.events.get()).as_mut_ptr().add(slot); - core::ptr::write(slot_ptr, Record { - timestamp_ns, - kind: kind as u16, - cpu: cpu as u8, - _pad: 0, - pid, - tid, - data, + let seq = ring.reserve(&guard); + let stamp = cpu::counter(); + ring.publish(seq, &guard, |body| { + body[0].store(stamp, Ordering::Relaxed); + body[1].store(kind as u64 | (at as u64) << 16 | (data as u64) << 32, Ordering::Relaxed); + body[2].store(pid as u64 | (tid as u64) << 32, Ordering::Relaxed); }); } } +impl Stream for TraceRing { + type Record = TraceRecord; + fn record(&self, seq: u64) -> Option { + self.load(seq, |body| { + let shape = body[1].load(Ordering::Relaxed); + let thread = body[2].load(Ordering::Relaxed); + TraceRecord { + seq, + stamp: body[0].load(Ordering::Relaxed), + kind: shape as u16, + cpu: (shape >> 16) as u16, + data: (shape >> 32) as u32, + pid: thread as u32, + tid: (thread >> 32) as u32, + } + }) + } +} + /// Encodes a scheduler-core event into the ring; no wildcard arm, so a new `TraceKind` variant fails to compile rather than being silently dropped. pub fn record(ev: TraceEvent) { let (kind, task, data) = match ev.kind { - TraceKind::Schedule { task } => (Kind::SchedPick, Some(task), 0), - TraceKind::Wake { task } => (Kind::Wake, Some(task), 0), - TraceKind::Block { task } => (Kind::Block, Some(task), 0), - TraceKind::ParkCommit { task } => (Kind::ParkCommit, Some(task), 0), - TraceKind::Migrate { task, to } => (Kind::Migrate, Some(task), to.0), - TraceKind::Adopt { task } => (Kind::Adopt, Some(task), 0), - TraceKind::Retire { task } => (Kind::Retire, Some(task), 0), + TraceKind::Schedule { name, .. } => (Kind::Pick, Some(name), 0), + TraceKind::Wake { name, .. } => (Kind::Wake, Some(name), 0), + TraceKind::ParkCommit { name, .. } => (Kind::ParkCommit, Some(name), 0), + TraceKind::Migrate { name, to, .. } => (Kind::Migrate, Some(name), to.0), + TraceKind::Adopt { name, .. } => (Kind::Adopt, Some(name), 0), + TraceKind::Retire { name, .. } => (Kind::Retire, Some(name), 0), TraceKind::IdleEnter => (Kind::IdleEnter, None, 0), - TraceKind::IdleExit => (Kind::IdleExit, None, 0), - TraceKind::Irq => (Kind::Irq, None, 0), TraceKind::TimerFire => (Kind::TimerFire, None, 0), }; - // `TaskKey` packs `TaskId` with pid in the high half, matching `TaskId::pack`. - let (pid, tid) = match task { - Some(key) => ((key.0 >> 32) as u32, key.0 as u32), - None => ( - percpu::current_pid().map_or(u32::MAX, |p| p.raw()), - percpu::current_tid().map_or(u32::MAX, |t| t.raw()), - ), - }; - push(ev.cpu.0, ev.ts.0, kind, pid, tid, data); + // A task's name is its `TaskId::pack`, pid in the high half. + push(kind, task.map(|name| ((name >> 32) as u32, name as u32)), data); } /// Record consumption of an `irq_ring` record (see [`Kind::IrqDrain`]). @@ -216,3 +116,35 @@ pub fn trace_irq_drain(source: crate::irq_ring::IrqSource, latency_us: u64) { let data = ((source as u32) << 24) | (latency_us.min(0x00FF_FFFF) as u32); trace(Kind::IrqDrain, data); } + +/// Every CPU's ring a reader can name: one per CPU online now. +fn rings() -> Rings { + let online = crate::smp::cpu_count() as usize; + core::array::from_fn(|cpu| RINGS.get(cpu).filter(|_| cpu < online)) +} + +/// Copies records `cursor` has not seen into `out`, oldest first; never blocks. +pub fn read(cursor: &mut TraceCursor, out: &mut UserBytesMut, capacity: usize) -> Result { + crate::log::user::read_rings(&rings(), &mut cursor.0, out, capacity, TraceRecord::as_bytes) +} + +/// [`Kind::Mark`] records `count` of them on this CPU, `data` counting up, and +/// the counter ticks spent writing them with interrupts closed. +#[cfg(feature = "test-actuators")] +pub fn flood(count: u64) -> u64 { + /// Records written under one closing of interrupts. + const BATCH: u64 = 4096; + let mut ticks = 0; + let mut written = 0; + while written < count { + let batch = BATCH.min(count - written); + let _closed = IrqGuard::close(); + let from = cpu::counter(); + for i in written..written + batch { + trace(Kind::Mark, i as u32); + } + ticks += cpu::counter() - from; + written += batch; + } + ticks +} diff --git a/kernel/src/user_ptr.rs b/kernel/src/user_ptr.rs index 1169d9e1545..ed78f14b25b 100644 --- a/kernel/src/user_ptr.rs +++ b/kernel/src/user_ptr.rs @@ -64,6 +64,8 @@ unsafe impl UserSafe for toyos_abi::input::MouseEvent {} // SAFETY: `#[repr(C)] Copy`, 88 bytes with no padding (checked by a compile-time size assertion); every field is clamped where it is used, not here. unsafe impl UserSafe for toyos_abi::log::LogCursor {} +// SAFETY: `#[repr(transparent)]` over the `LogCursor` above. +unsafe impl UserSafe for toyos_abi::trace::TraceCursor {} pub(crate) use toyos_userbound::Access; diff --git a/src/sourcegate.rs b/src/sourcegate.rs index 568f537e36d..13cdedf6ca0 100644 --- a/src/sourcegate.rs +++ b/src/sourcegate.rs @@ -148,7 +148,6 @@ const AUTO_TRAIT_IMPLS: &[(&str, usize)] = &[ ("kernel/src/process.rs", 1), ("kernel/src/sched/driver.rs", 2), ("kernel/src/symbols.rs", 2), - ("kernel/src/trace.rs", 1), ]; /// Directories whose Rust is compiled for the guest, by repository-relative diff --git a/system.toml b/system.toml index ee8411d2bf3..f01913ed8e7 100644 --- a/system.toml +++ b/system.toml @@ -106,6 +106,12 @@ receives = ["netstack"] receives = ["netstack", "soundserver", "log", "compositor"] syscap = ["inventory", "counters", "trace"] +# The kernel's diary: when every thread in the machine was woken, ran and +# parked, which times every other program, so `trace` is all it holds and it +# is an admin tool. +[programs.trace] +syscap = ["trace"] + [programs.filepicker] service = true serves = ["filepicker"] diff --git a/tests/toyos-rust-tests/Cargo.lock b/tests/toyos-rust-tests/Cargo.lock index da948ecead9..538a0d85107 100644 --- a/tests/toyos-rust-tests/Cargo.lock +++ b/tests/toyos-rust-tests/Cargo.lock @@ -708,6 +708,7 @@ dependencies = [ "toyos-abi", "toyos-inspect", "toyos-tco", + "toyos-trace", "toyos-window", ] @@ -715,6 +716,13 @@ dependencies = [ name = "toyos-tco" version = "0.1.0" +[[package]] +name = "toyos-trace" +version = "0.1.0" +dependencies = [ + "toyos-abi", +] + [[package]] name = "toyos-window" version = "0.20.0" diff --git a/tests/toyos-rust-tests/Cargo.toml b/tests/toyos-rust-tests/Cargo.toml index b16d1b7fc47..5ef62700dab 100644 --- a/tests/toyos-rust-tests/Cargo.toml +++ b/tests/toyos-rust-tests/Cargo.toml @@ -11,6 +11,8 @@ toyos = { path = "../../toyos" } toyos-window = { path = "../../userland/toyos-window" } toyos-tco = { path = "../../toyos-tco" } toyos-inspect = { path = "../../toyos-inspect" } +# The diary's decoder, for `trace_read` and `trace_flood`. +toyos-trace = { path = "../../toyos-trace" } # The reader's asker, for `hda_client_stall`. inspect = { path = "../../userland/inspect" } libloading = { git = "https://github.com/ToyOSOrg/rust_libloading", branch = "toyos-sdk-0.12" } diff --git a/tests/toyos-rust-tests/src/bin/trace_flood.rs b/tests/toyos-rust-tests/src/bin/trace_flood.rs new file mode 100644 index 00000000000..7ceaa4f27e9 --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/trace_flood.rs @@ -0,0 +1,77 @@ +//! A flood longer than a ring: the records it overwrote before the reader got +//! there are counted, and the ones the reader gets are the newest, whole and in +//! order. On the T14 its line is what one record costs. +//! +//! **A guest on the test kernel**, because nothing else writes a known +//! sequence of records into one CPU's ring faster than a reader drains it: +//! `SYS_DEBUG`'s `TRACE_FLOOD` writes them through the shipped writer, and the +//! read, its loss count and its cursor are the shipped paths. The ticks it +//! answers are printed and judged on the T14 alone (`trace_record_cost`). + +use toyos::endow::{Endowments, SYSCAP_LABEL}; +use toyos::syscap::SysCap; +use toyos_abi::syscall::{self, debug_action, SyscallError}; +use toyos_abi::trace::{TraceCursor, TraceRecord}; +use toyos_trace::{Entry, Event}; + +/// A million: the count the track's exit measures a record's cost over. +const COUNT: u64 = 1_000_000; + +/// Records asked for at once. +const BATCH: usize = 512; + +fn main() { + let cap: SysCap = Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability"); + assert_eq!( + syscall::debug_with(debug_action::TRACE_FLOOD, debug_action::TRACE_FLOOD_MOST + 1), + SyscallError::InvalidArgument.to_u64(), + "a flood past the most one call writes was written", + ); + let mut cursor = TraceCursor::new(); + read_to_now(&cap, &mut cursor); + + let ticks = syscall::debug_with(debug_action::TRACE_FLOOD, COUNT); + assert!(SyscallError::from_u64(ticks).is_none(), "the flood was refused: {ticks:#x}"); + let (entries, lost) = read_to_now(&cap, &mut cursor); + + let marks: Vec<(u16, u32)> = entries + .iter() + .filter_map(|e| match e.event { + Event::Mark { index } => Some((e.cpu, index)), + _ => None, + }) + .collect(); + let (&(cpu, oldest), &(_, newest)) = + marks.first().zip(marks.last()).unwrap_or_else(|| panic!("no record of the flood was read back")); + assert!(marks.iter().all(|&(c, _)| c == cpu), "the flood's records came from more than its own cpu{cpu}"); + assert!( + marks.windows(2).all(|w| w[1].1 == w[0].1 + 1), + "the flood's records read back out of order or with a gap, from {oldest} to {newest}", + ); + assert_eq!(u64::from(newest), COUNT - 1, "the flood's newest record was not read back"); + assert!(oldest > 0, "a flood of {COUNT} read back whole: no ring is that long"); + assert!(lost >= u64::from(oldest), "{oldest} of the flood's records were overwritten and {lost} counted lost"); + + println!( + "trace_flood: {COUNT} records in {ticks} counter ticks with interrupts closed, {:.2} a record; \ + the newest {} read back whole, {lost} counted lost", + ticks as f64 / COUNT as f64, + marks.len(), + ); +} + +/// Every record from `cursor` on, decoded, until a read leaves its buffer +/// short, and the records lost on the way. +fn read_to_now(cap: &SysCap, cursor: &mut TraceCursor) -> (Vec, u64) { + let mut out = Vec::new(); + let mut lost = 0; + let mut raw = vec![TraceRecord::EMPTY; BATCH]; + loop { + let n = cap.trace(cursor, &mut raw).expect("the estate's capability reads the diary"); + lost += cursor.lost(); + out.extend(raw[..n].iter().map(|r| Entry::decode(r).unwrap_or_else(|why| panic!("{r:?}: {why}")))); + if n < raw.len() { + return (out, lost); + } + } +} diff --git a/tests/toyos-rust-tests/src/bin/trace_read.rs b/tests/toyos-rust-tests/src/bin/trace_read.rs new file mode 100644 index 00000000000..a538b6051da --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/trace_read.rs @@ -0,0 +1,192 @@ +//! `SYS_TRACE_READ`: the diary is the scheduler's own account of what it did, +//! read on a cursor the reader owns, and reading it is a right's. +//! +//! **A guest, because the subject is the scheduler's own records and the +//! syscall boundary**: which events the core emits, from which CPU, in what +//! order, and what the boundary refuses. No type or host test reaches either. +//! Nothing here is timed: a stamp is compared only with another. +//! +//! - A spawned child parked on a pipe until its parent writes: each pick of it +//! that follows its park follows a wake of it, in the order read and on the +//! clock. +//! - Two cursors at one position: one read to the end leaves the other where it +//! was, and the other then reads every record the first did, unchanged. +//! - Every record decodes, and each CPU's come numbered without a gap and +//! never earlier than the one before. +//! - The refusals: a capability without `TRACE` is refused and its buffer and +//! cursor left as they were; a buffer of no records or short of a CPU, and a +//! cursor ahead of a ring, are refused; a handle nobody holds ends the caller. + +use std::collections::BTreeMap; +use std::io::{Read, Write}; +use std::process::{Command, Stdio}; +use std::sync::OnceLock; + +use toyos::endow::{Endowments, SYSCAP_LABEL}; +use toyos::syscap::SysCap; +use toyos_abi::handle::{Rights, HANDLE_INVALID}; +use toyos_abi::syscall::{self, SyscallError}; +use toyos_abi::trace::{TraceCursor, TraceRecord}; +use toyos_trace::{Entry, Event, Thread}; + +const SELF_PATH: &str = "/system/bin/test_rs_trace_read"; + +/// `process::HANDLE_FAULT_EXIT_CODE`. +const HANDLE_FAULT: i32 = 139; + +/// Records asked for at once. +const BATCH: usize = 512; + +fn main() { + match std::env::args().nth(1).as_deref() { + Some("waiter") => { + let mut byte = [0u8]; + let read = std::io::stdin().read(&mut byte).expect("read the byte that wakes this child"); + return assert_eq!(read, 1, "the parent closed the pipe instead of writing"); + } + Some("unheld") => { + println!("reached unheld"); + std::io::stdout().flush().expect("flush the marker"); + let refused = syscall::trace_read(HANDLE_INVALID, &mut TraceCursor::new(), &mut [TraceRecord::EMPTY; 8]); + panic!("a handle nobody holds was answered {refused:?} instead of ending the caller"); + } + _ => {} + } + let mut first = TraceCursor::new(); + read_to_now(&mut first); + let mut second = first; + + let mut child = Command::new(SELF_PATH).arg("waiter").stdin(Stdio::piped()).spawn().expect("spawn the waiter"); + let task = Thread { pid: child.id(), tid: 0 }; + assert_ne!(task.pid, 0, "the waiter ended before its pid was asked"); + // The wake under test is the write's, so it is made only once the diary + // says the child parked on the pipe. + let mut read_first = Vec::new(); + let mut lost_first = 0; + while !read_first.iter().any(|r| is(r, task, Event::Park)) { + let (more, lost) = read_to_now(&mut first); + read_first.extend(more); + lost_first += lost; + std::thread::yield_now(); + } + child.stdin.take().expect("the waiter's stdin").write_all(&[1]).expect("wake the waiter"); + assert!(child.wait().expect("wait the waiter").success(), "the waiter failed"); + + let (more, lost) = read_to_now(&mut first); + read_first.extend(more); + lost_first += lost; + let (read_second, lost_second) = read_to_now(&mut second); + assert_eq!((lost_first, lost_second), (0, 0), "a quiet machine lapped a ring inside one spawn"); + let second_by_place: BTreeMap<(u16, u64), &TraceRecord> = + read_second.iter().map(|r| ((r.cpu, r.seq), r)).collect(); + for r in &read_first { + assert_eq!(second_by_place.get(&(r.cpu, r.seq)), Some(&r), "the second cursor did not read {r:?} as the first did"); + } + + let entries: Vec = + read_second.iter().map(|r| Entry::decode(r).unwrap_or_else(|why| panic!("{r:?}: {why}"))).collect(); + each_cpu_in_order(&entries); + woken_before_picked(&entries, task); + + rights(&first); + unheld(); + println!("trace_read: a wake precedes its pick, a cursor is its reader's own, and the diary is TRACE's"); +} + +/// Whether `record` is `event` happening to `task`. +fn is(record: &TraceRecord, task: Thread, event: Event) -> bool { + Entry::decode(record).is_ok_and(|e| e.event == event && e.thread == Some(task)) +} + +/// The estate's capability, taken once: taking an endowment is a swap. +fn cap() -> &'static SysCap { + static CAP: OnceLock = OnceLock::new(); + CAP.get_or_init(|| Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability")) +} + +/// Every record from `cursor` on, until a read leaves its buffer short, and +/// the records lost on the way. +fn read_to_now(cursor: &mut TraceCursor) -> (Vec, u64) { + let mut out = Vec::new(); + let mut lost = 0; + let mut raw = vec![TraceRecord::EMPTY; BATCH]; + loop { + let n = cap().trace(cursor, &mut raw).expect("the estate's capability reads the diary"); + lost += cursor.lost(); + out.extend_from_slice(&raw[..n]); + if n < raw.len() { + return (out, lost); + } + } +} + +/// Each CPU's records come in its ring's order, without a gap, and never +/// stamped before the one ahead of them. +fn each_cpu_in_order(entries: &[Entry]) { + let mut last: BTreeMap = BTreeMap::new(); + for e in entries { + if let Some(before) = last.insert(e.cpu, e) { + assert_eq!(e.seq, before.seq + 1, "cpu{}'s ring skipped from {before:?} to {e:?}", e.cpu); + assert!(e.stamp >= before.stamp, "cpu{} stamped {e:?} before {before:?}", e.cpu); + } + } +} + +/// Every pick of `task` after it parked comes after a wake of it, in the +/// order read and on the clock; and it was woken and picked at least once. +fn woken_before_picked(entries: &[Entry], task: Thread) { + let mut parked = false; + let mut woken: Option<&Entry> = None; + let mut picked_after_a_wake = 0; + for e in entries.iter().filter(|e| e.event.names_its_task() && e.thread == Some(task)) { + match e.event { + Event::Park => parked = true, + Event::Wake => { + parked = false; + woken = Some(e); + } + Event::Pick => { + assert!(!parked, "{task:?} was picked at {e:?} while parked, with no wake between"); + if let Some(wake) = woken.take() { + assert!(e.stamp >= wake.stamp, "{task:?} was picked at {e:?}, stamped before its wake {wake:?}"); + picked_after_a_wake += 1; + } + } + _ => {} + } + } + assert!(picked_after_a_wake > 0, "{task:?} slept and was never read woken and then picked"); +} + +fn rights(at: &TraceCursor) { + let none = cap().narrowed(Rights::TRANSFER).expect("a cap carrying less"); + let mut cursor = *at; + let mut buf = vec![TraceRecord::EMPTY; BATCH]; + assert_eq!(none.trace(&mut cursor, &mut buf), Err(SyscallError::PermissionDenied), "a cap without TRACE read the diary"); + // The demand is above every write, so a refusal leaves both as they were. + assert!(buf.iter().all(|r| *r == TraceRecord::EMPTY), "a refused read wrote into the caller's buffer"); + assert_eq!(cursor, *at, "a refused read moved the caller's cursor"); + + assert_eq!(cap().trace(&mut cursor, &mut []), Err(SyscallError::InvalidArgument), "a buffer of no records"); + let cpus = syscall::cpu_count() as usize; + if cpus > 1 { + let mut short = vec![TraceRecord::EMPTY; cpus - 1]; + assert_eq!(cap().trace(&mut cursor, &mut short), Err(SyscallError::InvalidArgument), "a buffer short of a cpu"); + } + let mut ahead = *at; + ahead.0.next[0] = u64::MAX; + assert_eq!(cap().trace(&mut ahead, &mut buf), Err(SyscallError::InvalidArgument), "a cursor ahead of cpu0's ring"); +} + +/// In a child of its own, since the kernel's answer is to end the caller. +fn unheld() { + let out = Command::new(SELF_PATH) + .arg("unheld") + .stdout(Stdio::piped()) + .spawn() + .expect("spawn the unheld child") + .wait_with_output() + .expect("wait the unheld child"); + assert_eq!(String::from_utf8_lossy(&out.stdout).trim(), "reached unheld", "the child never reached its call"); + assert_eq!(out.status.code(), Some(HANDLE_FAULT), "SYS_TRACE_READ took a handle nobody holds"); +} diff --git a/tests/toyos.rs b/tests/toyos.rs index 7fac3b67117..48820b9ffd0 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -101,6 +101,9 @@ const RUST_SKIP: &[&str] = &[ // every CPU, which the `counters` metal row judges; on a guest it would be // seconds of four CPUs spinning, read by nothing. "counters_metal", + // Its product is what a diary record costs, which the `trace_record_cost` + // metal row reads off the test kernel its flood needs. + "trace_flood", // It takes the machine down; `virt_fatal_halts_the_others_first` runs it. "panic_halts_first", // Needs a launcher and a declared `cat` and shell, which `tests/testcases` @@ -152,6 +155,7 @@ const DRIVEN_AND_SHARED: &[&str] = &[ // Its shared run is the x86-64 verdict; `virt_smp` builds it for AArch64 // and runs it on that architecture's SMP case. "counters_read", + "trace_read", // Its shared run is the x86-64 verdict; `virt_readonly_copyout` builds it // for AArch64 and runs it on that architecture's job case. "abuse_readonly_copyout", @@ -425,6 +429,24 @@ const METAL: &[(&str, metal::Metal)] = &[ judge: |b| b[0].job_passed("test_rs_tlb_shootdown_waits"), }, ), + ( + // What one diary record costs its writer: a million written back to + // back by `SYS_DEBUG`'s flood, so the kernel that carries it, timed + // with interrupts closed. Read, not held: the number is the product. + "trace_record_cost", + metal::Metal { + arms: &[metal::Arm { + features: toyos_build::build::TEST_KERNEL, + ..metal::once("testcases-debug", "tests/testcases", &[], &["test_rs_trace_flood"]) + }], + judge: |b| { + b[0].job_passed("test_rs_trace_flood")?; + let log = b[0].log(); + eprintln!(" [trace] {}", log.must_say("trace_flood: ")?); + Ok(()) + }, + }, + ), ( // One CPU deafened by the actuator, named by the blocked-task dump and // found by its NMI where it spins. @@ -1468,6 +1490,10 @@ const VIRT_COPYOUT: &str = "abuse_readonly_copyout"; /// `test_rs_counters_read`. const VIRT_COUNTERS_READ: &str = "counters_read"; +/// `tests/toyos-rust-tests`' binary that `tests/virtsmpcase` runs as its job +/// `test_rs_trace_read`. +const VIRT_TRACE_READ: &str = "trace_read"; + /// `tests/toyos-rust-tests`' binary `name` built for `arch`, once a run, as a /// file a case's job list names on ROOT. fn suite_bin(arch: toyos_build::arch::Arch, name: &'static str) -> (String, Vec) { @@ -1583,7 +1609,10 @@ fn boot_virt_smp(options: BootOptions) -> QemuInstance { &[], BootOptions { ready_marker: "control registers: SCTLR_EL1=", - extra_root_files: vec![suite_bin(options.profile.arch(), VIRT_COUNTERS_READ)], + extra_root_files: vec![ + suite_bin(options.profile.arch(), VIRT_COUNTERS_READ), + suite_bin(options.profile.arch(), VIRT_TRACE_READ), + ], ..options }, ) @@ -1592,11 +1621,14 @@ fn boot_virt_smp(options: BootOptions) -> QemuInstance { /// What `counters_read` says once every CPU answered for itself. const COUNTERS_READ_SAID: &str = "counters_read: every cpu answered for itself, and each counter is a right's"; +/// What `trace_read` says once the diary read back as the scheduler wrote it. +const TRACE_READ_SAID: &str = "trace_read: a wake precedes its pick, a cursor is its reader's own, and the diary is TRACE's"; + /// Boot `tests/virtsmpcase` on [`VIRT_CPUS`] CPUs under `profile`, whose /// firmware enters every CPU at EL`el` and whose FADT names PSCI's `conduit`: /// each CPU is started by `CPU_ON`, holds the control-register declaration as -/// entered there and joins the scheduler, and the case's jobs `unmap_touch` -/// and `test_rs_counters_read` end with exit 0. Then its job `shutdown` stops the machine and powers it +/// entered there and joins the scheduler, and the case's jobs `unmap_touch`, +/// `test_rs_counters_read` and `test_rs_trace_read` end with exit 0. Then its job `shutdown` stops the machine and powers it /// off, every other CPU turned off first ([`psci_powered_off`]). fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String> { let trace = common::lane::dir().join(format!("virt_smp-{conduit}.psci")); @@ -1632,7 +1664,8 @@ fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String } } eprintln!(" [virt] {VIRT_CPUS} CPUs entered at EL{el}, started through {conduit}, and scheduling"); - let counted = judge_virt_job(&mut qemu, "test_rs_counters_read", COUNTERS_READ_SAID)?; + judge_virt_job(&mut qemu, "test_rs_counters_read", COUNTERS_READ_SAID)?; + let counted = judge_virt_job(&mut qemu, "test_rs_trace_read", TRACE_READ_SAID)?; let (console, calls) = ended_through_psci(&mut qemu, &mut stop, counted, power::SHUTTING_DOWN, "guest-shutdown", &trace, |_| Vec::new())?; let record = console diff --git a/tests/virtsmpcase/system.toml b/tests/virtsmpcase/system.toml index 9e2db041d43..b71ae7ee639 100644 --- a/tests/virtsmpcase/system.toml +++ b/tests/virtsmpcase/system.toml @@ -1,8 +1,8 @@ -# Every CPU the machine names, and the two jobs whose premise is more than one -# CPU: a page unmapped beside a thread that is still reading it, and a counters -# read every CPU answers for itself, the suite's `test_rs_counters_read`, which -# the harness puts on ROOT. Then the machine powers off, every CPU but one -# turned off first. +# Every CPU the machine names, and the jobs whose premise is more than one +# CPU: a page unmapped beside a thread that is still reading it; a counters read +# every CPU answers for itself, the suite's `test_rs_counters_read`; and a diary +# every CPU writes, the suite's `test_rs_trace_read`. The harness puts both on +# ROOT. Then the machine powers off, every CPU but one turned off first. [boot] start = ["logkeeper", "test-runner"] @@ -14,8 +14,9 @@ syscap = ["logread"] receives = ["power"] # Four minutes from boot: every job here runs on emulated CPUs, and a job past # the bound reboots the guest with the job named. -args = ["--bound-ms=240000", "unmap_touch", "test_rs_counters_read", "shutdown"] -# What `test_rs_counters_read` reads, and narrows away to prove its refusals. +args = ["--bound-ms=240000", "unmap_touch", "test_rs_counters_read", "test_rs_trace_read", "shutdown"] +# What `test_rs_counters_read` and `test_rs_trace_read` read, and narrow away +# to prove their refusals. syscap = ["dup", "counters", "trace"] [programs.kernelprobe] diff --git a/toyos-abi/src/clock.rs b/toyos-abi/src/clock.rs index 26b16138dcf..0f17e33fce6 100644 --- a/toyos-abi/src/clock.rs +++ b/toyos-abi/src/clock.rs @@ -44,16 +44,25 @@ pub const fn nanos_between(counter_at_boot: u64, period_fs: u64, now: u64) -> u6 /// Nanoseconds since boot, off this process's clock page. /// /// # Panics +/// As [`page`]. +pub fn nanos_since_boot() -> u64 { + let page = page(); + let now = crate::arch::counter(); + nanos_between(page.counter_at_boot, page.period_fs, now) +} + +/// This process's clock page. +/// +/// # Panics /// On a page that does not carry [`CLOCK_MAGIC`]: every address space the /// kernel builds maps one, so its absence is a kernel that broke the ABI. -pub fn nanos_since_boot() -> u64 { +pub fn page() -> ClockPage { // SAFETY: the kernel maps the page read-only at `CLOCK_PAGE` in every // address space before the first instruction runs, and never writes it // again, so a volatile copy of the whole value is a read of constants. let page = unsafe { core::ptr::read_volatile(CLOCK_PAGE as *const ClockPage) }; assert!(page.magic == CLOCK_MAGIC, "the clock page at {CLOCK_PAGE:#x} carries no clock"); - let now = crate::arch::counter(); - nanos_between(page.counter_at_boot, page.period_fs, now) + page } #[cfg(test)] diff --git a/toyos-abi/src/handle.rs b/toyos-abi/src/handle.rs index 5c503c112a7..0e9f85814f4 100644 --- a/toyos-abi/src/handle.rs +++ b/toyos-abi/src/handle.rs @@ -152,11 +152,14 @@ impl Rights { /// Beside [`COUNTERS`](Self::COUNTERS), [`SYS_COUNTERS`] answers each /// CPU's `APERF` and `MPERF` — its frequency and busy fraction, the /// Hertzbleed power channel — and the kicks it took, the wake-ups that time - /// keystrokes. Admin tools hold it, `inspect` and `test-runner`; no + /// keystrokes. [`SYS_TRACE_READ`] answers, on this alone, when every + /// thread in the machine was woken, ran and parked, and on which CPU. + /// Admin tools hold it, `inspect`, `trace` and `test-runner`; no /// ordinary program and no toybox applet does while a manifest row grants /// a whole binary. /// /// [`SYS_COUNTERS`]: crate::syscall::SYS_COUNTERS + /// [`SYS_TRACE_READ`]: crate::syscall::SYS_TRACE_READ pub const TRACE: Rights = Rights(1 << 14); /// Every bit that has a caller. A wider set than this is a bug in whoever diff --git a/toyos-abi/src/lib.rs b/toyos-abi/src/lib.rs index 15c26e12ad4..616ad86213d 100644 --- a/toyos-abi/src/lib.rs +++ b/toyos-abi/src/lib.rs @@ -29,6 +29,7 @@ pub mod part; pub mod pci; pub mod ring; pub mod syscall; +pub mod trace; pub mod virtio_sound; pub use handle::{RawHandle, Rights, HANDLE_INVALID}; diff --git a/toyos-abi/src/syscall.rs b/toyos-abi/src/syscall.rs index d63e214f3c3..293e596adf9 100644 --- a/toyos-abi/src/syscall.rs +++ b/toyos-abi/src/syscall.rs @@ -267,6 +267,13 @@ pub const SYS_DEVICE_DMA_UNMAP: u64 = 123; /// [`Rights::TRACE`]: crate::handle::Rights::TRACE pub const SYS_COUNTERS: u64 = 124; +/// The diary's records the caller's cursor has not seen, as +/// [`crate::trace`] records. Gated by [`Rights::TRACE`] on a `SysCap`. See +/// [`trace_read`]. +/// +/// [`Rights::TRACE`]: crate::handle::Rights::TRACE +pub const SYS_TRACE_READ: u64 = 125; + /// Bins in the per-process syscall profile — one for every number this ABI /// issues, and one at the end for every number it does not. /// @@ -279,7 +286,7 @@ pub const SYSCALL_PROFILE_BINS: usize = 128; /// a reader can see in the line; dropping is one nobody can. pub const SYSCALL_PROFILE_OTHER: usize = SYSCALL_PROFILE_BINS - 1; -const _: () = assert!(SYS_COUNTERS < SYSCALL_PROFILE_OTHER as u64); +const _: () = assert!(SYS_TRACE_READ < SYSCALL_PROFILE_OTHER as u64); pub const WNOHANG: u64 = 1; @@ -822,6 +829,14 @@ pub mod debug_action { pub const COUNTERS_DEAF: u64 = 24; /// Every CPU answers rounds again. pub const COUNTERS_HEAR: u64 = 25; + /// Write the argument's count of [`Kind::Mark`](crate::trace::Kind::Mark) + /// records into the calling CPU's diary ring back to back, the `i`th with + /// `data` `i`, and answer the counter ticks the writes took with + /// interrupts closed. A count past [`TRACE_FLOOD_MOST`] answers + /// `InvalidArgument`. + pub const TRACE_FLOOD: u64 = 14; + /// The most records one [`TRACE_FLOOD`] writes. + pub const TRACE_FLOOD_MOST: u64 = 1 << 24; } /// Every kind of kernel object, in the order the kernel's own `kobject!` @@ -1992,6 +2007,30 @@ pub fn counters( .map(|n| n as usize) } +/// Copy the diary's records `cursor` has not seen into `out`, oldest first and +/// merged across CPUs by stamp, advancing `cursor`. Answers how many were +/// written, and `0` when there is nothing new; it never blocks. +/// +/// `out` is whole [`crate::trace::TraceRecord`]s. A buffer that cannot hold one +/// record per CPU, and a `cursor` ahead of a CPU's ring, are +/// [`SyscallError::InvalidArgument`]. `syscap` must carry +/// [`crate::handle::Rights::TRACE`]: a capability without it is refused with +/// a word, and a handle the caller does not hold ends it. +pub fn trace_read( + syscap: RawHandle, + cursor: &mut crate::trace::TraceCursor, + out: &mut [crate::trace::TraceRecord], +) -> Result { + check(syscall( + SYS_TRACE_READ, + syscap.0 as u64, + cursor as *mut crate::trace::TraceCursor as u64, + out.as_mut_ptr() as u64, + out.len() as u64, + )) + .map(|n| n as usize) +} + /// Sleep for the given number of nanoseconds. pub fn nanosleep(nanos: u64) { syscall(SYS_NANOSLEEP, nanos, 0, 0, 0); diff --git a/toyos-abi/src/trace.rs b/toyos-abi/src/trace.rs new file mode 100644 index 00000000000..8eec6cef113 --- /dev/null +++ b/toyos-abi/src/trace.rs @@ -0,0 +1,170 @@ +//! What [`SYS_TRACE_READ`] answers: the kernel's diary of scheduling and timer +//! events, one [`TraceRecord`] each, from a ring per CPU the kernel writes +//! always. +//! +//! A record's [`TraceRecord::stamp`] is the CPU's free-running counter (TSC, +//! `CNTVCT_EL0`) in its own ticks, which [`crate::clock::ClockPage`] turns into +//! nanoseconds since boot. A read takes a [`TraceCursor`], the log's cursor +//! over these rings, and answers records oldest first, merged across CPUs by +//! stamp, with the records overwritten before the cursor reached them counted +//! in its `lost`. What each [`Kind`] means of `pid`, `tid` and `data` is on +//! the kind; the typed reading of one is `toyos-trace`'s. +//! +//! [`SYS_TRACE_READ`]: crate::syscall::SYS_TRACE_READ + +use crate::log::LogCursor; + +/// One record on the wire. A reader indexes by this stride. +pub const RECORD_BYTES: usize = 32; + +/// What `pid` and `tid` read when the CPU was running no thread. +pub const NO_THREAD: u32 = u32::MAX; + +/// One diary record, as a read copies it out. +#[repr(C)] +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct TraceRecord { + /// Its sequence number in its CPU's ring, which [`LogCursor::next`] counts in. + pub seq: u64, + /// The CPU's counter when the record was written. + pub stamp: u64, + /// A [`Kind`], undecoded: input until [`Kind::from_u16`] says otherwise. + pub kind: u16, + /// The CPU whose ring holds it, which is the CPU that wrote it. + pub cpu: u16, + pub data: u32, + pub pid: u32, + pub tid: u32, +} + +const _: () = assert!(core::mem::size_of::() == RECORD_BYTES); +/// Every byte belongs to a field: the record crosses the boundary through +/// [`TraceRecord::as_bytes`], so a gap would publish whatever the kernel stack +/// held. +const _: () = assert!(core::mem::size_of::() == 8 + 8 + 2 + 2 + 4 + 4 + 4); + +impl TraceRecord { + /// A record no ring wrote, for sizing a read buffer: sequence numbers + /// start at one, so this is no record. + pub const EMPTY: Self = Self { seq: 0, stamp: 0, kind: 0, cpu: 0, data: 0, pid: 0, tid: 0 }; + + /// The record's own bytes, which is what goes on the wire. + #[inline] + pub fn as_bytes(&self) -> &[u8] { + // SAFETY: `self` is a valid `&Self`, and the const assert above proves + // the `repr(C)` layout has no padding, so every byte is an initialized + // field. + unsafe { + core::slice::from_raw_parts(self as *const Self as *const u8, core::mem::size_of::()) + } + } +} + +/// What a record says happened. `pid`/`tid` name the thread running on the +/// CPU when it was written, [`NO_THREAD`] when none was, unless the kind +/// names its own task; `data` is 0 unless the kind says otherwise. +#[repr(u16)] +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum Kind { + /// The task `pid`/`tid` name was picked to run. + Pick = 1, + /// The task `pid`/`tid` name was made runnable on this CPU. + Wake = 2, + /// The task `pid`/`tid` name parked. + ParkCommit = 3, + /// A pass ran on the way out of an interrupt. + Preempt = 4, + /// The task `pid`/`tid` name left for the CPU `data` names. + Migrate = 5, + /// The task `pid`/`tid` name arrived from another CPU. + Adopt = 6, + /// The task `pid`/`tid` name was retired. + Retire = 7, + /// The CPU is about to halt. + IdleEnter = 8, + /// The one-shot timer was armed `data` nanoseconds out, the low 32 bits of the span. + TimerArm = 9, + TimerStop = 10, + TimerFire = 11, + /// `data` timer expiries taken in Ring 0 since the last return to Ring 3. + TimerFireBurst = 12, + /// An interrupt's record was consumed: `data`'s top byte is its source, + /// its low 24 bits the microseconds since the interrupt, saturating. + IrqDrain = 13, + /// Written only by a test kernel's flood; `data` is its index. + Mark = 14, +} + +impl Kind { + /// The kind a record's word names, or `None` for one this ABI does not. + pub const fn from_u16(word: u16) -> Option { + Some(match word { + 1 => Self::Pick, + 2 => Self::Wake, + 3 => Self::ParkCommit, + 4 => Self::Preempt, + 5 => Self::Migrate, + 6 => Self::Adopt, + 7 => Self::Retire, + 8 => Self::IdleEnter, + 9 => Self::TimerArm, + 10 => Self::TimerStop, + 11 => Self::TimerFire, + 12 => Self::TimerFireBurst, + 13 => Self::IrqDrain, + 14 => Self::Mark, + _ => return None, + }) + } +} + +/// A reader's position in the diary: the log's cursor, a type of its own so +/// that one is never walked over the other's rings. +#[repr(transparent)] +#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)] +pub struct TraceCursor(pub LogCursor); + +impl TraceCursor { + /// A cursor that has read nothing. + pub const fn new() -> Self { + Self(LogCursor::new()) + } + + /// Records the last read skipped because they were overwritten. + pub const fn lost(&self) -> u64 { + self.0.lost + } +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Every number a kind is read back as that kind, and no other number is one. + #[test] + fn every_kind_reads_back_and_nothing_else_does() { + let mut kinds = 0; + for word in 0..=u16::MAX { + if let Some(kind) = Kind::from_u16(word) { + assert_eq!(kind as u16, word); + kinds += 1; + } + } + assert_eq!(kinds, Kind::Mark as u16, "the kinds are numbered from one without a gap"); + } + + /// The encoder is the wire, so the test decodes the wire. + #[test] + fn as_bytes_is_the_fields_and_nothing_between_them() { + let r = TraceRecord { seq: 7, stamp: 0x0102_0304_0506_0708, kind: 2, cpu: 3, data: 4, pid: 5, tid: 6 }; + let b = r.as_bytes(); + assert_eq!(b.len(), RECORD_BYTES); + assert_eq!(u64::from_ne_bytes(b[0..8].try_into().unwrap()), 7); + assert_eq!(u64::from_ne_bytes(b[8..16].try_into().unwrap()), 0x0102_0304_0506_0708); + assert_eq!(u16::from_ne_bytes(b[16..18].try_into().unwrap()), 2); + assert_eq!(u16::from_ne_bytes(b[18..20].try_into().unwrap()), 3); + assert_eq!(u32::from_ne_bytes(b[20..24].try_into().unwrap()), 4); + assert_eq!(u32::from_ne_bytes(b[24..28].try_into().unwrap()), 5); + assert_eq!(u32::from_ne_bytes(b[28..32].try_into().unwrap()), 6); + } +} diff --git a/toyos-trace/Cargo.toml b/toyos-trace/Cargo.toml new file mode 100644 index 00000000000..e057a20660b --- /dev/null +++ b/toyos-trace/Cargo.toml @@ -0,0 +1,10 @@ +[package] +name = "toyos-trace" +description = "The diary's decoder: what a kernel trace record says, typed, when, and the line it prints as, pure." +version = "0.1.0" +edition = "2021" +license = "MIT OR Apache-2.0" + +[dependencies] +# The record and its kinds, whose layout the ABI owns. +toyos-abi = { path = "../toyos-abi" } diff --git a/toyos-trace/src/lib.rs b/toyos-trace/src/lib.rs new file mode 100644 index 00000000000..e4807110589 --- /dev/null +++ b/toyos-trace/src/lib.rs @@ -0,0 +1,255 @@ +//! The diary's decoder: what a `toyos_abi::trace::TraceRecord` says, typed, +//! when it said it, and the one line it prints as. +//! +//! A record crossed the syscall boundary or came off a file, so it is input: +//! [`Entry::decode`] refuses a kind the ABI does not name, and a kind that +//! names its own task but carries no thread, each by name. A stamp is the +//! writing CPU's counter, which the machine's `ClockPage` reads as +//! nanoseconds since boot on the kernel's own formula, so a diary and a log +//! line order against each other. +//! +//! Pure: `core` only, no `unsafe`, no I/O. + +#![no_std] +#![forbid(unsafe_code)] + +use core::fmt; + +use toyos_abi::clock::{nanos_between, ClockPage}; +use toyos_abi::trace::{Kind, TraceRecord, NO_THREAD}; + +/// A thread, by its process's id and its own, each as the writing CPU held +/// it: [`NO_THREAD`] where it held none. +#[derive(Clone, Copy, Debug, PartialEq, Eq, PartialOrd, Ord, Hash)] +pub struct Thread { + pub pid: u32, + pub tid: u32, +} + +/// What happened, with what the kind says of `data`. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum Event { + Pick, + Wake, + Park, + Preempt, + Migrate { to: u32 }, + Adopt, + Retire, + IdleEnter, + TimerArm { span_ns: u32 }, + TimerStop, + TimerFire, + TimerFireBurst { fires: u32 }, + IrqDrain { source: u8, latency_us: u32 }, + Mark { index: u32 }, +} + +impl Event { + /// Whether the record's thread is the task the event happened to, rather + /// than whichever thread the CPU was running. + pub const fn names_its_task(&self) -> bool { + matches!(self, Self::Pick | Self::Wake | Self::Park | Self::Migrate { .. } | Self::Adopt | Self::Retire) + } + + const fn name(&self) -> &'static str { + match self { + Self::Pick => "pick", + Self::Wake => "wake", + Self::Park => "park", + Self::Preempt => "preempt", + Self::Migrate { .. } => "migrate", + Self::Adopt => "adopt", + Self::Retire => "retire", + Self::IdleEnter => "idle", + Self::TimerArm { .. } => "timer-arm", + Self::TimerStop => "timer-stop", + Self::TimerFire => "timer-fire", + Self::TimerFireBurst { .. } => "timer-fires", + Self::IrqDrain { .. } => "irq-drain", + Self::Mark { .. } => "mark", + } + } +} + +/// One record, decoded. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Entry { + /// Its number in its CPU's ring. + pub seq: u64, + /// The writing CPU's counter. + pub stamp: u64, + pub cpu: u16, + /// The task, where [`Event::names_its_task`]; otherwise the thread the + /// CPU was running, `None` for none. + pub thread: Option, + pub event: Event, +} + +/// Why a record is not an [`Entry`]. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum Undecodable { + /// A kind word the ABI does not name. + Kind(u16), + /// A kind that names its own task, with no thread. + NoTask(u16), +} + +impl fmt::Display for Undecodable { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + Self::Kind(word) => write!(f, "kind {word} is no kind the ABI names"), + Self::NoTask(word) => write!(f, "kind {word} names its task and carries no thread"), + } + } +} + +impl Entry { + pub fn decode(raw: &TraceRecord) -> Result { + let kind = Kind::from_u16(raw.kind).ok_or(Undecodable::Kind(raw.kind))?; + let event = match kind { + Kind::Pick => Event::Pick, + Kind::Wake => Event::Wake, + Kind::ParkCommit => Event::Park, + Kind::Preempt => Event::Preempt, + Kind::Migrate => Event::Migrate { to: raw.data }, + Kind::Adopt => Event::Adopt, + Kind::Retire => Event::Retire, + Kind::IdleEnter => Event::IdleEnter, + Kind::TimerArm => Event::TimerArm { span_ns: raw.data }, + Kind::TimerStop => Event::TimerStop, + Kind::TimerFire => Event::TimerFire, + Kind::TimerFireBurst => Event::TimerFireBurst { fires: raw.data }, + Kind::IrqDrain => Event::IrqDrain { source: (raw.data >> 24) as u8, latency_us: raw.data & 0x00FF_FFFF }, + Kind::Mark => Event::Mark { index: raw.data }, + }; + let thread = (raw.pid != NO_THREAD || raw.tid != NO_THREAD).then_some(Thread { pid: raw.pid, tid: raw.tid }); + if event.names_its_task() && (raw.pid == NO_THREAD || raw.tid == NO_THREAD) { + return Err(Undecodable::NoTask(raw.kind)); + } + Ok(Self { seq: raw.seq, stamp: raw.stamp, cpu: raw.cpu, thread, event }) + } + + /// The line this entry prints as, its stamp read on `clock`: + /// `[12.000345678 cpu3] wake 7/0`. + pub fn line(&self, clock: ClockPage) -> Line<'_> { + Line { entry: self, clock } + } +} + +/// What [`Entry::line`] renders. +pub struct Line<'a> { + entry: &'a Entry, + clock: ClockPage, +} + +impl fmt::Display for Line<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let e = self.entry; + let nanos = nanos_between(self.clock.counter_at_boot, self.clock.period_fs, e.stamp); + write!(f, "[{}.{:09} cpu{}] {}", nanos / 1_000_000_000, nanos % 1_000_000_000, e.cpu, e.event.name())?; + match e.thread { + Some(t) => write!(f, " {}/{}", Id(t.pid), Id(t.tid))?, + None => f.write_str(" -")?, + } + match e.event { + Event::Migrate { to } => write!(f, " to=cpu{to}"), + Event::TimerArm { span_ns } => write!(f, " in={span_ns}ns"), + Event::TimerFireBurst { fires } => write!(f, " fires={fires}"), + Event::IrqDrain { source, latency_us } => write!(f, " source={source} after={latency_us}us"), + Event::Mark { index } => write!(f, " index={index}"), + Event::Pick + | Event::Wake + | Event::Park + | Event::Preempt + | Event::Adopt + | Event::Retire + | Event::IdleEnter + | Event::TimerStop + | Event::TimerFire => Ok(()), + } + } +} + +/// A pid or tid, `-` where the record has none. +struct Id(u32); + +impl fmt::Display for Id { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self.0 { + NO_THREAD => f.write_str("-"), + id => write!(f, "{id}"), + } + } +} + +#[cfg(test)] +mod tests { + extern crate std; + use std::string::ToString; + + use super::*; + + /// A 1 GHz counter that read 1000 at boot: one tick a nanosecond. + const CLOCK: ClockPage = ClockPage { magic: toyos_abi::clock::CLOCK_MAGIC, counter_at_boot: 1_000, period_fs: 1_000_000 }; + + fn raw(kind: Kind, data: u32, pid: u32, tid: u32) -> TraceRecord { + TraceRecord { seq: 9, stamp: 1_000 + 12_000_345_678, kind: kind as u16, cpu: 3, data, pid, tid } + } + + #[test] + fn a_wake_names_its_task_and_prints_when_on_which_cpu() { + let entry = Entry::decode(&raw(Kind::Wake, 0, 7, 0)).unwrap(); + assert_eq!(entry.thread, Some(Thread { pid: 7, tid: 0 })); + assert_eq!(entry.event, Event::Wake); + assert_eq!(entry.line(CLOCK).to_string(), "[12.000345678 cpu3] wake 7/0"); + } + + /// Thread zero is a thread: the first of every process. + #[test] + fn thread_zero_is_a_thread_and_no_thread_is_said() { + let on_none = Entry::decode(&raw(Kind::IdleEnter, 0, NO_THREAD, NO_THREAD)).unwrap(); + assert_eq!(on_none.thread, None); + assert_eq!(on_none.line(CLOCK).to_string(), "[12.000345678 cpu3] idle -"); + let half = Entry::decode(&raw(Kind::TimerFire, 0, NO_THREAD, 4)).unwrap(); + assert_eq!(half.line(CLOCK).to_string(), "[12.000345678 cpu3] timer-fire -/4"); + } + + #[test] + fn every_kind_decodes_with_what_its_data_says() { + let cases = [ + (Kind::Pick, 0, Event::Pick, ""), + (Kind::ParkCommit, 0, Event::Park, ""), + (Kind::Preempt, 0, Event::Preempt, ""), + (Kind::Migrate, 5, Event::Migrate { to: 5 }, " to=cpu5"), + (Kind::Adopt, 0, Event::Adopt, ""), + (Kind::Retire, 0, Event::Retire, ""), + (Kind::TimerArm, 250_000, Event::TimerArm { span_ns: 250_000 }, " in=250000ns"), + (Kind::TimerStop, 0, Event::TimerStop, ""), + (Kind::TimerFireBurst, 3, Event::TimerFireBurst { fires: 3 }, " fires=3"), + (Kind::IrqDrain, 2 << 24 | 13, Event::IrqDrain { source: 2, latency_us: 13 }, " source=2 after=13us"), + (Kind::Mark, 41, Event::Mark { index: 41 }, " index=41"), + ]; + for (kind, data, event, tail) in cases { + let entry = Entry::decode(&raw(kind, data, 1, 2)).unwrap(); + assert_eq!(entry.event, event, "{kind:?}"); + assert!(entry.line(CLOCK).to_string().ends_with(&std::format!(" 1/2{tail}")), "{kind:?}"); + } + } + + #[test] + fn a_kind_the_abi_does_not_name_is_refused_by_its_number() { + let mut r = raw(Kind::Pick, 0, 1, 2); + r.kind = 0; + assert_eq!(Entry::decode(&r), Err(Undecodable::Kind(0))); + r.kind = 15; + assert_eq!(Entry::decode(&r), Err(Undecodable::Kind(15))); + } + + #[test] + fn a_task_event_with_no_task_is_refused() { + assert_eq!(Entry::decode(&raw(Kind::Pick, 0, 1, NO_THREAD)), Err(Undecodable::NoTask(Kind::Pick as u16))); + assert_eq!(Entry::decode(&raw(Kind::Wake, 0, NO_THREAD, 0)), Err(Undecodable::NoTask(Kind::Wake as u16))); + } + +} diff --git a/toyos/src/syscap.rs b/toyos/src/syscap.rs index 9e20f70f690..fea93149825 100644 --- a/toyos/src/syscap.rs +++ b/toyos/src/syscap.rs @@ -143,6 +143,18 @@ impl SysCap { syscall::counters(self.0.raw(), buf) } + /// The diary's records `cursor` has not seen, into `out`, oldest first; + /// answers how many, and never blocks — see [`syscall::trace_read`]. + /// + /// Needs [`Rights::TRACE`]. + pub fn trace( + &self, + cursor: &mut toyos_abi::trace::TraceCursor, + out: &mut [toyos_abi::trace::TraceRecord], + ) -> Result { + syscall::trace_read(self.0.raw(), cursor, out) + } + /// Every inventory record, read whole or refused whole, never a shorter /// list; `buffer(n)` is `n` records to read into. /// diff --git a/userland/Cargo.lock b/userland/Cargo.lock index 856df3b4c2f..56ba64259e3 100644 --- a/userland/Cargo.lock +++ b/userland/Cargo.lock @@ -4269,6 +4269,13 @@ version = "0.1.0" name = "toyos-tmpdir" version = "0.1.0" +[[package]] +name = "toyos-trace" +version = "0.1.0" +dependencies = [ + "toyos-abi", +] + [[package]] name = "toyos-transport" version = "0.1.0" @@ -4302,6 +4309,15 @@ dependencies = [ "toyos-keymap", ] +[[package]] +name = "trace" +version = "0.1.0" +dependencies = [ + "toyos", + "toyos-abi", + "toyos-trace", +] + [[package]] name = "tracing" version = "0.1.44" diff --git a/userland/Cargo.toml b/userland/Cargo.toml index 260fa329b7f..c1ab73857a6 100644 --- a/userland/Cargo.toml +++ b/userland/Cargo.toml @@ -35,6 +35,7 @@ members = [ "toybox", "toyos-font", "toyos-window", + "trace", "update", ] exclude = [ diff --git a/userland/trace/Cargo.toml b/userland/trace/Cargo.toml new file mode 100644 index 00000000000..37b224115a1 --- /dev/null +++ b/userland/trace/Cargo.toml @@ -0,0 +1,13 @@ +[package] +name = "trace" +version = "0.1.0" +edition = "2024" +license = "MIT OR Apache-2.0" + +[dependencies] +toyos = { path = "../../toyos" } +toyos-abi = { path = "../../toyos-abi" } +toyos-trace = { path = "../../toyos-trace" } + +[package.metadata.toyos.host] +exempt.manages = "ToyOS's kernel diary: what its `trace` SysCap right reads off every CPU's ring" diff --git a/userland/trace/src/main.rs b/userland/trace/src/main.rs new file mode 100644 index 00000000000..b3d5930b7d3 --- /dev/null +++ b/userland/trace/src/main.rs @@ -0,0 +1,72 @@ +//! `/system/bin/trace` — the kernel's diary, as it stood when asked. +//! +//! Every record the CPUs' rings still hold, oldest first and merged across +//! CPUs, one line each as `toyos-trace` prints it, up to the moment the +//! program started; on stderr, how many records were overwritten before the +//! read reached them. The diary is read on this program's `SysCap`, whose +//! `trace` right its manifest row grants. +//! +//! Exit 2 is a refusal, named on stderr: no capability, a capability without +//! `trace`, and a record that does not decode. + +use std::io::Write; + +use toyos::endow::{Endowments, SYSCAP_LABEL}; +use toyos::syscap::SysCap; +use toyos_abi::clock; +use toyos_abi::syscall::SyscallError; +use toyos_abi::trace::{TraceCursor, TraceRecord}; +use toyos_trace::Entry; + +const USAGE: &str = "usage: trace"; + +/// Records asked for at once; above any machine's CPU count, which a read needs room for. +const BATCH: usize = 1024; + +fn main() { + if std::env::args().len() > 1 { + refuse(USAGE); + } + let Some(cap) = Endowments::get().take::(SYSCAP_LABEL) else { + refuse("trace: this program holds no system capability, so the kernel's diary is not its to read"); + }; + let page = clock::page(); + let until = clock::nanos_since_boot(); + + let mut cursor = TraceCursor::new(); + let mut raw = vec![TraceRecord::EMPTY; BATCH]; + let mut lost = 0; + let mut stdout = std::io::stdout().lock(); + 'read: loop { + let n = match cap.trace(&mut cursor, &mut raw) { + Ok(n) => n, + Err(SyscallError::PermissionDenied) => { + refuse("trace: the kernel refused: this program's capability does not carry `trace`") + } + Err(e) => refuse(&format!("trace: the diary would not read: {e:?}")), + }; + lost += cursor.lost(); + for record in &raw[..n] { + let entry = Entry::decode(record).unwrap_or_else(|why| refuse(&format!("trace: {record:?}: {why}"))); + if clock::nanos_between(page.counter_at_boot, page.period_fs, entry.stamp) > until { + break 'read; + } + // A reader whose pipe closed early (`| head`) has nobody left to tell. + if writeln!(stdout, "{}", entry.line(page)).is_err() { + return; + } + } + if n < raw.len() { + break; + } + } + let _ = stdout.flush(); + if lost > 0 { + eprintln!("trace: {lost} records were overwritten before this read reached them"); + } +} + +fn refuse(why: &str) -> ! { + eprintln!("{why}"); + std::process::exit(2); +} From bf2e0af5b74d2e084a7771e52b90c5028283de2b Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 09:49:21 +0200 Subject: [PATCH 2/7] trace_read: wait on the park without yielding A yield is a pass, and a pass writes records into the ring the second cursor stands in; the wait reads the diary and writes nothing of its own. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- tests/toyos-rust-tests/src/bin/trace_read.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/toyos-rust-tests/src/bin/trace_read.rs b/tests/toyos-rust-tests/src/bin/trace_read.rs index a538b6051da..1d1dbe24c68 100644 --- a/tests/toyos-rust-tests/src/bin/trace_read.rs +++ b/tests/toyos-rust-tests/src/bin/trace_read.rs @@ -60,14 +60,14 @@ fn main() { let task = Thread { pid: child.id(), tid: 0 }; assert_ne!(task.pid, 0, "the waiter ended before its pid was asked"); // The wake under test is the write's, so it is made only once the diary - // says the child parked on the pipe. + // says the child parked on the pipe; a read writes no record, so this + // wait cannot lap the ring `second` stands in. let mut read_first = Vec::new(); let mut lost_first = 0; while !read_first.iter().any(|r| is(r, task, Event::Park)) { let (more, lost) = read_to_now(&mut first); read_first.extend(more); lost_first += lost; - std::thread::yield_now(); } child.stdin.take().expect("the waiter's stdin").write_all(&[1]).expect("wake the waiter"); assert!(child.wait().expect("wait the waiter").success(), "the waiter failed"); From 7067014e6a8114adef8c1079d1f0561770833845 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 10:07:54 +0200 Subject: [PATCH 3/7] virt_smp judges its jobs over one capture Each judge drained into a capture of its own, so a job whose end arrived in the drain that took the job before it was never seen: the suite run at bf2e0af5b stalled on test_rs_trace_read with the guest already powered off. The later jobs now wait over the capture the first one returned. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- tests/toyos.rs | 23 ++++++++++++++--------- 1 file changed, 14 insertions(+), 9 deletions(-) diff --git a/tests/toyos.rs b/tests/toyos.rs index 48820b9ffd0..cd98eed3047 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1553,11 +1553,16 @@ fn mask_windows(capture: &str, cpus: u32) -> Result<(), String> { /// Wait for `job`'s end on a guest booted with it, and judge it: it ends with /// exit 0, having said `said`. Answers everything the PL011 carried. fn judge_virt_job(qemu: &mut QemuInstance, job: &str, said: &str) -> Result { + let mut serial = format!("{}\n", qemu.boot_log()); + judge_virt_job_after(qemu, &mut serial, job, said)?; + Ok(serial) +} + +/// [`judge_virt_job`] for a job after another, over the capture the one before +/// it drained into: one drain can carry both jobs' ends. +fn judge_virt_job_after(qemu: &mut QemuInstance, serial: &mut String, job: &str, said: &str) -> Result<(), String> { let end = format!("===TEST_END {job} "); - let mut rest = String::new(); - let waited = await_marker(qemu, &mut rest, &end, &format!("the job {job} to end")); - let serial = format!("{}\n{rest}", qemu.boot_log()); - if let Err(why) = waited { + if let Err(why) = await_marker(qemu, serial, &end, &format!("the job {job} to end")) { return Err(format!("{why}\nserial:\n{serial}")); } let ended = serial @@ -1571,7 +1576,7 @@ fn judge_virt_job(qemu: &mut QemuInstance, job: &str, said: &str) -> Result Result<(), String // Before the job list can reach its `shutdown`: QMP delivers no event // emitted before its client connected. let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET)); - let serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?; + let mut serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?; let psci = serial.lines().find(|l| l.contains("PSCI: ")).unwrap_or_default(); if !psci.contains(&format!(" through {conduit}")) { return Err(format!("PSCI is not said to be reached through {conduit}: {psci:?}\nserial:\n{serial}")); @@ -1664,10 +1669,10 @@ fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String } } eprintln!(" [virt] {VIRT_CPUS} CPUs entered at EL{el}, started through {conduit}, and scheduling"); - judge_virt_job(&mut qemu, "test_rs_counters_read", COUNTERS_READ_SAID)?; - let counted = judge_virt_job(&mut qemu, "test_rs_trace_read", TRACE_READ_SAID)?; + judge_virt_job_after(&mut qemu, &mut serial, "test_rs_counters_read", COUNTERS_READ_SAID)?; + judge_virt_job_after(&mut qemu, &mut serial, "test_rs_trace_read", TRACE_READ_SAID)?; let (console, calls) = - ended_through_psci(&mut qemu, &mut stop, counted, power::SHUTTING_DOWN, "guest-shutdown", &trace, |_| Vec::new())?; + ended_through_psci(&mut qemu, &mut stop, serial, power::SHUTTING_DOWN, "guest-shutdown", &trace, |_| Vec::new())?; let record = console .lines() .find_map(toyos_quiesce::Record::parse) From 53f75eacb74335aed17506e68c734dc5d4229f05 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 12:52:46 +0200 Subject: [PATCH 4/7] DIAGNOSTIC, reverted by the next commit: name what laps a ring on the T14 The T14 lapped a diary ring inside trace_read's spawn, 10802 records lost to the cursor that read throughout and 14424 to the one that read last, inside about 20 ms, on a boot whose interrupt census gives each CPU at most two timer interrupts. The readback cannot say which CPU wrote them or what they were. This commit exists only to build the image that can: - the idle path writes a Mark record whose data names every reason it declined to halt (bit 0 a kick, 1 need_resched, 2 an irq_ring record, 3 a mailbox message, 4 the i8042 verdict, 5 xHCI port work); - trace_read prints, before its assertion, each CPU's records written over the window and the kinds and pids of the records it read back. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- kernel/src/sched/driver.rs | 17 ++++++------- tests/toyos-rust-tests/src/bin/trace_read.rs | 26 ++++++++++++++++++++ 2 files changed, 34 insertions(+), 9 deletions(-) diff --git a/kernel/src/sched/driver.rs b/kernel/src/sched/driver.rs index eb41187bd06..00c7af8555c 100644 --- a/kernel/src/sched/driver.rs +++ b/kernel/src/sched/driver.rs @@ -639,16 +639,15 @@ fn execute(action: Action) { // Not `Machine::irq_guard`: both exits must set `IF`. crate::arch::cpu::disable_interrupts(); let cpu = CpuId(percpu::cpu_id()); - let awake = cpus().get(cpu).doorbell().kick_pending() - || crate::preempt::need_resched() - || crate::irq_ring::any_pending_self() - || !with_cpu(|c| c.mailbox_is_empty()) - // The i8042 verdict needs a pass to notice its deadline; a quiet machine after boot runs none otherwise. - || crate::arch::keyboard_controller::verdict_due() - // No log condition here: a log to write means a runnable process, covered above. A pending - // root-hub port needs a pass too — no interrupt is coming. - || crate::drivers::xhci::port_work_pending(); + let why = (cpus().get(cpu).doorbell().kick_pending() as u32) + | (crate::preempt::need_resched() as u32) << 1 + | (crate::irq_ring::any_pending_self() as u32) << 2 + | (!with_cpu(|c| c.mailbox_is_empty()) as u32) << 3 + | (crate::arch::keyboard_controller::verdict_due() as u32) << 4 + | (crate::drivers::xhci::port_work_pending() as u32) << 5; + let awake = why != 0; if awake { + crate::trace::trace(crate::trace::Kind::Mark, why); crate::arch::cpu::enable_interrupts(); drop(token); return; diff --git a/tests/toyos-rust-tests/src/bin/trace_read.rs b/tests/toyos-rust-tests/src/bin/trace_read.rs index 1d1dbe24c68..d4870ad3f6f 100644 --- a/tests/toyos-rust-tests/src/bin/trace_read.rs +++ b/tests/toyos-rust-tests/src/bin/trace_read.rs @@ -75,7 +75,33 @@ fn main() { let (more, lost) = read_to_now(&mut first); read_first.extend(more); lost_first += lost; + let start = second; let (read_second, lost_second) = read_to_now(&mut second); + { + let mut by: BTreeMap<(u16, String, u32), u64> = BTreeMap::new(); + let mut span: BTreeMap = BTreeMap::new(); + for r in &read_second { + let k = match Entry::decode(r) { + Ok(e) => match e.event { + Event::Mark { index } => format!("awake{index:#x}"), + ev => format!("{ev:?}").split([' ', '{']).next().unwrap().to_string(), + }, + Err(_) => format!("bad{}", r.kind), + }; + *by.entry((r.cpu, k, r.pid)).or_default() += 1; + let s = span.entry(r.cpu).or_insert((u64::MAX, 0)); + s.0 = s.0.min(r.stamp); + s.1 = s.1.max(r.stamp); + } + for cpu in 0..syscall::cpu_count() as usize { + eprintln!("DIAG cpu{cpu} wrote {} stamps {:?}", second.0.next[cpu] - start.0.next[cpu], span.get(&(cpu as u16))); + } + for ((cpu, k, pid), n) in &by { + eprintln!("DIAG cpu{cpu} {k} pid{pid} {n}"); + } + eprintln!("DIAG test pid {} child pid {}", std::process::id(), task.pid); + eprintln!("DIAG lost {lost_first} {lost_second}"); + } assert_eq!((lost_first, lost_second), (0, 0), "a quiet machine lapped a ring inside one spawn"); let second_by_place: BTreeMap<(u16, u64), &TraceRecord> = read_second.iter().map(|r| ((r.cpu, r.seq), r)).collect(); From 1ed7bfb8de9f0f62da1b52396a9ef24207c30f8d Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 12:53:23 +0200 Subject: [PATCH 5/7] Revert the diagnostic: its image is staged, and nothing of it ships This reverts commit 53f75eacb, whose only product is the T14 image staged from it (sha256 a839b782337c6781d5a5d617a15d30939c5c73fa8bfc0ebc2f22a10bc0c90bb4). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- kernel/src/sched/driver.rs | 17 +++++++------ tests/toyos-rust-tests/src/bin/trace_read.rs | 26 -------------------- 2 files changed, 9 insertions(+), 34 deletions(-) diff --git a/kernel/src/sched/driver.rs b/kernel/src/sched/driver.rs index 00c7af8555c..eb41187bd06 100644 --- a/kernel/src/sched/driver.rs +++ b/kernel/src/sched/driver.rs @@ -639,15 +639,16 @@ fn execute(action: Action) { // Not `Machine::irq_guard`: both exits must set `IF`. crate::arch::cpu::disable_interrupts(); let cpu = CpuId(percpu::cpu_id()); - let why = (cpus().get(cpu).doorbell().kick_pending() as u32) - | (crate::preempt::need_resched() as u32) << 1 - | (crate::irq_ring::any_pending_self() as u32) << 2 - | (!with_cpu(|c| c.mailbox_is_empty()) as u32) << 3 - | (crate::arch::keyboard_controller::verdict_due() as u32) << 4 - | (crate::drivers::xhci::port_work_pending() as u32) << 5; - let awake = why != 0; + let awake = cpus().get(cpu).doorbell().kick_pending() + || crate::preempt::need_resched() + || crate::irq_ring::any_pending_self() + || !with_cpu(|c| c.mailbox_is_empty()) + // The i8042 verdict needs a pass to notice its deadline; a quiet machine after boot runs none otherwise. + || crate::arch::keyboard_controller::verdict_due() + // No log condition here: a log to write means a runnable process, covered above. A pending + // root-hub port needs a pass too — no interrupt is coming. + || crate::drivers::xhci::port_work_pending(); if awake { - crate::trace::trace(crate::trace::Kind::Mark, why); crate::arch::cpu::enable_interrupts(); drop(token); return; diff --git a/tests/toyos-rust-tests/src/bin/trace_read.rs b/tests/toyos-rust-tests/src/bin/trace_read.rs index d4870ad3f6f..1d1dbe24c68 100644 --- a/tests/toyos-rust-tests/src/bin/trace_read.rs +++ b/tests/toyos-rust-tests/src/bin/trace_read.rs @@ -75,33 +75,7 @@ fn main() { let (more, lost) = read_to_now(&mut first); read_first.extend(more); lost_first += lost; - let start = second; let (read_second, lost_second) = read_to_now(&mut second); - { - let mut by: BTreeMap<(u16, String, u32), u64> = BTreeMap::new(); - let mut span: BTreeMap = BTreeMap::new(); - for r in &read_second { - let k = match Entry::decode(r) { - Ok(e) => match e.event { - Event::Mark { index } => format!("awake{index:#x}"), - ev => format!("{ev:?}").split([' ', '{']).next().unwrap().to_string(), - }, - Err(_) => format!("bad{}", r.kind), - }; - *by.entry((r.cpu, k, r.pid)).or_default() += 1; - let s = span.entry(r.cpu).or_insert((u64::MAX, 0)); - s.0 = s.0.min(r.stamp); - s.1 = s.1.max(r.stamp); - } - for cpu in 0..syscall::cpu_count() as usize { - eprintln!("DIAG cpu{cpu} wrote {} stamps {:?}", second.0.next[cpu] - start.0.next[cpu], span.get(&(cpu as u16))); - } - for ((cpu, k, pid), n) in &by { - eprintln!("DIAG cpu{cpu} {k} pid{pid} {n}"); - } - eprintln!("DIAG test pid {} child pid {}", std::process::id(), task.pid); - eprintln!("DIAG lost {lost_first} {lost_second}"); - } assert_eq!((lost_first, lost_second), (0, 0), "a quiet machine lapped a ring inside one spawn"); let second_by_place: BTreeMap<(u16, u64), &TraceRecord> = read_second.iter().map(|r| ((r.cpu, r.seq), r)).collect(); From 60d3547aea5cc4544b97bc89379c1fd9ce0b3130 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 15:41:01 +0200 Subject: [PATCH 6/7] Answer review round 4: the ring is indexed, the step-1 exit is the owner's - kernel/src/trace.rs: a record on a CPU id past MAX_CPUS is an index panic, not a silent drop. - userland/trace: a description; a failed flush ends the program as a failed write does. - toyos-abi/src/trace.rs: the two tests that re-read adjacent declarations go. - The diary track states what step 1's code does against its accepted exit, keeps the owner's clause "a process without the right is ended" unchanged, and leaves the difference (PermissionDenied, the caller lives) open for him; it carries the T14 reading of 70c1fbf56 and the restored accepted line on the LLDB path. - issues/clippy-stage-two-is-lints-one-at-a-time.md: initialize_zeroed is gone, so log/ no longer names it as its irreducible site. - Filed issues/no-test-runs-the-shipped-trace-reader.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...clippy-stage-two-is-lints-one-at-a-time.md | 13 ++++---- .../no-test-runs-the-shipped-trace-reader.md | 21 ++++++++++++ ...ateness-and-records-no-slow-system-call.md | 12 +++++-- kernel/src/trace.rs | 2 +- toyos-abi/src/trace.rs | 33 ------------------- userland/trace/Cargo.toml | 1 + userland/trace/src/main.rs | 4 ++- 7 files changed, 42 insertions(+), 44 deletions(-) create mode 100644 issues/no-test-runs-the-shipped-trace-reader.md diff --git a/issues/clippy-stage-two-is-lints-one-at-a-time.md b/issues/clippy-stage-two-is-lints-one-at-a-time.md index 0ddaaa66cf4..c2d86736172 100644 --- a/issues/clippy-stage-two-is-lints-one-at-a-time.md +++ b/issues/clippy-stage-two-is-lints-one-at-a-time.md @@ -145,7 +145,7 @@ before adopting: | `sched/` | 8 | **adopted 2026-08-22**, under the reduction ruling. 8 findings (26 `unsafe` blocks in all); **4 removed, 5 documented, 1 filed** — the five sites of the same shape outside this area, since taken by the root-file and `arch/` sweeps, so that file is closed too. | | `loader/` | 8 | **adopted** — every site now carries a `SAFETY:` comment (one finding shared with `elf/`, above) | | `iommu/` | 8 | **adopted 2026-08-22**, under the reduction ruling. 8 findings (8 `unsafe` blocks in all); **5 removed, 3 documented, 0 filed** — the area's whole remainder is two window constructions and a `clflush`. | -| `log/` | 2 | **adopted 2026-08-22**, under the reduction ruling. 2 findings (9 `unsafe` blocks in all, seven of them documented before this pass); **0 removed, 2 documented, 1 filed** — and the filed one was built the same day: `LogRecord` has the safe `as_bytes` its six siblings carry, so `log::user`'s hand-rolled slice is gone and the area's remainder is one block (`shard::initialize_zeroed`, irreducible). | +| `log/` | 2 | **adopted 2026-08-22**, under the reduction ruling. 2 findings (9 `unsafe` blocks in all, seven of them documented before this pass); **0 removed, 2 documented, 1 filed** — and the filed one was built the same day: `LogRecord` has the safe `as_bytes` its six siblings carry, so `log::user`'s hand-rolled slice is gone. The block left, `shard::initialize_zeroed`, went once a zeroed shard was an empty one. | | `object/` | 1 | **adopted** — the one site is `object::shm::Pages`'s `Send`/`Sync` pair, part of the finding filed above | | `completion` (since deleted) | 0 undocumented (3 unsafe sites, all already carrying a `SAFETY:`/`Safety:` comment predating this pass) | already documented | | **adopted** | **389** — the whole kernel (`mm` 35 + `elf` 23 + `loader` 8 + `object` 1 + root files 76 + `drivers` 121 + `arch` 107 + `sched` 8 + `iommu` 8 + `log` 2) | gated at the source, because the kernel is one crate with no `-p` scoping to hang a lint on. Every area sweep opened its entry module (`mm/mod.rs`, `object/mod.rs`, `elf/mod.rs`, `loader/mod.rs`, `drivers/mod.rs`, `arch/mod.rs`, `sched/mod.rs`, `iommu/mod.rs`, `log/mod.rs`) with `#![warn(clippy::undocumented_unsafe_blocks)]`; the root-file sweep could not — there is no entry module above them but the crate root — so it **inverted the form**: `main.rs` carries one crate-level `#![warn(...)]`, and an `#[allow(...)]` on a `mod` line is the form a tree not yet swept would take. Both compose with `host-tests.yml`'s existing `-D warnings` on the two kernel invocations, so no command line changed. The module attributes are redundant under the crate one and are left where they are — each still records its own area's status. | @@ -480,14 +480,13 @@ What stayed: `table::flush`'s `clflush`/`mfence`, which has no safe spelling and no narrower one — the instruction takes an address and no length, so the bound has to be on the caller's side, and it now is. -**`log/` removed nothing in the sweep itself, and both reasons are named at the -site.** `shard::initialize_zeroed` writes one word in place through a -caller-supplied pointer because the alternative is materialising a 512 KiB -`Shard` on the BSP's 16 KiB stack — irreducible. `log::user`'s record-to-bytes +**`log/` removed nothing in the sweep itself.** `log::user`'s record-to-bytes slice was reducible and needed a sysroot claim to reduce, so the sweep filed it and the next pull request that was claiming the sysroot anyway took it: -`LogRecord::as_bytes` exists, `log::user`'s block is gone, and the area is down -to the one irreducible site. +`LogRecord::as_bytes` exists and `log::user`'s block is gone. +`shard::initialize_zeroed`, which wrote a shard's one nonzero word in place +rather than build 512 KiB on the BSP's 16 KiB stack, went once a zeroed shard +was an empty one. **What was reducible and was declined, with the reason.** The kernel stack canary's two accesses (`write_stack_canary`, `check_stack_canary`) can go diff --git a/issues/no-test-runs-the-shipped-trace-reader.md b/issues/no-test-runs-the-shipped-trace-reader.md new file mode 100644 index 00000000000..e480bcd046b --- /dev/null +++ b/issues/no-test-runs-the-shipped-trace-reader.md @@ -0,0 +1,21 @@ +--- +status: open +kind: defect +opened: 2026-10-04 +--- + +# No test runs the shipped `/system/bin/trace` + +`userland/trace` ships on the `trace` right `system.toml` grants it, and no +test runs it: not its lines, and none of its refusals, each exit 2 with a +reason on stderr — no system capability, a capability without `trace`, a +record that does not decode. `test_rs_trace_read` reaches the syscall and the +decoder underneath it, not the program. A test of the program needs a boot +whose image carries it, which `tests/virtsmpcase` does not (its jobs are the +suite binaries the harness puts on ROOT). + +Owned by step 2 of +`issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md`, +whose lateness reader reads the same rings. **Exit**: a test runs the program +with its right and reads its lines back, and runs it with no capability and +with one lacking `trace`, and reads exit 2 and the reason for each. diff --git a/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md b/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md index 80cace117cf..c4dcbf6bc1a 100644 --- a/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md +++ b/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md @@ -26,8 +26,15 @@ anything more is built on it. test in which a spawned child's wake precedes its pick, a second cursor is undisturbed, loss is counted after a flood, and a process without the right is ended; and on the T14, the ticks a record costs, measured by a boot that - writes a million records. Built; the T14 reading is owed, and the - `trace_record_cost` row takes it. + writes a million records. Where the tree stands against it: every clause + but one is met, the LLDB reading path and its pinned numbers are gone, + and a record costs 53.15 counter ticks on the T14 (`trace_record_cost` at + `70c1fbf56`: 1000000 records in 53145868 ticks). The clause not met as + written is "a process without the right is ended": a capability without + `trace` is refused with `PermissionDenied` and its caller lives, and only + a handle the caller does not hold ends it. Whether that answers the clause, + or the kernel ends such a caller, is open for the owner, and step 1 is not + done until he says. 2. **Timer and thread lateness**, computed by a reader from the arm, fire and pick events, with no tracer in the kernel. **Exit**, on the T14: the 50 ms for which `hold_once` keeps both windows open once a boot @@ -66,6 +73,7 @@ The proposal's other lines, accepted with it: - The ring stays always written in the shipping kernel. - Reading it needs a new `trace` right. +- The LLDB reading path and its pinned numbers go. - A T14 judge may read a binary trace file, the decoder printing the lines a pull request quotes. - The profiling sample shares the ring. diff --git a/kernel/src/trace.rs b/kernel/src/trace.rs index 49f1d67622a..9aeef3a287d 100644 --- a/kernel/src/trace.rs +++ b/kernel/src/trace.rs @@ -57,7 +57,7 @@ fn push(kind: Kind, task: Option<(u32, u32)>, data: u32) { } let guard = IrqGuard::close(); let at = percpu::cpu_id(); - let Some(ring) = RINGS.get(at as usize) else { return }; + let ring = &RINGS[at as usize]; let (pid, tid) = task.unwrap_or_else(|| { ( percpu::current_pid().map_or(NO_THREAD, |p| p.raw()), diff --git a/toyos-abi/src/trace.rs b/toyos-abi/src/trace.rs index 8eec6cef113..9737406304d 100644 --- a/toyos-abi/src/trace.rs +++ b/toyos-abi/src/trace.rs @@ -135,36 +135,3 @@ impl TraceCursor { self.0.lost } } - -#[cfg(test)] -mod tests { - use super::*; - - /// Every number a kind is read back as that kind, and no other number is one. - #[test] - fn every_kind_reads_back_and_nothing_else_does() { - let mut kinds = 0; - for word in 0..=u16::MAX { - if let Some(kind) = Kind::from_u16(word) { - assert_eq!(kind as u16, word); - kinds += 1; - } - } - assert_eq!(kinds, Kind::Mark as u16, "the kinds are numbered from one without a gap"); - } - - /// The encoder is the wire, so the test decodes the wire. - #[test] - fn as_bytes_is_the_fields_and_nothing_between_them() { - let r = TraceRecord { seq: 7, stamp: 0x0102_0304_0506_0708, kind: 2, cpu: 3, data: 4, pid: 5, tid: 6 }; - let b = r.as_bytes(); - assert_eq!(b.len(), RECORD_BYTES); - assert_eq!(u64::from_ne_bytes(b[0..8].try_into().unwrap()), 7); - assert_eq!(u64::from_ne_bytes(b[8..16].try_into().unwrap()), 0x0102_0304_0506_0708); - assert_eq!(u16::from_ne_bytes(b[16..18].try_into().unwrap()), 2); - assert_eq!(u16::from_ne_bytes(b[18..20].try_into().unwrap()), 3); - assert_eq!(u32::from_ne_bytes(b[20..24].try_into().unwrap()), 4); - assert_eq!(u32::from_ne_bytes(b[24..28].try_into().unwrap()), 5); - assert_eq!(u32::from_ne_bytes(b[28..32].try_into().unwrap()), 6); - } -} diff --git a/userland/trace/Cargo.toml b/userland/trace/Cargo.toml index 37b224115a1..29eee8adc3a 100644 --- a/userland/trace/Cargo.toml +++ b/userland/trace/Cargo.toml @@ -1,5 +1,6 @@ [package] name = "trace" +description = "ToyOS's diary reader: every record the kernel's trace rings still hold, merged across CPUs, one line each." version = "0.1.0" edition = "2024" license = "MIT OR Apache-2.0" diff --git a/userland/trace/src/main.rs b/userland/trace/src/main.rs index b3d5930b7d3..37903365c2d 100644 --- a/userland/trace/src/main.rs +++ b/userland/trace/src/main.rs @@ -60,7 +60,9 @@ fn main() { break; } } - let _ = stdout.flush(); + if stdout.flush().is_err() { + return; + } if lost > 0 { eprintln!("trace: {lost} records were overwritten before this read reached them"); } From 4dd33a87244f3744a8beead9bea7b6fc84b4170d Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 15:58:19 +0200 Subject: [PATCH 7/7] The diary's step 1 exit is the owner's ruling: refused, and the program lives The owner ruled (2026-10-04), "Refuse, like others": one rule for every permission, the request refused and the program alive. The track's exit is reworded to it, quoted, and step 1 reads Built. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...ateness-and-records-no-slow-system-call.md | 20 +++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md b/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md index c4dcbf6bc1a..233bb0ef68a 100644 --- a/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md +++ b/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md @@ -25,16 +25,16 @@ anything more is built on it. needs, and a decoder crate. **Exit**: host tests on the decoder; a guest test in which a spawned child's wake precedes its pick, a second cursor is undisturbed, loss is counted after a flood, and a process without the right - is ended; and on the T14, the ticks a record costs, measured by a boot that - writes a million records. Where the tree stands against it: every clause - but one is met, the LLDB reading path and its pinned numbers are gone, - and a record costs 53.15 counter ticks on the T14 (`trace_record_cost` at - `70c1fbf56`: 1000000 records in 53145868 ticks). The clause not met as - written is "a process without the right is ended": a capability without - `trace` is refused with `PermissionDenied` and its caller lives, and only - a handle the caller does not hold ends it. Whether that answers the clause, - or the kernel ends such a caller, is open for the owner, and step 1 is not - done until he says. + is refused and lives; and on the T14, the ticks a record costs, measured by + a boot that writes a million records. The refusal clause is the owner's + ruling (2026-10-04), **"Refuse, like others"**: "Keep one rule for every + permission: the request is refused and the program lives. The track's exit + is reworded to that. If you want missing permissions to end programs, that + becomes one change for all of them." Built: a capability without `trace` + is refused with `PermissionDenied` and its caller lives, the LLDB reading + path and its pinned numbers are gone, and a record costs 53.15 counter + ticks on the T14 (`trace_record_cost` at `70c1fbf56`: 1000000 records in + 53145868 ticks). 2. **Timer and thread lateness**, computed by a reader from the arm, fire and pick events, with no tracer in the kernel. **Exit**, on the T14: the 50 ms for which `hold_once` keeps both windows open once a boot