diff --git a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md index 9fe7bf58773..ebc005a0361 100644 --- a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md +++ b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md @@ -17,9 +17,9 @@ compiler; the branch `wt/toyos-counterstall` at `bc5f36c7b`, whose harness keeps every line the guest said. `test_rs_counters_read` started at 4.031, spawned at 4.044, two of its threads exited (4.174 and 4.576), and then the console carried nothing until the harness gave up 15 s later. No CPU printed -`sched: cpu=` again, though each last printed one at 2.17-2.22 s and prints -again on its first idle trip 10 s on (`scheduler::log_health`): no CPU went -idle, or the console stopped. No register capture of that guest exists. One +`sched: cpu=` again, though each last printed one at 2.17-2.22 s and that +kernel printed again on a CPU's first idle trip 10 s on: no CPU went idle, or +the console stopped. No register capture of that guest exists. One in 30 guests of that loop; none in the 1724 guests that followed on the same host at load 15-60. @@ -39,6 +39,13 @@ once per answering CPU (`762a524f0`, reverted in the next commit) changed neither the kicks taken during the read (median 116/122/118, fix/base/fix) nor its span, so the waiter-list contention is not shown to be the cause. +**The idle report is gone.** The owner ruled on 2026-10-04, choosing "Remove +it entirely": "Delete the periodic report and its counters; hang triage uses +the trace diary and panic records instead." A silent guest no longer says +whether its CPUs went idle by a `sched:` line's absence; its diary +(`kernel/src/trace.rs`, read by `/system/bin/trace`) and its panic records +(`kernel/src/panic.rs`, `kernel/src/blackbox.rs`) do. + Exit: the cause of the silence is named from a capture of a silent guest (registers over QMP before anything else touches it), and fixed with the evidence, or shown to be the host stopping the guest. diff --git a/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md b/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md index f3e2025dbe8..5c3f09cea8f 100644 --- a/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md +++ b/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md @@ -50,8 +50,16 @@ would leave a whole boot idle straight after a sibling thread's clean exit. path's two posts. **Exit condition.** A capture taken from a boot that has actually stopped, which -names the first waiter and the subject it waits on — the blocked-task dump, or a -guest whose own last line is not the periodic reporter. +names the first waiter and the subject it waits on — the blocked-task dump, or +that boot's trace diary and panic records. + +**The periodic reporter is gone.** The owner ruled on 2026-10-04, choosing +"Remove it entirely": "Delete the periodic report and its counters; hang +triage uses the trace diary and panic records instead." The `sched:` and +`PMM:` lines the sightings below quote are no longer printed, so a stopped +boot is told from a healthy idle one by its diary (`kernel/src/trace.rs`, read +by `/system/bin/trace`) and its panic records (`kernel/src/panic.rs`, +`kernel/src/blackbox.rs`). **Sighting, 2026-09-25.** `cargo test` (the full fast tier) on the dev host, 12 wide, TCG, on `wt/toyos-inspect` at `9ff0d254`. That branch touches no file under `kernel/`, diff --git a/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md b/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md index 11d066e2a44..ca1627505fa 100644 --- a/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md +++ b/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md @@ -28,7 +28,10 @@ A thousand such processes is the whole 16 GB machine. Packing a process's small regions into one shared page lowers the floor to about 4 MB, since every stack still needs its own page with an unmapped neighbour as its guard; that moves the ceiling to a few thousand and not past it. x86-64 offers no page -size between 4 KiB and 2 MiB. +size between 4 KiB and 2 MiB. That `PMM:` record and its rows went with the +kernel's idle report (the owner's ruling of 2026-10-04: "Delete the periodic +report and its counters"); stage 3's floor is read from the used memory +`SYS_SYSINFO` reports. **What this removes as a side effect:** a device window mapped at 4 KiB no longer shares a 2 MiB page with a neighbour's registers, so the relocation diff --git a/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md b/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md index c95daf9a9ff..b0021e4b007 100644 --- a/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md +++ b/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md @@ -57,6 +57,9 @@ running through the silence; the capture cannot tell a dropped marker from a `lo forwarding. The tree moved `rust` from `aca5f527f` to `9151571ca`, which changes std's exported C `malloc`, `free` and `realloc` in every Rust guest program, so reading it as this loss rests on that change being off its path. Owner: the orchestrator. +That kernel's ten-second report is gone: the owner ruled on 2026-10-04, choosing "Remove it +entirely": "Delete the periodic report and its counters; hang triage uses the trace diary and +panic records instead." A later sighting tells a live kernel from a stopped one by those. ## Exit condition diff --git a/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md b/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md deleted file mode 100644 index 4d891d1538a..00000000000 --- a/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md +++ /dev/null @@ -1,28 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-04 ---- - -# T14 cpu7 idles busier under ToyOS than any CPU under Linux - -The `counters` metal row reads each CPU's MPERF over its stamp across the idle -second between its `idle0` and `idle1` reads. Linux's turbostat on the same -machine, idle (`tests/t14-linux/turbostat-idle.txt`), reads 0.11 to 0.36% -machine-wide per 10 s and no CPU above 0.69%. - -cpu7 reads about four times that, on every boot so far: 1.45% at `ce1786ff0` -(pull request #705), 1.42% at `a059144e2`, and 1.86% and 1.85% on the two arms -of pull request #725's run. - -cpu0 read 1.37% and 1.35% on the first two boots. That was the idle loop -spinning on an `irq_ring` record `xhci::poll_if_pending` left when a USB-stick -transfer held `XHCI`; since `XHCI` became an `OwedLock`, cpu0 reads 0.50% with -the change (`a65205a81`) and 1.77% with the whole change reverted -(`b0cae9a19`), cpu1 to cpu6 0.45 to 0.68% on both arms. - -Not yet attributed: the row's own reader runs between the two reads, prints -its `idle0` lines and parks, and which CPUs it and the log's path ran on that -second is not recorded. Owner: the orchestrator, which holds the T14. -**Exit**: a reading that names what ran on cpu7 across that second; then the -cause is fixed, or, if it is the row's own work, folded to the row's doc. diff --git a/issues/the-global-pipe-lock-spans-a-user-copy.md b/issues/the-global-pipe-lock-spans-a-user-copy.md index f2efd081b3a..f52db2d1e28 100644 --- a/issues/the-global-pipe-lock-spans-a-user-copy.md +++ b/issues/the-global-pipe-lock-spans-a-user-copy.md @@ -18,7 +18,7 @@ The bulk copy is inside that closure, not outside it. The size is bounded only by the ring: `PIPE_SIZE = PAGE_2M` (`pipe.rs:104`), `PAGE_2M = 2 * 1024 * 1024` (`toyos-userbound/src/span.rs:27`), and `capacity = total_size - size_of::()` (`ring.rs:60`) with `RingHeader` `#[repr(C, align(64))]` holding one `AtomicU32` (`ring.rs:24-27`) — so **2,097,088 bytes** is the largest single copy under the lock. Nothing above caps it: `SYS_READ`/`SYS_WRITE` pass the userland length straight through (`kernel/src/syscall/dispatch.rs:110-116`), `object::ops::try_read` hands the full window to `pipe::try_read` (`kernel/src/object/ops.rs:339-340`), and the only other bound, `user_ptr::window` (`user_ptr.rs:269`), requires physical contiguity — which a demand-paged 2 MiB frame satisfies exactly. -A pipe's **first** write is worse, because the page is allocated lazily under the same lock. `try_write` calls `pipe.back()` (`pipe.rs:250`), which calls `pmm::alloc_page(pmm::Category::Pipe)` (`pipe.rs:148`). That takes `BITMAP` nested inside `PIPES` (`kernel/src/mm/pmm.rs:221`), linearly scans up to the whole physical bitmap for a free frame (`pmm.rs:224-241`), and then `write_bytes(..., 0, PAGE_2M)` — a 2 MiB zeroing (`pmm.rs:233-237`) — before `Ring::new` and the user copy that follows it. +A pipe's **first** write is worse, because the page is allocated lazily under the same lock. `try_write` calls `pipe.back()` (`pipe.rs:250`), which calls `pmm::alloc_page()` (`pipe.rs:148`). That takes `BITMAP` nested inside `PIPES` (`kernel/src/mm/pmm.rs:221`), linearly scans up to the whole physical bitmap for a free frame (`pmm.rs:224-241`), and then `write_bytes(..., 0, PAGE_2M)` — a 2 MiB zeroing (`pmm.rs:233-237`) — before `Ring::new` and the user copy that follows it. ## What queues behind it diff --git a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md index fcc34d91b5a..de69458b088 100644 --- a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md +++ b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md @@ -25,6 +25,14 @@ lines are quoted on #681 (comment 5962619169; the boot itself in comment 9.925 s all eight CPUs carry one at once. That the CPU stops is shown by two CPUs waiting on a lock across a step, which went 4,503,694 and 4,554,675 ns between two turns of their own spin. +- **MPERF reads the stop as about 4.55 ms of C0 on every CPU.** One T14 boot + of a scout image without ACPI mode read twelve back-to-back idle seconds + between counters rounds; `35cd63142`, which added this bullet, carries its + image hash and per-second lines. In the five whose SMI count moved by one, + cpu2, cpu4, cpu5 and cpu6, which ran none of the log's work, read 4535 to + 4571 ppm busy; in the seven where it did not, 6 to 285 ppm. So the + `counters` row's idle second reads one of two floors, about 0.45% or 0.03% + and less: a 1 s second catches a 2.2 s-period SMI or does not. - **Linux, in one condition, read none.** On the same machine under Ubuntu's `6.8.0-142-generic`, `perf stat -a -A -e msr/smi/` read 0 on every CPU over 120.378 s beside `rtla timerlat top -q -d 2m --dma-latency 0`, which holds diff --git a/issues/toyos-explains-itself.md b/issues/toyos-explains-itself.md index 795ee3852ef..b5bc757632e 100644 --- a/issues/toyos-explains-itself.md +++ b/issues/toyos-explains-itself.md @@ -8,7 +8,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:`), +log carries numbers in prose (`irq:`, `tlb:`, `syscalls:`), 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. diff --git a/kernel/pure/sched/cpu.rs b/kernel/pure/sched/cpu.rs index b622316e1ca..958a19bbf0f 100644 --- a/kernel/pure/sched/cpu.rs +++ b/kernel/pure/sched/cpu.rs @@ -398,18 +398,10 @@ impl CpuSched { self.dying.iter().map(|corpse| &corpse.task) } - pub fn dying_len(&self) -> usize { - self.dying.len() - } - pub fn stopped(&self) -> impl Iterator> + '_ { self.stopped.iter() } - pub fn stopped_len(&self) -> usize { - self.stopped.len() - } - pub fn zombie_key(&self) -> Option { self.zombie.as_ref().map(|z| z.key()) } @@ -1687,9 +1679,8 @@ impl SchedPass<'_, '_, H, P, Disposed> { // wants everything a new task would queue behind, and a corpse // mid-unwind is exactly that: it is dispatched ahead of the fair // band, so counting `rq` alone makes a CPU holding two teardowns - // look as empty as an idle one — the same blindness `dying_len` - // closes in the dump. The steal probe wants what this CPU could - // hand over, which is the fair band and only the fair band; + // look as empty as an idle one. The steal probe wants what this + // CPU could hand over, which is the fair band and only the fair band; // publishing the first number to the second reader sends thieves to // CPUs with nothing to give. // @@ -2727,7 +2718,7 @@ mod tests { w.cpus[0].parked_task(key).is_some(), "the retire lost the claim: the entry stays for the wake to find", ); - assert_eq!(w.cpus[0].dying_len(), 0, "the retire placed nothing itself"); + assert_eq!(w.cpus[0].dying().count(), 0, "the retire placed nothing itself"); assert!(w.cpus[0].rq.is_empty(), "and queued nothing either"); // Now the wake it lost to lands, and *it* places the task — in the @@ -2877,14 +2868,14 @@ mod tests { } assert!(stopped_shared.stop_pending(), "the safe point takes the mark"); - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); assert_eq!(w.cpus[0].stopped[0].key(), stopped); assert_eq!( w.cpus[0].running().map(|t| t.key()), Some(other), "the CPU keeps working; only the stopped task is out", ); - assert_eq!(w.cpus[0].dying_len(), 0, "stopping is not dying"); + assert_eq!(w.cpus[0].dying().count(), 0, "stopping is not dying"); // Every later pass, including ones where the CPU has nothing else. w.run_a_pass_at(C0, Nanos(NOW.0 + QUANTUM_NS + 1)); @@ -2894,7 +2885,7 @@ mod tests { Some(stopped), "no pick serves the band", ); - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); w.abandon(); } @@ -2928,7 +2919,7 @@ mod tests { w.post_claimed_wake(C0, &parked_shared, WakeReason::Woken); w.run_a_pass(C0); - assert_eq!(w.cpus[0].stopped_len(), 1, "the wake reached the band"); + assert_eq!(w.cpus[0].stopped().count(), 1, "the wake reached the band"); assert_eq!(w.cpus[0].stopped[0].key(), parked); assert!(w.cpus[0].rq.is_empty(), "and never the run queue"); assert!( @@ -2970,9 +2961,9 @@ mod tests { w.post_claimed_wake(C0, &shared, WakeReason::Woken); w.run_a_pass(C0); - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); assert_eq!(w.cpus[0].stopped[0].key(), key); - assert_eq!(w.cpus[0].dying_len(), 0, "never dispatched to unwind"); + assert_eq!(w.cpus[0].dying().count(), 0, "never dispatched to unwind"); assert!(w.cpus[0].running().is_none()); w.abandon(); } @@ -2994,7 +2985,7 @@ mod tests { let pass = SchedPass::begin(&mut cpus[0], env, NOW); let _ = pass.dispose_stop().finish(); } - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); assert_eq!( w.handles.get(C0).load(), 0, @@ -3044,7 +3035,7 @@ mod tests { "the corpse that has been waiting longest unwinds next", ); assert_eq!( - w.cpus[0].dying_len(), + w.cpus[0].dying().count(), 1, "and the one whose quantum expired went back to the dying list", ); @@ -3087,7 +3078,7 @@ mod tests { Some(queued), "the waiting corpse runs; the killed one did not keep the CPU", ); - assert_eq!(w.cpus[0].dying_len(), 1); + assert_eq!(w.cpus[0].dying().count(), 1); assert_eq!(w.cpus[0].dying[0].task.key(), expiring); assert!(w.cpus[0].rq.is_empty(), "never through the fair queue"); w.abandon(); @@ -3131,7 +3122,7 @@ mod tests { "the yield hands the CPU to the corpse that was waiting", ); assert_eq!( - w.cpus[0].dying_len(), + w.cpus[0].dying().count(), 1, "and the yielder went back to the dying list", ); @@ -3193,7 +3184,7 @@ mod tests { cpus[1].drain(env, NOW); } - assert_eq!(w.cpus[1].dying_len(), 1, "the arriving corpse is placed to unwind"); + assert_eq!(w.cpus[1].dying().count(), 1, "the arriving corpse is placed to unwind"); assert_eq!(w.cpus[1].dying[0].task.key(), key); assert!( w.cpus[1].rq.is_empty(), @@ -3262,7 +3253,7 @@ mod tests { Some(rt), "the RT task got the CPU on the first pass after it became ready", ); - assert_eq!(w.cpus[0].dying_len(), 1, "the corpse is queued, not running"); + assert_eq!(w.cpus[0].dying().count(), 1, "the corpse is queued, not running"); assert!(w.released().is_empty(), "and nothing was discarded"); w.abandon(); } @@ -3284,7 +3275,7 @@ mod tests { Some(rt), "the expiring quantum is not a fresh one for the corpse", ); - assert_eq!(w.cpus[0].dying_len(), 1); + assert_eq!(w.cpus[0].dying().count(), 1); w.abandon(); } @@ -3388,7 +3379,7 @@ mod tests { Some(rt), "the RT task still takes the CPU on the pass that makes it ready", ); - assert_eq!(w.cpus[0].dying_len(), 1, "and the corpse is queued"); + assert_eq!(w.cpus[0].dying().count(), 1, "and the corpse is queued"); // Follow the armed timer, which is the only thing that takes the CPU // away from a task nothing preempts — a real machine does exactly this. @@ -3537,7 +3528,7 @@ mod tests { Some(rt), "the grant ends on its own boundary and not a nanosecond later", ); - assert_eq!(w.cpus[0].dying_len(), 1, "the corpse is queued again"); + assert_eq!(w.cpus[0].dying().count(), 1, "the corpse is queued again"); w.abandon(); } @@ -3577,7 +3568,7 @@ mod tests { "the corpse is unwinding, not doing real-time work, so the sibling \ that is doing real-time work gets the CPU at the next pass", ); - assert_eq!(w.cpus[0].dying_len(), 1, "and the corpse waits its age out"); + assert_eq!(w.cpus[0].dying().count(), 1, "and the corpse waits its age out"); assert!( w.cpus[0].dying[0].task.is_rt(), "with its right intact — this is about the band it competes in, not \ @@ -3646,7 +3637,7 @@ mod tests { "and the task came out of cpu2's surplus", ); assert_eq!( - w.cpus[1].dying_len(), + w.cpus[1].dying().count(), 3, "while cpu1's corpses stayed exactly where they were", ); diff --git a/kernel/src/arch/x86_64/vtd/table.rs b/kernel/src/arch/x86_64/vtd/table.rs index 0867e4b40fb..39e2fc2d44a 100644 --- a/kernel/src/arch/x86_64/vtd/table.rs +++ b/kernel/src/arch/x86_64/vtd/table.rs @@ -8,7 +8,7 @@ use alloc::vec::Vec; use crate::iommu::{AddressWidth, IommuError, Iova, StreamId}; -use crate::mm::pmm::{self, Category, PhysPage}; +use crate::mm::pmm::{self, PhysPage}; use crate::mm::{DirectMap, Mmio, PAGE_2M}; /// 4 KiB per table: 256 16-byte entries (root/context) or 512 8-byte entries (second-level). @@ -49,7 +49,7 @@ impl Tables { /// Returns one zeroed 4 KiB table, usable as a root, context, second-level, or invalidation-queue table. pub fn alloc(&mut self) -> Table { if self.used + TABLE_BYTES > PAGE_2M as usize { - let page = pmm::alloc_page(Category::Dma) + let page = pmm::alloc_page() .expect("iommu: no physical memory for a remapping table"); self.pages.push(page); self.used = 0; diff --git a/kernel/src/clock.rs b/kernel/src/clock.rs index ee7795c7dc1..2adf21ddd57 100644 --- a/kernel/src/clock.rs +++ b/kernel/src/clock.rs @@ -32,7 +32,7 @@ fn publish_page(counter_at_boot: u64, period_fs: u64) { use toyos_abi::clock::{ClockPage, CLOCK_MAGIC}; let bytes = crate::mm::PAGE_2M as usize; // Held for the machine's life: every process maps it. - let frame = crate::process::PageAlloc::new(bytes, crate::mm::pmm::Category::SharedMemory) + let frame = crate::process::PageAlloc::new(bytes) .expect("clock: no 2 MiB frame for the clock page"); // SAFETY: a fresh allocation this function owns, `bytes` long, that no // address space maps yet; zeroed whole because all of it is mapped, and diff --git a/kernel/src/drivers/gop.rs b/kernel/src/drivers/gop.rs index cc5f6797619..bdfe4f1018b 100644 --- a/kernel/src/drivers/gop.rs +++ b/kernel/src/drivers/gop.rs @@ -77,7 +77,7 @@ pub fn init( ); log!("GOP: scanout memory type {memory_type}"); - let cursor_pages = crate::mm::pmm::alloc_contiguous(1, crate::mm::pmm::Category::Framebuffer).expect("GOP: cursor alloc failed"); + let cursor_pages = crate::mm::pmm::alloc_contiguous(1).expect("GOP: cursor alloc failed"); let cursor_phys = cursor_pages[0].direct_map().phys(); // Cursor buffer is plain system RAM, not scanout, so it keeps the default write-back type. let cursor = Region { diff --git a/kernel/src/drivers/virtio_gpu.rs b/kernel/src/drivers/virtio_gpu.rs index e58b5a251a8..fa8ade0c680 100644 --- a/kernel/src/drivers/virtio_gpu.rs +++ b/kernel/src/drivers/virtio_gpu.rs @@ -415,8 +415,8 @@ impl GpuController { let fb_pages = fb_size.div_ceil(PAGE_2M as usize); let fb_aligned = (fb_pages * PAGE_2M as usize) as u64; let all_pages = - [crate::mm::pmm::alloc_contiguous(fb_pages, crate::mm::pmm::Category::Framebuffer)?, - crate::mm::pmm::alloc_contiguous(fb_pages, crate::mm::pmm::Category::Framebuffer)?]; + [crate::mm::pmm::alloc_contiguous(fb_pages)?, + crate::mm::pmm::alloc_contiguous(fb_pages)?]; let regions = all_pages.map(|pages| { let phys = pages[0].direct_map().phys(); Region { @@ -617,7 +617,7 @@ pub fn init(devices: &[PciDevice]) -> Option<(Box, GpuInfo)> { gpu.set_scanout(0, gpu.resource, rect); let cursor_bytes = (CURSOR_SIZE * CURSOR_SIZE * 4) as usize; - let cursor_pages = crate::mm::pmm::alloc_contiguous(1, crate::mm::pmm::Category::Framebuffer).expect("VirtIO GPU: cursor alloc failed"); + let cursor_pages = crate::mm::pmm::alloc_contiguous(1).expect("VirtIO GPU: cursor alloc failed"); let cursor_ptr = cursor_pages[0].direct_map().as_mut_ptr::(); let cursor_phys = cursor_pages[0].direct_map().phys(); gpu.cursor = Region { diff --git a/kernel/src/elf/cache.rs b/kernel/src/elf/cache.rs index 963222950d0..26cdcd53195 100644 --- a/kernel/src/elf/cache.rs +++ b/kernel/src/elf/cache.rs @@ -206,7 +206,7 @@ pub fn cache_loaded_lib( let Some(relocs) = scanned else { return Ok(owned(alloc)); }; - let Some(rw_alloc) = PageAlloc::new(rw_size, crate::mm::pmm::Category::Elf) else { + let Some(rw_alloc) = PageAlloc::new(rw_size) else { return Ok(owned(alloc)); }; let alloc_ptr = alloc.ptr(); @@ -282,7 +282,7 @@ pub fn try_clone_cached( fn clone_from_cache(cached: &CachedLib) -> Option { let t0 = crate::clock::nanos_since_boot(); - let rw_alloc = PageAlloc::new(cached.rw_size, crate::mm::pmm::Category::Elf)?; + let rw_alloc = PageAlloc::new(cached.rw_size)?; // SAFETY: `rw_offset + rw_size` was validated inside `cached.alloc` when this `CachedLib` was built; `CachedLib` is immortal once cached, so `cached.alloc` is still live. let src = unsafe { cached.alloc.ptr().add(cached.rw_offset) }; // SAFETY: `src` is valid for `cached.rw_size` bytes per the `SAFETY` above; `rw_alloc` is a fresh, distinct allocation, so the ranges cannot overlap. diff --git a/kernel/src/elf/mod.rs b/kernel/src/elf/mod.rs index 41618d3d993..6da1af0b3c1 100644 --- a/kernel/src/elf/mod.rs +++ b/kernel/src/elf/mod.rs @@ -377,7 +377,7 @@ pub fn load_shared_lib( let t0 = crate::clock::nanos_since_boot(); let alloc = - PageAlloc::new(load_size, crate::mm::pmm::Category::Elf).ok_or("dlopen: allocation failed")?; + PageAlloc::new(load_size).ok_or("dlopen: allocation failed")?; let t1 = crate::clock::nanos_since_boot(); // Every offset below is bounded against what the PMM actually returned, not `load_size`. let image = alloc.window(); diff --git a/kernel/src/loader/mod.rs b/kernel/src/loader/mod.rs index 303bcee008c..deb308799aa 100644 --- a/kernel/src/loader/mod.rs +++ b/kernel/src/loader/mod.rs @@ -487,7 +487,7 @@ pub fn spawn( } // Mapped eagerly, not demand-paged: every process touches the stack immediately. - let stack_pages = match PageAlloc::new(USER_STACK_SIZE, crate::mm::pmm::Category::Stack) { + let stack_pages = match PageAlloc::new(USER_STACK_SIZE) { Some(a) => a, None => { log!("spawn: {}: failed to allocate user stack ({} bytes)", path, USER_STACK_SIZE); diff --git a/kernel/src/loader/tls.rs b/kernel/src/loader/tls.rs index a4102834b39..c459287c2a9 100644 --- a/kernel/src/loader/tls.rs +++ b/kernel/src/loader/tls.rs @@ -63,7 +63,7 @@ impl TlsBlock { /// the block's physical address, which [`rebase`] moves once it has another. fn build_combined(modules: &[TlsModule], tls: Static) -> Option { let plan = tls.plan(TCB_SIZE, DTV_BYTES, crate::mm::PAGE_2M as usize)?; - let frames = Unpublished::new(PageAlloc::new(plan.alloc_size, crate::mm::pmm::Category::InitTls)?); + let frames = Unpublished::new(PageAlloc::new(plan.alloc_size)?); let block = frames.ptr(); // SAFETY: `block` is the fresh, unpublished `plan.alloc_size`-byte allocation above. diff --git a/kernel/src/mm/alloc.rs b/kernel/src/mm/alloc.rs index 0bb60a5bb98..a8250a070a0 100644 --- a/kernel/src/mm/alloc.rs +++ b/kernel/src/mm/alloc.rs @@ -557,7 +557,7 @@ unsafe impl GlobalAlloc for KernelAllocator { }; let mut base = malloc(None); if base.is_null() { - if let Some(frame) = pmm::claim(pmm::Category::KernelHeap) { + if let Some(frame) = pmm::claim() { base = malloc(Some(frame)); } } diff --git a/kernel/src/mm/dma.rs b/kernel/src/mm/dma.rs index 87b8132c777..1b89130ff2a 100644 --- a/kernel/src/mm/dma.rs +++ b/kernel/src/mm/dma.rs @@ -217,7 +217,7 @@ impl DmaPool { /// `space` and reachable by nothing outside it. pub fn alloc_in(size: usize, space: DeviceSpace) -> Self { let pages_2m = size.div_ceil(super::PAGE_2M as usize); - let pages = super::pmm::alloc_contiguous(pages_2m, super::pmm::Category::Dma) + let pages = super::pmm::alloc_contiguous(pages_2m) .expect("DmaPool: out of physical memory"); let base = pages[0].direct_map(); let size = pages_2m * super::PAGE_2M as usize; diff --git a/kernel/src/mm/pmm.rs b/kernel/src/mm/pmm.rs index 9be7bd4919d..266b0586109 100644 --- a/kernel/src/mm/pmm.rs +++ b/kernel/src/mm/pmm.rs @@ -1,5 +1,3 @@ -use core::sync::atomic::{AtomicU64, Ordering}; - use super::{DirectMap, PAGE_2M}; use crate::sync::Lock; use crate::MemoryMapEntry; @@ -11,105 +9,15 @@ pub struct Region { pub end: u64, } - -#[derive(Clone, Copy, Debug, PartialEq, Eq)] -#[repr(u8)] -pub enum Category { - KernelHeap = 0, // dlmalloc backing pages (global allocator) - DemandPage = 1, // page fault handler - Mmap = 2, // sys_mmap - SharedMemory = 3, // shared_memory::alloc - Pipe = 4, // pipe ring buffers - Elf = 5, // ELF loading (dlopen, cache, RW overlay) - Tls = 6, // thread-local storage blocks - Dma = 7, // DMA pools (drivers) - Framebuffer = 8, // GPU framebuffers - Stack = 9, // user stacks - InitTls = 10, // initial TLS block at spawn -} - -const NUM_CATEGORIES: usize = 11; - -impl Category { - fn name(self) -> &'static str { - match self { - Category::KernelHeap => "kernel-heap", - Category::DemandPage => "demand-page", - Category::Mmap => "mmap", - Category::SharedMemory => "shared-mem", - Category::Pipe => "pipe", - Category::Elf => "elf", - Category::Tls => "tls", - Category::Dma => "dma", - Category::Framebuffer => "framebuffer", - Category::Stack => "stack", - Category::InitTls => "init-tls", - } - } -} - -struct CategoryCounters { - alloc_pages: AtomicU64, - free_pages: AtomicU64, -} - -impl CategoryCounters { - const fn new() -> Self { - Self { - alloc_pages: AtomicU64::new(0), - free_pages: AtomicU64::new(0), - } - } -} - -static CATEGORY_STATS: [CategoryCounters; NUM_CATEGORIES] = - [const { CategoryCounters::new() }; NUM_CATEGORIES]; - -/// Snapshot of the last time `dump_stats` ran, for computing rates. -static LAST_DUMP_NANOS: AtomicU64 = AtomicU64::new(0); -static LAST_ALLOC: [AtomicU64; NUM_CATEGORIES] = [const { AtomicU64::new(0) }; NUM_CATEGORIES]; - -/// Log per-category page allocation stats to serial. -pub fn dump_stats() { - let now = crate::clock::nanos_since_boot(); - let prev = LAST_DUMP_NANOS.swap(now, Ordering::Relaxed); - let dt_secs = if prev == 0 { 0.0 } else { (now - prev) as f64 / 1_000_000_000.0 }; - - let (total, used) = stats(); - crate::log!("PMM: {}/{}MB used ({} pages free)", - used / (1024 * 1024), total / (1024 * 1024), - (total - used) / PAGE_2M); - - for i in 0..NUM_CATEGORIES { - let alloc = CATEGORY_STATS[i].alloc_pages.load(Ordering::Relaxed); - let free = CATEGORY_STATS[i].free_pages.load(Ordering::Relaxed); - let held = alloc.saturating_sub(free); - if alloc == 0 { continue; } - - let prev_alloc = LAST_ALLOC[i].swap(alloc, Ordering::Relaxed); - let rate = if dt_secs > 0.0 { - ((alloc - prev_alloc) as f64 / dt_secs) as u64 - } else { - 0 - }; - - // Safety: i < NUM_CATEGORIES which equals the number of Category variants - let cat = unsafe { core::mem::transmute::(i as u8) }; - crate::log!(" {:12} alloc={:6} free={:6} held={:6} ({}MB) rate={}/s", - cat.name(), alloc, free, held, held * 2, rate); - } -} - /// Owns one 2MB physical page; dropping it returns the page to the free list. pub struct PhysPage { phys: u64, // raw physical address, 2MB-aligned - category: u8, // Category as u8 } impl PhysPage { - /// Caller must ensure `phys` is a previously allocated, 2MB-aligned page; assigned to `KernelHeap`. + /// Caller must ensure `phys` is a previously allocated, 2MB-aligned page. pub(super) fn from_raw(phys: u64) -> Self { - Self { phys, category: Category::KernelHeap as u8 } + Self { phys } } /// Access this page through the kernel direct map. @@ -121,10 +29,6 @@ impl PhysPage { impl Drop for PhysPage { fn drop(&mut self) { - let cat = self.category as usize; - if cat < NUM_CATEGORIES { - CATEGORY_STATS[cat].free_pages.fetch_add(1, Ordering::Relaxed); - } free_page(self.phys); } } @@ -263,8 +167,8 @@ pub(super) fn init(entries: &[MemoryMapEntry], reserved: &[Region]) { } /// Allocate one 2MB physical page. -pub fn alloc_page(cat: Category) -> Option { - let page = claim(cat)?; +pub fn alloc_page() -> Option { + let page = claim()?; // SAFETY: `claim` just took the frame off the bitmap, so it is unaliased, and the direct map covers every address the bitmap can name. unsafe { core::ptr::write_bytes(page.direct_map().as_mut_ptr::(), 0, PAGE_2M as usize); @@ -273,7 +177,7 @@ pub fn alloc_page(cat: Category) -> Option { } /// One 2MB physical page holding what its last owner left in it. Only the kernel heap takes one as it is: the heap answers uninitialized memory, and `alloc_zeroed` writes its own zeros. Does not heap-allocate: the heap calls it when it is full. -pub(super) fn claim(cat: Category) -> Option { +pub(super) fn claim() -> Option { let mut bm = BITMAP.lock(); if bm.free_count == 0 { return None; } let start = bm.next_hint; @@ -285,15 +189,14 @@ pub(super) fn claim(cat: Category) -> Option { bm.next_hint = if idx + 1 < bm.page_count { idx + 1 } else { 0 }; let phys = bm.idx_to_phys(idx); drop(bm); - CATEGORY_STATS[cat as usize].alloc_pages.fetch_add(1, Ordering::Relaxed); - return Some(PhysPage { phys, category: cat as u8 }); + return Some(PhysPage { phys }); } } None } /// Allocate `count` physically contiguous 2MB pages. -pub fn alloc_contiguous(count: usize, cat: Category) -> Option> { +pub fn alloc_contiguous(count: usize) -> Option> { // `count` comes from userland, so a bogus 0 and a legitimate `mmap(0)` can't be told apart here — refuse, don't assert. if count == 0 { return None; } let mut bm = BITMAP.lock(); @@ -312,8 +215,6 @@ pub fn alloc_contiguous(count: usize, cat: Category) -> Option Option(), 0, PAGE_2M as usize, ); } - pages.push(PhysPage { phys, category: cat as u8 }); + pages.push(PhysPage { phys }); } return Some(pages); } diff --git a/kernel/src/object/shm.rs b/kernel/src/object/shm.rs index 581ce8fc13e..e19eda42b91 100644 --- a/kernel/src/object/shm.rs +++ b/kernel/src/object/shm.rs @@ -83,7 +83,7 @@ impl SharedMemObject { // `SYS_SHM_CREATE`'s length, straight from a register: the rounding // itself is the checked sum. let aligned = align_2m_checked(size).ok_or(SyscallError::InvalidArgument)?; - let pages = pmm::alloc_contiguous((aligned / PAGE_2M) as usize, pmm::Category::SharedMemory) + let pages = pmm::alloc_contiguous((aligned / PAGE_2M) as usize) .ok_or(SyscallError::ResourceExhausted)?; let phys = DirectMap::from_phys(pages[0].direct_map().phys()); Ok(Self::over(Region { diff --git a/kernel/src/pipe.rs b/kernel/src/pipe.rs index 565679d4af3..b0c8122a702 100644 --- a/kernel/src/pipe.rs +++ b/kernel/src/pipe.rs @@ -142,7 +142,7 @@ impl Pipe { /// Allocate the ring page if this is the first use; `None` on exhaustion, an error return rather than a panic since userland drives it. fn back(&mut self) -> Option<&mut Backing> { if self.backing.is_none() { - let page = pmm::alloc_page(pmm::Category::Pipe)?; + let page = pmm::alloc_page()?; // SAFETY: a fresh 2 MiB page this `Pipe` owns for as long as the `Ring` addresses it. let ring = unsafe { Ring::new(page.direct_map().as_mut_ptr(), PIPE_SIZE) }; self.backing = Some(Backing { page, ring }); diff --git a/kernel/src/process.rs b/kernel/src/process.rs index 8f7a9a9e3c3..78cfa1ded34 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -97,9 +97,9 @@ pub struct PageAlloc(Vec); impl PageAlloc { /// Allocate `size` bytes as contiguous 2MB pages. - pub fn new(size: usize, cat: crate::mm::pmm::Category) -> Option { + pub fn new(size: usize) -> Option { let count = size.div_ceil(PAGE_2M as usize); - Some(Self(crate::mm::pmm::alloc_contiguous(count, cat)?)) + Some(Self(crate::mm::pmm::alloc_contiguous(count)?)) } /// Kernel pointer to the start of the allocation (via direct map). @@ -1443,7 +1443,7 @@ pub fn handle_page_fault(fault_addr: u64, _error_code: u64) -> bool { let reloc_index = data.elf.reloc_index.clone(); let elf_base = data.elf.elf_base.raw(); - let page_alloc = match PageAlloc::new(page_2m as usize, crate::mm::pmm::Category::DemandPage) { + let page_alloc = match PageAlloc::new(page_2m as usize) { Some(a) => a, None => return false, }; diff --git a/kernel/src/sched/driver.rs b/kernel/src/sched/driver.rs index 7fa783030a6..d613be313d2 100644 --- a/kernel/src/sched/driver.rs +++ b/kernel/src/sched/driver.rs @@ -704,7 +704,6 @@ extern "C" fn idle_loop() -> ! { if crate::drivers::panic_console::probe_due() { panic!("metal-panic-probe: a fatal report over a desktop that owns the screen"); } - crate::scheduler::log_health(); crate::scheduler::reap_finished(); // `pass` below covers this too; here as well so a CPU that // halts immediately has still run every hook first. @@ -779,22 +778,6 @@ pub fn ready_len() -> usize { try_with_cpu(|cpu| cpu.ready_len()).unwrap_or(0) } -pub fn parked_len() -> usize { - try_with_cpu(|cpu| cpu.parked().count()).unwrap_or(0) -} - -/// Killed threads on this CPU that are unwinding or waiting to. -/// -/// The dump's fourth container — without it a dying task is invisible to `unheld = claimed − scheduled`. -pub fn dying_len() -> usize { - try_with_cpu(|cpu| cpu.dying_len()).unwrap_or(0) -} - -/// Threads on this CPU the machine's stop banded; no pick serves them again. -pub fn stopped_len() -> usize { - try_with_cpu(|cpu| cpu.stopped_len()).unwrap_or(0) -} - /// Every thread on this CPU the machine's stop banded. pub fn for_each_stopped(mut f: impl FnMut(TaskId)) -> bool { try_with_cpu(|cpu| { diff --git a/kernel/src/sched/idle_stack.rs b/kernel/src/sched/idle_stack.rs index 34365c56d74..3c0a41910b5 100644 --- a/kernel/src/sched/idle_stack.rs +++ b/kernel/src/sched/idle_stack.rs @@ -35,7 +35,7 @@ struct Arena { fn alloc_slot() -> u64 { let mut arena = ARENA.lock(); if arena.left < SLOT { - let page = crate::mm::pmm::alloc_page(crate::mm::pmm::Category::KernelHeap) + let page = crate::mm::pmm::alloc_page() .expect("idle stack: no physical page for one"); arena.next = page.direct_map().as_mut_ptr::() as u64; arena.left = crate::mm::PAGE_2M as usize; diff --git a/kernel/src/scheduler.rs b/kernel/src/scheduler.rs index fb95bf95a9b..b2b1e6affd4 100644 --- a/kernel/src/scheduler.rs +++ b/kernel/src/scheduler.rs @@ -22,7 +22,7 @@ use crate::sched::payload::{KShare, KernelLock, TaskHandle, ThreadSched}; use crate::sched::reap_gate::ReapGate; use crate::sched::futex; use crate::sync::Lock; -use crate::time::{Cadence, Deadline, Duration}; +use crate::time::Deadline; use crate::DirectMap; pub use crate::sched::driver::{ @@ -582,69 +582,3 @@ pub fn task_sched_state(sched: &ThreadSched) -> u8 { pub fn flush_current_stats(acct: &mut process::ProcessAccounting) { driver::with_current_acct(|a| crate::sched::payload::merge_accounting(a, acct)); } - -/// How often an idle CPU may report occupancy: not a deadline, so it never -/// wakes a CPU with nothing to run — turning it into one would be an audio -/// change. -const SNAPSHOT_INTERVAL: Cadence = Cadence::every( - Duration::from_secs(10), - "one clock read and one relaxed compare per idle trip, on a CPU already awake", -); - -/// When each CPU may next print its own line: per CPU, not global, so no -/// single CPU speaks for all of them. -static NEXT_HEALTH: [AtomicU64; MAX_CPUS] = [const { AtomicU64::new(0) }; MAX_CPUS]; - -/// How many times each CPU has passed through idle since boot. -static IDLE_TRIPS: [AtomicU64; MAX_CPUS] = [const { AtomicU64::new(0) }; MAX_CPUS]; - -/// A snapshot of this CPU's run queues, at most once per -/// [`SNAPSHOT_INTERVAL`], plus the machine's page pools on the same -/// cadence. Called from the idle loop on every trip; the cadence is wall -/// clock rather than per-trip because a CPU that declines to sleep loops at -/// memory speed. Not a heartbeat: a busy CPU prints nothing, so a gap here -/// is not evidence of a hang. -pub fn log_health() { - let now = crate::hw::now_ns(); - let cpu = percpu::cpu_id(); - let Some(next_health) = NEXT_HEALTH.get(cpu as usize) else { return }; - // Unconditional and every trip, unlike the print below. - let trips = IDLE_TRIPS - .get(cpu as usize) - .map_or(0, |t| t.fetch_add(1, Ordering::Relaxed) + 1); - if now >= next_health.load(Ordering::Relaxed) { - next_health.store(now + SNAPSHOT_INTERVAL.nanos(), Ordering::Relaxed); - let ready = driver::ready_len() + usize::from(percpu::current_tid().is_some()); - let parked = driver::parked_len(); - let dying = driver::dying_len(); - let stopped = driver::stopped_len(); - crate::log!( - "sched: cpu={} ready={} dying={} stopped={} parked={} current={:?} trips={}", - cpu, - ready, - dying, - stopped, - parked, - percpu::current_tid(), - trips, - ); - } - - static NEXT_PMM_DUMP: AtomicU64 = AtomicU64::new(0); - let next = NEXT_PMM_DUMP.load(Ordering::Relaxed); - if next == 0 { - NEXT_PMM_DUMP.store(now + SNAPSHOT_INTERVAL.nanos(), Ordering::Relaxed); - } else if now >= next - && NEXT_PMM_DUMP - .compare_exchange( - next, - now + SNAPSHOT_INTERVAL.nanos(), - Ordering::Relaxed, - Ordering::Relaxed, - ) - .is_ok() - { - crate::mm::pmm::dump_stats(); - } -} - diff --git a/kernel/src/syscall/vm.rs b/kernel/src/syscall/vm.rs index 1a414c8ebc8..c6450755b12 100644 --- a/kernel/src/syscall/vm.rs +++ b/kernel/src/syscall/vm.rs @@ -76,7 +76,7 @@ pub(super) fn sys_mmap(req_addr: u64, size: u64, prot: MmapProt, flags: MmapFlag // fault: `handle_page_fault` refuses to fill a `Mapped` region. None } else { - match process::PageAlloc::new(aligned, crate::mm::pmm::Category::Mmap) { + match process::PageAlloc::new(aligned) { Some(pages) => Some(pages), None => return SyscallError::ResourceExhausted.to_u64(), } @@ -426,7 +426,7 @@ fn tls_alloc_block(module_id: u64) -> Result { let tls_vaddr = match existing { Some(vaddr) => vaddr, None => { - let page_alloc = process::PageAlloc::new(tls_memsz.max(1), crate::mm::pmm::Category::Tls) + let page_alloc = process::PageAlloc::new(tls_memsz.max(1)) .ok_or(SyscallError::ResourceExhausted)?; // SAFETY: `page_alloc` is a fresh, unaliased allocation of at // least `tls_memsz.max(1)` bytes; `template.size()` comes from the diff --git a/tests/testcases/system.toml b/tests/testcases/system.toml index 63247e5cad0..ba7366b2ffd 100644 --- a/tests/testcases/system.toml +++ b/tests/testcases/system.toml @@ -6,12 +6,14 @@ start = ["logkeeper", "diskserver", "fileserver", "soundserver", "test-runner"] # image does. The kernel keeps the record ring and writes no file at all, so a # boot config without `logkeeper` is a boot whose `/log` is empty — # `every_boot_config_runs_logkeeper` is what refuses one. -# It claims no device and serves no port: its row's authority is `logread`, -# which is `Rights::LOG | Rights::WAIT` on a `SysCap` duplicate, and the supervisor hands -# it every program's output beside that. +# It claims no device: its row's authority is `logread`, which is +# `Rights::LOG | Rights::WAIT` on a `SysCap` duplicate, and the supervisor hands +# it every program's output beside that. `log` is the port it hands a reader +# the log on. [programs.logkeeper] service = true syscap = ["logread"] +serves = ["log"] [programs.soundserver] service = true @@ -38,8 +40,10 @@ syscap = ["rt"] # without it would make that arm vacuous rather than red. # `counters` and `trace` because `counters_read` reads every counter there is, # and narrows each away to prove its refusal. +# `log` because `counters_metal` measures its idle second only once the log +# holds its own line, read back off logkeeper. [programs.test-runner] -receives = ["soundserver", "power"] +receives = ["soundserver", "power", "log"] syscap = ["device", "dup", "logread", "power", "roster", "counters", "trace"] [programs.toybox] diff --git a/tests/toyos-rust-tests/Cargo.lock b/tests/toyos-rust-tests/Cargo.lock index 538a0d85107..e1d6d0cabd3 100644 --- a/tests/toyos-rust-tests/Cargo.lock +++ b/tests/toyos-rust-tests/Cargo.lock @@ -280,6 +280,14 @@ version = "0.4.33" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0ceec5bc11778974d1bcb055b18002eba7f4b3518b6a0081b3af5f21666da9ad" +[[package]] +name = "logkeeper-api" +version = "0.1.0" +dependencies = [ + "toyos", + "toyos-logstream", +] + [[package]] name = "mach2" version = "0.6.0" @@ -696,6 +704,13 @@ dependencies = [ name = "toyos-keymap" version = "0.1.0" +[[package]] +name = "toyos-logstream" +version = "0.1.0" +dependencies = [ + "toyos-abi", +] + [[package]] name = "toyos-rust-tests" version = "0.1.0" @@ -703,10 +718,12 @@ dependencies = [ "cpal", "inspect", "libloading", + "logkeeper-api", "memmap2", "toyos", "toyos-abi", "toyos-inspect", + "toyos-logstream", "toyos-tco", "toyos-trace", "toyos-window", diff --git a/tests/toyos-rust-tests/Cargo.toml b/tests/toyos-rust-tests/Cargo.toml index 5ef62700dab..148f0ae471f 100644 --- a/tests/toyos-rust-tests/Cargo.toml +++ b/tests/toyos-rust-tests/Cargo.toml @@ -11,6 +11,10 @@ toyos = { path = "../../toyos" } toyos-window = { path = "../../userland/toyos-window" } toyos-tco = { path = "../../toyos-tco" } toyos-inspect = { path = "../../toyos-inspect" } +# The log as logkeeper serves it, and the asking for it, for `counters_metal`'s +# wait on the log being quiet. +toyos-logstream = { path = "../../toyos-logstream" } +logkeeper-api = { path = "../../userland/logkeeper-api" } # The diary's decoder, for `trace_read` and `trace_flood`. toyos-trace = { path = "../../toyos-trace" } # The reader's asker, for `hda_client_stall`. diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index 757e1845b3e..4d023c89835 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -6,7 +6,13 @@ //! Three reads: `idle0` and `idle1` either side of [`IDLE`], and `spin` after //! [`SPIN`] iterations on a thread per CPU begun at `idle1`. Each read's //! records follow a line with the clock after it and what the read took, a -//! whole round each, none joining another's. +//! whole round each, none joining another's. **Nothing is printed until all +//! three are taken**: a printed line reaches the stick within the second, +//! through the `/log` fileserver on that fileserver's CPU. +//! +//! **`idle0` waits for the log to be quiet** ([`settle`]): a job starts while +//! logkeeper is still writing the boot so far and the job's own launch lines +//! to the stick, and a second begun then measures that write. //! //! **Then `loaded`: how late the round's kick reaches each CPU** while a thread //! per CPU spawns a program that exits at once, which is the load Linux's @@ -22,9 +28,11 @@ use std::sync::atomic::{AtomicBool, Ordering}; use std::time::{Duration, Instant}; use toyos::endow::{Endowments, SYSCAP_LABEL}; +use toyos::poller::{Poller, READABLE}; use toyos::syscap::SysCap; use toyos_abi::counters::{Counter, RawRecord, Record}; -use toyos_abi::syscall; +use toyos_abi::syscall::{self, SyscallError}; +use toyos_logstream::{program_line, Lines}; /// The idle span: long enough that a CPU's busy fraction is its idle one and /// not the reads'. @@ -40,6 +48,10 @@ const SPIN: u64 = 4_000_000_000; /// (`toyos_tco::JOB_BOUND_MS`) the reads before it leave. const LOADED: Duration = Duration::from_secs(20); +/// How long [`settle`] waits for each of its lines: two of logkeeper's rounds +/// at its write budget (`userland/logkeeper/src/policy.rs`, 5 s). +const SETTLE_BOUND: Duration = Duration::from_secs(10); + /// What this binary's own children are asked to do: exit at once. const EXIT_AT_ONCE: &str = "exit-at-once"; @@ -118,26 +130,77 @@ fn loaded(cap: &SysCap) { } } -fn read(cap: &SysCap, phase: &str) { +/// One read: the clock after it, what it took, and every CPU's records. +struct Read { + at: u64, + took: Duration, + records: Vec, +} + +fn read(cap: &SysCap) -> Read { let mut raw = vec![RawRecord::EMPTY; syscall::cpu_count() as usize]; let asked = Instant::now(); let n = cap.counters(&mut raw).expect("the estate's capability reads the counters"); let took = asked.elapsed(); - println!("counters_metal {phase}: at {} ns, the read took {} ns", toyos_abi::clock::nanos_since_boot(), took.as_nanos()); - let records: Vec = raw[..n].iter().map(|r| Record::decode(r).expect("a record that decodes")).collect(); - for (path, value) in toyos_inspect::kernel::render(&records).expect("one record per cpu") { + let at = toyos_abi::clock::nanos_since_boot(); + Read { at, took, records: raw[..n].iter().map(|r| Record::decode(r).expect("a record that decodes")).collect() } +} + +fn print(phase: &str, read: &Read) { + println!("counters_metal {phase}: at {} ns, the read took {} ns", read.at, read.took.as_nanos()); + for (path, value) in toyos_inspect::kernel::render(&read.records).expect("one record per cpu") { println!("counters_metal {phase}: {}", toyos_inspect::line(&path, &value)); } } +/// Return once logkeeper has written, and made durable, everything stamped +/// before this call. +/// +/// A reader of the `log` port is handed each round only after it is on the +/// stick, so this prints a line and reads the log until that line comes back. +/// **Twice**: the round that writes the first may itself put a record in the +/// log — the stick's first sync is one — and the second writes it. The +/// `counters` row reds any line stamped inside the idle second. +fn settle() { + let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; + let poller = Poller::new(1); + let mut lines = Lines::new(); + let mut chunk = vec![0u8; 64 * 1024]; + for round in ["first", "second"] { + let said = format!("counters_metal settle: the log holds this {round} line"); + println!("{said}"); + let by = Instant::now() + SETTLE_BOUND; + let mut held = false; + while !held { + match pipe.read_nonblock(&mut chunk) { + Ok(0) => panic!("logkeeper closed the log before it held {said:?}"), + Ok(n) => lines.push(&chunk[..n], |line, _| { + let line = std::str::from_utf8(line) + .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); + held |= program_line(line).is_some_and(|line| line.text == said); + }), + Err(SyscallError::WouldBlock) => { + let left = by.checked_duration_since(Instant::now()).unwrap_or_else(|| { + panic!("the log did not hold {said:?} within {SETTLE_BOUND:?}") + }); + poller.watch(&pipe, READABLE, 0); + poller.wait(1, left.as_nanos() as u64, |_| {}); + } + Err(e) => panic!("the log's pipe refused a read: {e:?}"), + } + } + } +} + fn main() { if std::env::args().nth(1).as_deref() == Some(EXIT_AT_ONCE) { return; } let cap: SysCap = Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability"); - read(&cap, "idle0"); + settle(); + let idle0 = read(&cap); std::thread::sleep(IDLE); - read(&cap, "idle1"); + let idle1 = read(&cap); std::thread::scope(|s| { for _ in 0..syscall::cpu_count() { s.spawn(|| { @@ -148,6 +211,9 @@ fn main() { }); } }); - read(&cap, "spin"); + let spin = read(&cap); + for (phase, read) in [("idle0", &idle0), ("idle1", &idle1), ("spin", &spin)] { + print(phase, read); + } loaded(&cap); } diff --git a/tests/toyos.rs b/tests/toyos.rs index 30ee51f7380..738534818ce 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -3485,7 +3485,10 @@ const SMI_SPAN_NS: u64 = 4_444_000_000; /// reads` line names, and none stale; every CPU's performance request /// declared at boot, `pm_enable=1`, the request Linux makes on this machine /// (`tests/t14-linux/hwp-request.txt`), and its power envelope in every read -/// the one its `control_regs:` line holds. From `idle0` to `spin`, at least +/// the one its `control_regs:` line holds. No line, the kernel's or a +/// program's, is stamped in a millisecond from `idle0`'s to `idle1`'s, either +/// edge's included because a line stamped in it may follow the read: the +/// second is the idle machine's. From `idle0` to `spin`, at least /// [`SMI_SPAN_NS`] apart, every CPU's SMI count rose alike and by two or more: /// the firmware's legacy mode, the positive control ACPI stage 1's flatness /// is read against, and the row that stage changes. Across the spin every @@ -3496,7 +3499,8 @@ const SMI_SPAN_NS: u64 = 4_444_000_000; /// same span of load (`tests/t14-linux/turbostat-loaded.txt`). /// /// Read and not held, beside Linux's turbostat: each CPU's idle busy -/// fraction, and what one round cost its reader; and beside Linux's loaded +/// fraction, which an SMI in the idle second raises on every CPU alike by the +/// time it held them, and what one round cost its reader; and beside Linux's loaded /// timer reading (`issues/toyos-beats-linuxs-latency-on-the-t14.md`), /// how late each CPU's kick handler ran under the `loaded` phase. fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { @@ -3533,6 +3537,19 @@ fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { let (idle0, at0) = phase("idle0")?; let (idle1, at1) = phase("idle1")?; let (spin, at2) = phase("spin")?; + let (from_ms, to_ms) = (at0 / 1_000_000, at1 / 1_000_000); + let inside: Vec<&str> = log + .text() + .lines() + .filter(|line| { + toyos_logstream::record_ms(line) + .or_else(|| toyos_logstream::program_ms(line)) + .is_some_and(|ms| (from_ms..=to_ms).contains(&ms)) + }) + .collect(); + if !inside.is_empty() { + return Err(format!("the idle second {at0}..{at1} ns holds lines: {inside:?}")); + } let linux_request = u64::from_str_radix(include_str!("t14-linux/hwp-request.txt").trim().trim_start_matches("0x"), 16) .map_err(|e| format!("t14-linux/hwp-request.txt: {e}"))?; let bsp = kernel.must_say("percpu: BSP cpu_id=0 lapic_id=")?; @@ -3620,9 +3637,10 @@ fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { } let spinning: Vec = (0..cpus).map(|cpu| tsc_mhz * ratio(idle1, spin, cpu, "aperf", "mperf")).collect(); eprintln!( - " [counters] {cpus} cpus, SMI +{} each over {} ms; TSC {tsc_mhz:.0} MHz", + " [counters] {cpus} cpus, SMI +{} each over {} ms, +{} in the idle second; TSC {tsc_mhz:.0} MHz", smis[0], - (at2 - at0) / 1_000_000 + (at2 - at0) / 1_000_000, + delta(idle0, idle1, 0, "smi") ); for (cpu, busy) in busy.iter().enumerate() { eprintln!( diff --git a/toyos-logstream/src/lib.rs b/toyos-logstream/src/lib.rs index 7cc6b919f9f..ccde063b6df 100644 --- a/toyos-logstream/src/lib.rs +++ b/toyos-logstream/src/lib.rs @@ -306,6 +306,15 @@ pub fn record_ms(line: &str) -> Option { millis(record_head(line)?.0.split(' ').next()?) } +/// The milliseconds since boot a program's line carries ([`ProgramLine`]), or +/// `None` for any other line. +pub fn program_ms(line: &str) -> Option { + match shown(line)?.head? { + Head { source: Source::Program(_), stamp } => millis(stamp.split(' ').next()?), + Head { source: Source::Kernel, .. } => None, + } +} + /// Whose a line on a screen is. #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub enum Source<'a> { @@ -682,6 +691,26 @@ mod tests { assert_eq!(record_ms(""), None); } + /// Every head [`ProgramLine`] writes reads back to the time it carries, and + /// no text after the head answers for it. + #[test] + fn a_program_lines_time_is_read_inside_its_head_and_nowhere_else() { + let tag = Tag::new("test-runner").expect("a tag"); + for stamp in ["", "2026-09-24 10:00:00", "---------- --------"] { + for severity in [Severity::Info, Severity::Warn, Severity::Error, Severity::Alert] { + for (tid, pid) in [(0, None), (3, None), (0, Some(9)), (3, Some(9))] { + let line = + format!("{}", ProgramLine { stamp, at_ns: 1_500_999_999, severity, tid, pid, tag, text: b"9.000" }); + assert_eq!(program_ms(&line), Some(1_500), "{line:?}"); + } + } + } + assert_eq!(program_ms("[2026-09-07 22:57:46 3.109 cpu1] exit: a pid=7"), None); + assert_eq!(program_ms("{2026-09-24 10:00:00 netstack} 1.000"), None); + assert_eq!(program_ms(" its second line"), None); + assert_eq!(program_ms(""), None); + } + /// What a terminal shows of a line, with its colours taken out. fn plain(shown: Shown<'_>) -> String { let painted = format!("{shown}"); diff --git a/userland/Cargo.lock b/userland/Cargo.lock index a597548e4e1..13290f99f27 100644 --- a/userland/Cargo.lock +++ b/userland/Cargo.lock @@ -542,6 +542,7 @@ dependencies = [ name = "console" version = "0.1.0" dependencies = [ + "logkeeper-api", "terminal", "toyos", "toyos-abi", @@ -1964,6 +1965,14 @@ dependencies = [ "toyos-wallclock", ] +[[package]] +name = "logkeeper-api" +version = "0.1.0" +dependencies = [ + "toyos", + "toyos-logstream", +] + [[package]] name = "mach2" version = "0.6.0" diff --git a/userland/Cargo.toml b/userland/Cargo.toml index 55a41520e05..f783bfa2f26 100644 --- a/userland/Cargo.toml +++ b/userland/Cargo.toml @@ -16,6 +16,7 @@ members = [ "inspect", "kernelprobe", "logkeeper", + "logkeeper-api", "metalprobe", "netstack", "netstack/mdns", diff --git a/userland/console/Cargo.toml b/userland/console/Cargo.toml index 1d79c14de09..9413a1a4677 100644 --- a/userland/console/Cargo.toml +++ b/userland/console/Cargo.toml @@ -12,6 +12,7 @@ toyos-abi = { path = "../../toyos-abi" } toyos-font = { path = "../toyos-font" } toyos-window = { path = "../toyos-window" } toyos-logstream = { path = "../../toyos-logstream" } +logkeeper-api = { path = "../logkeeper-api" } [package.metadata.toyos.host] exempt.owns = "ToyOS's framebuffer, keyboard and mouse, claimed from the kernel, on which it runs the shell" diff --git a/userland/console/src/main.rs b/userland/console/src/main.rs index 39351eeaf22..e6a65cbf49b 100644 --- a/userland/console/src/main.rs +++ b/userland/console/src/main.rs @@ -37,7 +37,7 @@ use toyos::port::{self, Connector}; use toyos::surface::{self, Delivery, Host, Notice}; use toyos::{FramebufferDev, Keyboard, Pipe}; use toyos_abi::syscall::{DeviceType, SyscallError}; -use toyos_logstream::{Lines, Showing, Source, READ, SERVED, SERVICE}; +use toyos_logstream::{Lines, Showing, Source}; use window::Screen; const FONT: &str = "/system/share/fonts/JetBrainsMono-Regular-8x16.font"; @@ -81,18 +81,7 @@ impl Log { /// Ask `logkeeper`: one request, and a blocking read of its one answer. fn subscribe() -> Result { let asked_ms = toyos_abi::clock::nanos_since_boot() / 1_000_000; - let conn = endow::service(SERVICE).map_err(|e| format!("no `{SERVICE}` service: {e:?}"))?; - conn.signal(READ).map_err(|e| format!("logkeeper would not take the request: {e:?}"))?; - let header = conn.recv_header().map_err(|e| format!("logkeeper did not answer: {e:?}"))?; - if header.msg_type != SERVED { - return Err(format!("logkeeper answered frame type {}", header.msg_type)); - } - let handed: u64 = - conn.recv_payload(&header).map_err(|e| format!("logkeeper's answer is short: {e:?}"))?; - let [raw] = conn.recv_handles_exact::<1>().ok_or("logkeeper's answer carried no pipe")?; - // SAFETY: the kernel moved this handle into this table with the frame - // that names it, and nothing else answers for it. - let pipe = unsafe { Pipe::from_raw(raw) }; + let logkeeper_api::Served { pipe, boot_so_far: handed } = logkeeper_api::read()?; Ok(Self { pipe, lines: Lines::new(), diff --git a/userland/logkeeper-api/Cargo.toml b/userland/logkeeper-api/Cargo.toml new file mode 100644 index 00000000000..05e9d0daa5f --- /dev/null +++ b/userland/logkeeper-api/Cargo.toml @@ -0,0 +1,13 @@ +[package] +name = "logkeeper-api" +description = "Asking logkeeper for this boot's log on this machine: the request its `log` port answers with a pipe, and the decoding of that answer." +version = "0.1.0" +edition = "2021" +license = "MIT OR Apache-2.0" + +[lib] +doctest = false + +[dependencies] +toyos = { path = "../../toyos" } +toyos-logstream = { path = "../../toyos-logstream" } diff --git a/userland/logkeeper-api/src/lib.rs b/userland/logkeeper-api/src/lib.rs new file mode 100644 index 00000000000..dc32932d5fe --- /dev/null +++ b/userland/logkeeper-api/src/lib.rs @@ -0,0 +1,32 @@ +//! Asking `logkeeper` for this boot's log on this machine: one [`READ`] on +//! its [`SERVICE`] port, answered by one [`SERVED`] frame carrying how many +//! bytes are the boot so far and the read end of a pipe the log is written +//! into, from its first line. + +use toyos::endow; +use toyos::Pipe; +use toyos_logstream::{READ, SERVED, SERVICE}; + +/// `logkeeper`'s answer. +pub struct Served { + pub pipe: Pipe, + /// How many of the pipe's bytes are the boot so far. + pub boot_so_far: u64, +} + +/// Ask: one request, and a blocking read of its one answer. +pub fn read() -> Result { + let conn = endow::service(SERVICE).map_err(|e| format!("no `{SERVICE}` service: {e:?}"))?; + conn.signal(READ).map_err(|e| format!("logkeeper would not take the request: {e:?}"))?; + let header = conn.recv_header().map_err(|e| format!("logkeeper did not answer: {e:?}"))?; + if header.msg_type != SERVED { + return Err(format!("logkeeper answered frame type {}", header.msg_type)); + } + let boot_so_far: u64 = + conn.recv_payload(&header).map_err(|e| format!("logkeeper's answer is short: {e:?}"))?; + let [raw] = conn.recv_handles_exact::<1>().ok_or("logkeeper's answer carried no pipe")?; + // SAFETY: the kernel moved this handle into this table with the frame + // that names it, and nothing else answers for it. + let pipe = unsafe { Pipe::from_raw(raw) }; + Ok(Served { pipe, boot_so_far }) +}