diff --git a/Cargo.lock b/Cargo.lock index 8459fc5a54f..4fa74723474 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2648,6 +2648,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 86fb3420eef..67651bf7ab0 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -59,6 +59,7 @@ members = [ "toyos-symbols", "toyos-tco", "toyos-tmpdir", + "toyos-trace", "toyos-tsc", "toyos-untrusted", "toyos-update", 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/nothing-in-the-machine-can-read-the-trace-ring.md b/issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md similarity index 65% rename from issues/nothing-in-the-machine-can-read-the-trace-ring.md rename to issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md index cfd72e56c33..233bb0ef68a 100644 --- a/issues/nothing-in-the-machine-can-read-the-trace-ring.md +++ b/issues/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/toyos-explains-itself.md`. @@ -24,12 +25,24 @@ 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. + 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 (`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). diff --git a/issues/toyos-beats-linuxs-latency-on-the-t14.md b/issues/toyos-beats-linuxs-latency-on-the-t14.md index 79368131af2..c85c9bf6c22 100644 --- a/issues/toyos-beats-linuxs-latency-on-the-t14.md +++ b/issues/toyos-beats-linuxs-latency-on-the-t14.md @@ -41,7 +41,7 @@ rows. The tail delays are only worked on once the diary shows their cause." The step his text names is step 2 here, `issues/syscall-preemption-is-incidental.md`, whose exit the `mask_windows` row reads; the diary is -`issues/nothing-in-the-machine-can-read-the-trace-ring.md`. That +`issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md`. That mapping is the orchestrator's, not his. **Exit**: each step's exit is met, in the file the step names, and on the T14, @@ -51,7 +51,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/nothing-in-the-machine-can-read-the-trace-ring.md`, a +`issues/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/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/issues/toyos-explains-itself.md b/issues/toyos-explains-itself.md index 5df16b270e3..795ee3852ef 100644 --- a/issues/toyos-explains-itself.md +++ b/issues/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, and a process's memory is a byte sum that reads 0 under contention. 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/logging-records-from-every-producer-and-a-kernel-that-waits-on-nobody.md`; the sinks half of `issues/redesign-the-log-subsystem.md` | -| Diary | `issues/nothing-in-the-machine-can-read-the-trace-ring.md` | +| Diary | `issues/the-diary-computes-no-lateness-and-records-no-slow-system-call.md` | | Counters, sizes | this file | | Profile | behind the diary's judgement; `issues/a-frozen-toyos-waits-for-a-hand-on-the-power-button.md` | | Accounting | `issues/nothing-charges-kernel-memory-to-a-process.md`, `issues/a-processs-memory-is-a-byte-total-that-reads-zero-under-contention.md`, `issues/blocked-time-is-invisible-while-the-park-lasts.md` | 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 57d6e77a216..b622316e1ca 100644 --- a/kernel/pure/sched/cpu.rs +++ b/kernel/pure/sched/cpu.rs @@ -916,13 +916,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 }, @@ -1057,7 +1058,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); } @@ -1069,7 +1070,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 @@ -1102,7 +1103,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"), @@ -1113,7 +1114,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; } @@ -1581,6 +1582,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, @@ -1599,7 +1601,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() } @@ -1632,11 +1634,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() } @@ -1832,6 +1835,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 @@ -1843,7 +1847,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; } } @@ -1853,11 +1857,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 }); } } @@ -2414,6 +2419,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 366efc9effc..3cb80e46fa1 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 f0894458f0f..2ff8cc727c4 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 d36b28c560d..e4472eb1526 100644 --- a/kernel/src/sched/payload.rs +++ b/kernel/src/sched/payload.rs @@ -68,6 +68,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 9fe3c50a9b2..c3dacf6690c 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 { @@ -625,6 +635,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(), + }, // An interrupt inside a syscall's body, which nothing a guest does puts there on demand. DA::RING0_TIMER_IN_SYSCALL => ring0_timer_in_syscall(), _ => SyscallError::InvalidArgument.to_u64(), diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index da3a809c58d..ccb143d81ab 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..9aeef3a287d 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 ring = &RINGS[at as usize]; + 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 571c134e92f..092bc52b608 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 ccffcf39ee2..266087d1fe4 100644 --- a/system.toml +++ b/system.toml @@ -113,6 +113,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"] + # Names a killed program's frames from the file and offset the kernel records: # it reads the files a record names and holds nothing else. [programs.symbolize] 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..1d1dbe24c68 --- /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; 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; + } + 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 bca88e9f617..ba3aac3a3c2 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -108,6 +108,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` @@ -166,6 +169,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", @@ -446,6 +450,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. @@ -1539,6 +1561,10 @@ const VIRT_RING0_TIMER: &str = "ring0_timer_in_syscall"; /// `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) { @@ -1661,7 +1687,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 }, ) @@ -1670,11 +1699,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")); @@ -1712,6 +1744,7 @@ 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, &mut serial, "test_rs_counters_read", COUNTERS_READ_SAID)?; + judge_virt_job(&mut qemu, &mut serial, "test_rs_trace_read", TRACE_READ_SAID)?; let (console, calls) = ended_through_psci(&mut qemu, &mut stop, serial, 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 220b683b98b..85e16841057 100644 --- a/toyos-abi/src/handle.rs +++ b/toyos-abi/src/handle.rs @@ -152,11 +152,15 @@ impl Rights { /// Beside [`COUNTERS`](Self::COUNTERS), [`SYS_COUNTERS`] answers each /// CPU's `APERF` and `MPERF` — its frequency and busy fraction, the /// Hertzbleed power channel — the kicks it took, the wake-ups that time - /// keystrokes, and the power envelope it runs under. Admin tools hold it, `inspect` and `test-runner`; no + /// keystrokes, and the power envelope it runs under. [`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 a72f1508f15..c5c4d71930d 100644 --- a/toyos-abi/src/syscall.rs +++ b/toyos-abi/src/syscall.rs @@ -276,19 +276,26 @@ pub const SYS_PORT_MINT: u64 = 125; /// with. See [`port_badge`]. pub const SYS_PORT_BADGE: u64 = 126; +/// 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 = 127; + /// 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. /// /// **The profile's parts sum to its total, and that is the whole requirement.** /// A bin array narrower than the ABI reaches drops calls out of the line while /// the total goes on counting them. -pub const SYSCALL_PROFILE_BINS: usize = 128; +pub const SYSCALL_PROFILE_BINS: usize = 129; /// Where a number this ABI does not issue is counted. Merging is a degradation /// 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_PORT_BADGE < SYSCALL_PROFILE_OTHER as u64); +const _: () = assert!(SYS_TRACE_READ < SYSCALL_PROFILE_OTHER as u64); pub const WNOHANG: u64 = 1; @@ -831,6 +838,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; /// Arm this CPU's timer to fire within 100 µs and wait inside the syscall /// for the kernel's own fire. Answers [`RING0_FIRE_REARMED`] once it fired /// and re-armed a quantum, [`RING0_FIRE_NEVER`] if none came within @@ -2041,6 +2056,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..9737406304d --- /dev/null +++ b/toyos-abi/src/trace.rs @@ -0,0 +1,137 @@ +//! 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 + } +} 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 50e2824dc15..a90cda0dc37 100644 --- a/toyos/src/syscap.rs +++ b/toyos/src/syscap.rs @@ -144,6 +144,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 66ce73e9a07..a597548e4e1 100644 --- a/userland/Cargo.lock +++ b/userland/Cargo.lock @@ -4302,6 +4302,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" @@ -4335,6 +4342,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 4897c7ecb57..55a41520e05 100644 --- a/userland/Cargo.toml +++ b/userland/Cargo.toml @@ -36,6 +36,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..29eee8adc3a --- /dev/null +++ b/userland/trace/Cargo.toml @@ -0,0 +1,14 @@ +[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" + +[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..37903365c2d --- /dev/null +++ b/userland/trace/src/main.rs @@ -0,0 +1,74 @@ +//! `/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; + } + } + if stdout.flush().is_err() { + return; + } + if lost > 0 { + eprintln!("trace: {lost} records were overwritten before this read reached them"); + } +} + +fn refuse(why: &str) -> ! { + eprintln!("{why}"); + std::process::exit(2); +}