diff --git a/Cargo.lock b/Cargo.lock index a22e5bcdf29..dc6231b92d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2752,8 +2752,10 @@ name = "osbench" version = "0.1.0" dependencies = [ "libc", + "miniz_oxide", "toyos", "toyos-abi", + "toyos-trace", ] [[package]] diff --git a/build/clippy.rs b/build/clippy.rs index 485c02cad92..e79c6880fcd 100644 --- a/build/clippy.rs +++ b/build/clippy.rs @@ -217,7 +217,11 @@ const SHAPES: &[Shape] = &[ }, // osbench's Linux half, which no image builds: a check, so nothing links. Shape { - before: &["-p", "osbench", "--target", OSBENCH_LINUX], + before: &["-p", "osbench", "--target", OSBENCH_LINUX[0]], + after: &["$ADOPTED", "-D", "warnings"], + }, + Shape { + before: &["-p", "osbench", "--target", OSBENCH_LINUX[1]], after: &["$ADOPTED", "-D", "warnings"], }, // Its own target directory: cargo keeps one check of a unit, so a unit @@ -229,14 +233,21 @@ const SHAPES: &[Shape] = &[ }, ]; -/// The Linux target `tests/guest/osbench` is built for beside ToyOS. -const OSBENCH_LINUX: &str = "x86_64-unknown-linux-musl"; +/// The Linux targets `tests/guest/osbench` is built for beside ToyOS, one +/// per architecture. +const OSBENCH_LINUX: [&str; 2] = ["x86_64-unknown-linux-musl", "aarch64-unknown-linux-musl"]; /// The targets the shapes lint against, which `rustup target add` installs: /// every architecture's bare targets for the kernel and bootloader, and -/// osbench's Linux one. -pub const TARGETS: [&str; 5] = - [Arch::X86_64.kernel(), Arch::X86_64.loader(), Arch::Aarch64.kernel(), Arch::Aarch64.loader(), OSBENCH_LINUX]; +/// osbench's Linux ones. +pub const TARGETS: [&str; 6] = [ + Arch::X86_64.kernel(), + Arch::X86_64.loader(), + Arch::Aarch64.kernel(), + Arch::Aarch64.loader(), + OSBENCH_LINUX[0], + OSBENCH_LINUX[1], +]; impl Shape { /// The command as a reader writes it, its tokens unexpanded. diff --git a/issues/a-64-mib-write-to-the-in-memory-data-volume-runs-its-file-server-out-of-memory.md b/issues/a-64-mib-write-to-the-in-memory-data-volume-runs-its-file-server-out-of-memory.md new file mode 100644 index 00000000000..d7cc2276bf4 --- /dev/null +++ b/issues/a-64-mib-write-to-the-in-memory-data-volume-runs-its-file-server-out-of-memory.md @@ -0,0 +1,50 @@ +--- +status: open +kind: defect +opened: 2026-10-21 +--- + +# A 64 MiB write to the in-memory DATA volume runs its file server out of memory + +On a boot with no DATA partition the DATA file server formats a volume in +memory (`system/fileserver/src/main.rs`, `RAM_BLOCKS`: 1 GiB, sparse). Writing +one 64 MiB file to it through std (`osbench files`, `fs.served.seq_write.4096`: +`File::create`, then 16,384 writes of 4 KiB) ends the server: + +``` +fileserver error] memory allocation of 4096 bytes failed +cpu0 kernel] exit: fileserver pid=4 code=134 cpu=11326ms peak=3724MB allocs=1863 ... 63=1864 ... +supervisor] supervisor: fileserver data (pid 4) ended; started again as pid 11 +``` + +QEMU TCG, 4 vCPUs, 4 GiB of memory, the benchcase image (`tests/images/benchcase.toml`) +built from `wt/toyos-bench2`. Before it, the same process had served a 16 MiB +file, 2,000 4 KiB writes into it and a few thousand small creates and stats. +The restarted server died the same way within its first 88 requests of the +1 MiB-call variant of the same write (`peak=3724MB`). The 1 GiB volume and a +cache bounded for clean blocks account for at most a little over 1 GiB; the +server's heap reached every byte the machine had. + +The growth is not isolated. The server's own allocations per write are a +block (`cache.write` of a dirty block, `data.rs`'s `write`) and an allocation +in the volume's metadata per page grown (`resolve_or_alloc_block`); a +metadata update that writes a whole btree node through the unbounded dirty +side of the cache per page would come to gigabytes for 16,384 pages, but that +is an inference from the code, not a measurement. + +On metal the server survived: all six osbench boots of round 2's +`e5573b7fe` (three each on the T14 and the AMD bench, both with more memory +than the 4 GiB guest) wrote the file and exited 0. One did not do it cleanly: +on the T14's first boot a `fs.served.seq_write.1048576` round of the same +write ran under 1 MB/s (`min=0`), and `files` took 80 s against the other +boots' 13 s, so the same write stalls on metal even where it completes. + +The server also refuses nothing on the way: every request answered until the +allocator aborted the process, and the client saw `the file server is gone`. + +**Exit**: the server's memory for a 64 MiB file written to the in-memory volume +is bounded by the file's size plus a stated overhead, shown by the same write +under QEMU with its peak in the kernel's exit record; or the server refuses +the write that would exceed what it may hold, by name. + +Owner: the file server (`system/fileserver/`). diff --git a/issues/osbench-times-cpus-leaving-idle-and-not-their-settled-clock.md b/issues/osbench-times-cpus-leaving-idle-and-not-their-settled-clock.md index 4c3aab75076..1bcde5520b8 100644 --- a/issues/osbench-times-cpus-leaving-idle-and-not-their-settled-clock.md +++ b/issues/osbench-times-cpus-leaving-idle-and-not-their-settled-clock.md @@ -20,7 +20,18 @@ across ToyOS's groups. Under all-CPU load the two run one clock: 2.389 M and is therefore no normalisation: the memory bandwidths, equal raw, come out a quarter apart. -**Exit**: each benchmark runs after a steady-state warm-up of the CPUs it -uses and prints the chunk time measured beside it, and a T14 run on each -system shows `cpu.chunk` agreeing with the all-CPU rate per CPU within the -run-to-run spread. +`cpu.chunk`'s loop compiles to the same 3,125 dependent multiply-adds on +both builds (`llvm-objdump` of `chunk_rate` in each), so its ratio is a +clock ratio: at the four cycles a step takes, 10.5 µs is about 1.2 GHz and +3.3 µs about 3.8 GHz, an inference from the instruction latencies and not a +counter reading. + +Since round 2 every benchmark but the wake and fairness groups' (whose CPUs +idle or are all busy by design) runs after `clock::settle`, which spins the +measuring CPU until three probes of a dependent `add` chain agree within 1%, +and every result line prints that clock as `mhz_settled` and the clock just +after as `mhz`; each group also prints `cpu.clock`, 200 probes from idle. + +**Exit**: a T14 run on each system shows `mhz_settled` near the all-CPU rate +per CPU within the run-to-run spread, or names the benchmark whose CPU did +not settle. diff --git a/tests/common/metal.rs b/tests/common/metal.rs index 3be402e94ed..f314fd00463 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -61,6 +61,11 @@ pub struct Arm { /// arms that name different ones. The members riding the boot run behind /// it: it is a row's job, and a row's jobs have the machine first. pub last: Option<&'static str>, + /// What this arm's jobs add to their boot's list bound past + /// [`toyos_tco::JOB_BOUND_MS`], in milliseconds: zero for a row whose jobs + /// fit the bound every boot has, and a measurement's own span for one that + /// runs longer on purpose. Two arms on one boot add both. + pub adds_ms: u64, } /// The ordinary arm: one boot, and the fields a caller must still say. @@ -74,7 +79,7 @@ pub const fn once( params: &'static [&'static str], jobs: &'static [&'static str], ) -> Arm { - Arm { boot, config, params, jobs, features: &[], last: None } + Arm { boot, config, params, jobs, features: &[], last: None, adds_ms: 0 } } /// One boot carrying members that are **discovered rather than registered**. @@ -557,8 +562,8 @@ pub struct Batch { features: &'static [&'static str], /// What the runner spawns, in order. pub jobs: Vec, - /// What the members riding it add to the bound of its list. - members_ms: u64, + /// What its arms and the members riding it add to the bound of its list. + adds_ms: u64, last: Option<&'static str>, files: Vec<(String, Vec)>, links: Vec<(String, String)>, @@ -575,7 +580,7 @@ impl Batch { /// The bound the runner gives this boot's whole list, in milliseconds. pub fn bound_ms(&self) -> u64 { - toyos_tco::list_bound_ms(self.members_ms) + toyos_tco::list_bound_ms(self.adds_ms) } /// The bound the kernel gives this whole boot, in milliseconds. @@ -608,7 +613,7 @@ fn ride<'a>( params: params.to_vec(), features, jobs: Vec::new(), - members_ms: 0, + adds_ms: 0, last: None, files: Vec::new(), links: Vec::new(), @@ -651,6 +656,7 @@ pub fn batches( for arm in *arms { let batch = ride(&mut out, name, arm.boot, arm.config, arm.params, arm.features)?; batch.add(arm.jobs.iter().map(|j| (*j).to_string())); + batch.adds_ms += arm.adds_ms; match (batch.last, arm.last) { (Some(was), Some(now)) if was != now => { return Err(format!( @@ -678,7 +684,7 @@ pub fn batches( let who = format!("the shared boot {:?}", boot.boot); let batch = ride(&mut out, &who, &boot.boot, boot.config, boot.params, boot.features)?; batch.add(boot.members.iter().map(|member| member.job.clone())); - batch.members_ms += boot.members_ms(); + batch.adds_ms += boot.members_ms(); batch.files.extend(boot.files.iter().cloned()); batch.links.extend(boot.links.iter().cloned()); } diff --git a/tests/guest/osbench/Cargo.toml b/tests/guest/osbench/Cargo.toml index b44ddf9d588..d8a915bae63 100644 --- a/tests/guest/osbench/Cargo.toml +++ b/tests/guest/osbench/Cargo.toml @@ -1,13 +1,20 @@ [package] name = "osbench" -description = "Scheduler and system benchmarks run unchanged on ToyOS and on Linux, so the two can be compared on one machine: one result line per measured distribution." +description = "System benchmarks run unchanged on ToyOS and on Linux, so the two can be compared on one machine: one result line per measured distribution." version = "0.1.0" edition = "2021" license = "MIT OR Apache-2.0" +[dependencies] +# The work group's compression, pure Rust and the same code on both systems. +miniz_oxide = "0.9" + [target.'cfg(target_os = "toyos")'.dependencies] toyos-abi = { path = "../../../sdk/abi" } +# Native IPC (ports, connections, endowments) and the observation rights the +# tail group reads the diary, the counters and the roster with. toyos = { path = "../../../sdk/toyos" } +toyos-trace = { path = "../../../lib/trace" } [target.'cfg(target_os = "linux")'.dependencies] libc = "0.2" diff --git a/tests/guest/osbench/src/arch/aarch64.rs b/tests/guest/osbench/src/arch/aarch64.rs new file mode 100644 index 00000000000..57680a306ba --- /dev/null +++ b/tests/guest/osbench/src/arch/aarch64.rs @@ -0,0 +1,43 @@ +//! What osbench needs written for AArch64 in particular, on Linux: a chain of +//! dependent adds to time the clock with, and the bytes of a program that +//! exits. ToyOS on AArch64 is refused by the selector. + +/// `turns` turns of 100 dependent register adds, each waiting on the one +/// before it. Inline assembly, so the chain is the one written whatever the +/// optimizer does. +pub fn add_chain(turns: u64) { + let (mut x, mut n) = (std::hint::black_box(0u64), turns); + // SAFETY: arithmetic on two registers this block owns. + unsafe { + std::arch::asm!( + "2:", + ".rept 100", + "add {x}, {x}, #1", + ".endr", + "subs {n}, {n}, #1", + "b.ne 2b", + x = inout(reg) x, + n = inout(reg) n, + options(nomem, nostack), + ); + } + std::hint::black_box((x, n)); +} + +/// Adds per turn of [`add_chain`]. +pub const ADDS_PER_TURN: u64 = 100; + +/// The ELF machine a generated program is for (`EM_AARCH64`). +pub const ELF_MACHINE: u16 = 183; + +/// What a generated program runs, position-independent: `exit_group(0)` +/// (AArch64's syscall 94, the number in X8 and the code in X0), then a +/// permanently undefined instruction that is never reached. +pub const EXIT_CODE: [u8; 16] = [ + 0xc8, 0x0b, 0x80, 0xd2, // movz x8, #94 (exit_group) + 0x00, 0x00, 0x80, 0xd2, // movz x0, #0 + 0x01, 0x00, 0x00, 0xd4, // svc #0 + 0x00, 0x00, 0x00, 0x00, // udf #0 +]; + +const _: () = assert!(libc::SYS_exit_group == 94); diff --git a/tests/guest/osbench/src/arch/mod.rs b/tests/guest/osbench/src/arch/mod.rs index a0a58bef77a..736d5d5d97c 100644 --- a/tests/guest/osbench/src/arch/mod.rs +++ b/tests/guest/osbench/src/arch/mod.rs @@ -1,13 +1,19 @@ -//! What ToyOS's half of `sys` names CPUs by: the architecture's own reading of -//! the CPU a thread runs on and of the cores CPUs share. +//! What osbench writes for one architecture: the clock's add chain and a +//! generated program on both systems, and on ToyOS, which has no call that +//! says, the CPU a thread runs on and the cores CPUs share. #[cfg(target_arch = "x86_64")] mod x86_64; #[cfg(target_arch = "x86_64")] -pub use x86_64::{core_of, cpu_model, current_cpu, threads_per_core}; +pub use x86_64::*; -#[cfg(not(target_arch = "x86_64"))] +#[cfg(all(target_arch = "aarch64", target_os = "linux"))] +mod aarch64; +#[cfg(all(target_arch = "aarch64", target_os = "linux"))] +pub use aarch64::*; + +#[cfg(not(any(target_arch = "x86_64", all(target_arch = "aarch64", target_os = "linux"))))] compile_error!( - "osbench names a ToyOS CPU by its x86-64 APIC ID, and has no AArch64 equivalent: \ + "osbench names a ToyOS CPU by its x86-64 APIC ID, which AArch64 has no EL0 equivalent of: \ issues/osbench-builds-for-no-aarch64-toyos.md" ); diff --git a/tests/guest/osbench/src/arch/x86_64.rs b/tests/guest/osbench/src/arch/x86_64.rs index 2e456f485e1..444e8376224 100644 --- a/tests/guest/osbench/src/arch/x86_64.rs +++ b/tests/guest/osbench/src/arch/x86_64.rs @@ -1,64 +1,129 @@ -//! CPU identity and topology as x86-64's CPUID reads them, which answers the -//! same under any OS. +//! What osbench needs written for x86-64 in particular: CPU identity and +//! topology as CPUID reads them (ToyOS has no call that says), a chain of +//! dependent adds to time the clock with, and the bytes of a program that +//! exits. -use core::arch::x86_64::__cpuid_count; -use std::sync::OnceLock; +#[cfg(target_os = "toyos")] +pub use cpuid::{core_of, cpu_model, current_cpu, threads_per_core}; -struct Topology { - /// CPUID leaf 0BH enumerates topology (SDM Vol. 2A: a subleaf 0 whose - /// EBX[15:0] is 0 enumerates nothing). - x2apic: bool, - /// Right shift from an APIC ID to its core's ID. - smt_shift: u32, +/// `turns` turns of 100 dependent register adds, each waiting one cycle for +/// the one before it on every x86-64 core either bench has (Intel's and AMD's +/// optimization manuals list `ADD r64, r64` at one cycle). Inline assembly, so +/// the chain is the one written whatever the optimizer does. +pub fn add_chain(turns: u64) { + let (mut x, mut n) = (std::hint::black_box(0u64), turns); + // SAFETY: arithmetic on two registers this block owns. + unsafe { + std::arch::asm!( + "2:", + ".rept 100", + "add {x}, 1", + ".endr", + "dec {n}", + "jnz 2b", + x = inout(reg) x, + n = inout(reg) n, + options(nomem, nostack), + ); + } + std::hint::black_box((x, n)); } -fn topology() -> &'static Topology { - static TOPOLOGY: OnceLock = OnceLock::new(); - TOPOLOGY.get_or_init(|| { - let max = __cpuid_count(0, 0).eax; - let leaf_b = __cpuid_count(0xb, 0); - if max >= 0xb && leaf_b.ebx & 0xffff != 0 { - // EAX[4:0] at the SMT level: the shift to the next level's ID. - return Topology { x2apic: true, smt_shift: leaf_b.eax & 0x1f }; - } - // AMD without leaf 0BH: CPUID 8000_001EH EBX[15:8] is threads per - // core minus one (APM Vol. 3), where 8000_0001H ECX[22] says the - // topology extensions exist. - let max_ext = __cpuid_count(0x8000_0000, 0).eax; - let extensions = max_ext >= 0x8000_001e && __cpuid_count(0x8000_0001, 0).ecx & (1 << 22) != 0; - let threads = if extensions { ((__cpuid_count(0x8000_001e, 0).ebx >> 8) & 0xff) + 1 } else { 1 }; - Topology { x2apic: false, smt_shift: threads.next_power_of_two().trailing_zeros() } - }) -} +/// Adds per turn of [`add_chain`]. +pub const ADDS_PER_TURN: u64 = 100; + +/// The ELF machine a generated program is for (`EM_X86_64`). +pub const ELF_MACHINE: u16 = 62; + +/// What a generated program runs, position-independent: `exit_group(0)` (the +/// x86-64 syscall table's 231, the number in RAX and the code in RDI), then a +/// trap that is never reached. +#[cfg(target_os = "linux")] +pub const EXIT_CODE: [u8; 11] = [ + 0xb8, 0xe7, 0x00, 0x00, 0x00, // mov eax, 231 (exit_group) + 0x31, 0xff, // xor edi, edi + 0x0f, 0x05, // syscall + 0x0f, 0x0b, // ud2 +]; -/// The APIC ID of the CPU that ran this: leaf 0BH's EDX, or leaf 01H's -/// EBX[31:24] where leaf 0BH enumerates nothing. Stale as soon as the -/// scheduler moves the thread. -pub fn current_cpu() -> u32 { - if topology().x2apic { - __cpuid_count(0xb, 0).edx - } else { - __cpuid_count(1, 0).ebx >> 24 +#[cfg(target_os = "linux")] +const _: () = assert!(libc::SYS_exit_group == 231); + +/// What a generated program runs, position-independent: `exit(0)` by +/// `SYS_EXIT` (`toyos_abi::syscall`: the number in RDI, the code in RSI), then +/// a trap that is never reached. +#[cfg(target_os = "toyos")] +pub const EXIT_CODE: [u8; 11] = [ + 0xbf, 0x48, 0x00, 0x00, 0x00, // mov edi, 72 (SYS_EXIT) + 0x31, 0xf6, // xor esi, esi + 0x0f, 0x05, // syscall + 0x0f, 0x0b, // ud2 +]; + +#[cfg(target_os = "toyos")] +const _: () = assert!(toyos_abi::syscall::SYS_EXIT == 0x48); + +#[cfg(target_os = "toyos")] +mod cpuid { + use core::arch::x86_64::__cpuid_count; + use std::sync::OnceLock; + + struct Topology { + /// CPUID leaf 0BH enumerates topology (SDM Vol. 2A: a subleaf 0 whose + /// EBX[15:0] is 0 enumerates nothing). + x2apic: bool, + /// Right shift from an APIC ID to its core's ID. + smt_shift: u32, } -} -/// The core an APIC ID belongs to: two CPUs of one core are SMT siblings. -pub fn core_of(apic: u32) -> u32 { - apic >> topology().smt_shift -} + fn topology() -> &'static Topology { + static TOPOLOGY: OnceLock = OnceLock::new(); + TOPOLOGY.get_or_init(|| { + let max = __cpuid_count(0, 0).eax; + let leaf_b = __cpuid_count(0xb, 0); + if max >= 0xb && leaf_b.ebx & 0xffff != 0 { + // EAX[4:0] at the SMT level: the shift to the next level's ID. + return Topology { x2apic: true, smt_shift: leaf_b.eax & 0x1f }; + } + // AMD without leaf 0BH: CPUID 8000_001EH EBX[15:8] is threads per + // core minus one (APM Vol. 3), where 8000_0001H ECX[22] says the + // topology extensions exist. + let max_ext = __cpuid_count(0x8000_0000, 0).eax; + let extensions = max_ext >= 0x8000_001e && __cpuid_count(0x8000_0001, 0).ecx & (1 << 22) != 0; + let threads = if extensions { ((__cpuid_count(0x8000_001e, 0).ebx >> 8) & 0xff) + 1 } else { 1 }; + Topology { x2apic: false, smt_shift: threads.next_power_of_two().trailing_zeros() } + }) + } -pub fn threads_per_core() -> u32 { - 1 << topology().smt_shift -} + /// The APIC ID of the CPU that ran this: leaf 0BH's EDX, or leaf 01H's + /// EBX[31:24] where leaf 0BH enumerates nothing. Stale as soon as the + /// scheduler moves the thread. + pub fn current_cpu() -> u32 { + if topology().x2apic { + __cpuid_count(0xb, 0).edx + } else { + __cpuid_count(1, 0).ebx >> 24 + } + } + + /// The core an APIC ID belongs to: two CPUs of one core are SMT siblings. + pub fn core_of(apic: u32) -> u32 { + apic >> topology().smt_shift + } + + pub fn threads_per_core() -> u32 { + 1 << topology().smt_shift + } -/// The processor brand string, CPUID 8000_0002H to 8000_0004H. -pub fn cpu_model() -> String { - let mut bytes = Vec::with_capacity(48); - for leaf in 0x8000_0002u32..=0x8000_0004 { - let r = __cpuid_count(leaf, 0); - for reg in [r.eax, r.ebx, r.ecx, r.edx] { - bytes.extend_from_slice(®.to_le_bytes()); + /// The processor brand string, CPUID 8000_0002H to 8000_0004H. + pub fn cpu_model() -> String { + let mut bytes = Vec::with_capacity(48); + for leaf in 0x8000_0002u32..=0x8000_0004 { + let r = __cpuid_count(leaf, 0); + for reg in [r.eax, r.ebx, r.ecx, r.edx] { + bytes.extend_from_slice(®.to_le_bytes()); + } } + String::from_utf8_lossy(&bytes).trim_matches(char::from(0)).trim().to_string() } - String::from_utf8_lossy(&bytes).trim_matches(char::from(0)).trim().to_string() } diff --git a/tests/guest/osbench/src/boot.rs b/tests/guest/osbench/src/boot.rs new file mode 100644 index 00000000000..a2914fbe398 --- /dev/null +++ b/tests/guest/osbench/src/boot.rs @@ -0,0 +1,45 @@ +//! Boot to userland, as each system can say it unprivileged. **The two boot +//! different things**: a ToyOS benchcase boot starts four services and the +//! runner, a Linux distribution its whole session; the numbers say where each +//! boot's time went, not which is better. +//! +//! ToyOS: the CPU's counter runs from reset, and the clock page says where +//! the kernel's zero is on it, so `boot.kernel_at_ms` is firmware and loader and +//! `boot.this_job_at_ms` the kernel and userland up to this job, which the job +//! list runs first. The kernel's own `boot:` lines in the log split the +//! kernel's part further. Linux: `systemd-analyze time`, as it prints it, +//! where it answers; and how long ago the kernel started. + +use crate::report::condition; + +pub fn suite() { + #[cfg(target_os = "toyos")] + { + let page = toyos_abi::clock::page(); + let since_kernel = toyos_abi::clock::nanos_since_boot(); + condition("boot.kernel_at_ms", page.stamp_at_boot / 1_000_000); + condition("boot.this_job_at_ms", since_kernel / 1_000_000); + condition("boot.this_job_since_counter_zero_ms", (page.stamp_at_boot + since_kernel) / 1_000_000); + } + #[cfg(target_os = "linux")] + { + let uptime = std::fs::read_to_string("/proc/uptime").unwrap_or_default(); + condition("boot.uptime_s", uptime.split_whitespace().next().unwrap_or("unknown")); + match std::process::Command::new("systemd-analyze").arg("time").output() { + Ok(out) if out.status.success() => { + let text = String::from_utf8_lossy(&out.stdout); + for (i, line) in text.lines().filter(|l| !l.trim().is_empty()).enumerate() { + condition(&format!("boot.systemd_analyze.{i}"), line.trim()); + } + } + Ok(out) => crate::report::refuse( + "boot.systemd_analyze", + format!("ended {}: {}", out.status, String::from_utf8_lossy(&out.stderr).trim()), + ), + Err(e) if e.kind() == std::io::ErrorKind::NotFound => { + crate::report::unsupported("boot.systemd_analyze", "this system has no systemd-analyze") + } + Err(e) => crate::report::refuse("boot.systemd_analyze", format!("would not run: {e}")), + } + } +} diff --git a/tests/guest/osbench/src/clock.rs b/tests/guest/osbench/src/clock.rs new file mode 100644 index 00000000000..e6a7fe2eeae --- /dev/null +++ b/tests/guest/osbench/src/clock.rs @@ -0,0 +1,62 @@ +//! The clock a CPU is running at, read the same way on both systems: +//! `arch::add_chain`'s adds wait a cycle each, so cycles are the number of +//! adds. + +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::{Duration, Instant}; + +use crate::report::result; +use crate::ns_since; + +/// What the last [`settle`] settled at, for the next result line to print. +static SETTLED: AtomicU64 = AtomicU64::new(0); + +/// Turns per probe: 100,000 cycles, 25 to 50 µs on either bench. +const TURNS: u64 = 1_000; +const ADDS: u64 = crate::arch::ADDS_PER_TURN; + +fn burst() -> u64 { + let t = Instant::now(); + crate::arch::add_chain(TURNS); + ns_since(t).max(1) +} + +/// The clock the calling CPU runs at now, in MHz: the fastest of five probes, +/// so an interrupt inside one does not read as a slow clock. +pub fn mhz() -> u64 { + let ns = (0..5).map(|_| burst()).min().expect("five probes"); + ADDS * TURNS * 1000 / ns +} + +/// A steady-state warm-up of the calling CPU, for a benchmark to run after: +/// probes back to back for at least 10 ms and until three in a row agree +/// within 1%, or for 200 ms. The clock it reached is printed beside the next +/// result as `mhz_settled`, and `mhz` beside it is the clock just after. +pub fn settle() { + let start = Instant::now(); + let mut last = [0u64; 3]; + loop { + last.rotate_left(1); + last[2] = ADDS * TURNS * 1000 / burst(); + let (lo, hi) = (last.iter().min().copied().unwrap_or(0), last.iter().max().copied().unwrap_or(0)); + let steady = lo > 0 && (hi - lo) * 100 <= hi; + let spent = start.elapsed(); + if (steady && spent >= Duration::from_millis(10)) || spent >= Duration::from_millis(200) { + SETTLED.store(last[2], Ordering::Relaxed); + return; + } + } +} + +/// The clock the last [`settle`] reached, once: zero when none has run since. +pub fn take_settled() -> u64 { + SETTLED.swap(0, Ordering::Relaxed) +} + +/// `cpu.clock`: 200 probes back to back after one, MHz. The first probes of a +/// CPU leaving idle show its ramp; the rest, the clock it settles at. +pub fn distribution() { + burst(); + let mut mhz: Vec = (0..200).map(|_| ADDS * TURNS * 1000 / burst()).collect(); + result("cpu.clock", "MHz", &mut mhz, &[("adds_per_probe", (ADDS * TURNS).to_string())]); +} diff --git a/tests/guest/osbench/src/files.rs b/tests/guest/osbench/src/files.rs new file mode 100644 index 00000000000..0b81b4dfc01 --- /dev/null +++ b/tests/guest/osbench/src/files.rs @@ -0,0 +1,225 @@ +//! Files, through std's `fs` on both systems, under a directory each one +//! keeps in memory: the same operations on Linux's VFS over tmpfs and on +//! ToyOS's two kinds of file service, the kernel's own tmpfs (syscalls) and a +//! file server process (IPC per request). Persistent storage is `storage`'s. +//! +//! The `` in each name says where it ran: `shm` is Linux's +//! `/dev/shm`; `tmp` is ToyOS's `/tmp`, which the kernel serves; `served` is +//! ToyOS's `/state`, which the DATA file server serves, and which a boot with +//! no DATA partition keeps in memory (the file server says so in the log). + +use std::fs::{self, File, OpenOptions}; +use std::io::{Read, Seek, SeekFrom, Write}; +use std::path::{Path, PathBuf}; + +use crate::measure::{each, io, throughput}; +use crate::report::{condition, refuse}; + +const MIB: usize = 1 << 20; + +/// A directory to measure under, and what serves it. +pub struct Target { + pub name: &'static str, + pub dir: &'static str, + pub served_by: &'static str, +} + +pub fn memory_targets() -> Vec { + if cfg!(target_os = "toyos") { + vec![ + Target { name: "tmp", dir: "/tmp", served_by: "the kernel's tmpfs, through syscalls" }, + Target { name: "served", dir: "/state", served_by: "the DATA file server, through IPC" }, + ] + } else { + vec![Target { name: "shm", dir: "/dev/shm", served_by: "tmpfs, through the VFS" }] + } +} + +/// A scratch directory of this process's under `dir`, removed whole on drop. +pub struct Scratch(pub PathBuf); + +impl Scratch { + pub fn new(dir: &str) -> std::io::Result { + let path = Path::new(dir).join(format!("osbench-{}", std::process::id())); + let _ = fs::remove_dir_all(&path); + fs::create_dir(&path)?; + Ok(Scratch(path)) + } + + pub fn at(&self, name: &str) -> PathBuf { + self.0.join(name) + } +} + +impl Drop for Scratch { + fn drop(&mut self) { + let _ = fs::remove_dir_all(&self.0); + } +} + +/// A file of `len` bytes of a pattern. +fn fill(path: &Path, len: usize) -> std::io::Result<()> { + let block: Vec = (0..MIB.min(len)).map(|i| (i % 251) as u8).collect(); + let mut f = File::create(path)?; + let mut left = len; + while left > 0 { + let n = left.min(block.len()); + f.write_all(&block[..n])?; + left -= n; + } + Ok(()) +} + +/// A 4 KiB-aligned offset in a file of `pages` pages, the same sequence on +/// both systems. +fn page_at(i: usize, pages: usize) -> u64 { + let x = (i as u64).wrapping_mul(0x9e37_79b9_7f4a_7c15) >> 20; + (x % pages as u64) * 4096 +} + +/// Every benchmark under `target`. Each one's comment is its warm-up and +/// repetitions. +pub fn suite(target: &Target) { + condition(&format!("fs.{}.dir", target.name), target.dir); + condition(&format!("fs.{}.served_by", target.name), target.served_by); + #[cfg(target_os = "linux")] + condition(&format!("fs.{}.mount", target.name), crate::sys::mount_options(target.dir)); + let scratch = match Scratch::new(target.dir) { + Ok(s) => s, + Err(e) => return refuse(&format!("fs.{}", target.name), format!("no scratch directory under {}: {e}", target.dir)), + }; + let name = |op: &str| format!("fs.{}.{op}", target.name); + + // Opening an existing 4 KiB file for reading and closing it: 2,000 after 100. + let small = scratch.at("small"); + if let Err(e) = fill(&small, 4096) { + return refuse(&name("setup"), e); + } + each(&name("open_close"), 100, 2000, &[], |_| io("open", File::open(&small)).map(drop)); + + // `metadata` of the same file: 2,000 after 100. + each(&name("stat"), 100, 2000, &[], |_| io("stat", fs::metadata(&small)).map(drop)); + + // A new file, 100 bytes written to it, closed and removed: 1,000 after 50. + let fresh = scratch.at("fresh"); + each(&name("create_write_unlink"), 50, 1000, &[("bytes", "100".into())], |_| { + let mut f = io("create", File::create(&fresh))?; + io("write", f.write_all(&[7u8; 100]))?; + drop(f); + io("unlink", fs::remove_file(&fresh)) + }); + + // A 4 KiB read and a 4 KiB write at a page-aligned offset of a 16 MiB + // file held open, each a seek and the transfer (std on ToyOS has no + // positioned read): 2,000 after 100. + let big = scratch.at("big"); + if let Err(e) = fill(&big, 16 * MIB) { + return refuse(&name("setup"), e); + } + let pages = 16 * MIB / 4096; + match OpenOptions::new().read(true).write(true).open(&big) { + Ok(mut f) => { + let mut buf = vec![0u8; 4096]; + each(&name("read_4k_at"), 100, 2000, &[("file_bytes", (16 * MIB).to_string())], |i| { + io("seek", f.seek(SeekFrom::Start(page_at(i, pages))))?; + io("read", f.read_exact(&mut buf)) + }); + each(&name("write_4k_at"), 100, 2000, &[("file_bytes", (16 * MIB).to_string())], |i| { + io("seek", f.seek(SeekFrom::Start(page_at(i, pages))))?; + io("write", f.write_all(&buf)) + }); + } + Err(e) => refuse(&name("read_4k_at"), e), + } + let _ = fs::remove_file(&big); + + // Listing a directory of 1,000 files, every name: 50 after 5. + let listed = scratch.at("listed"); + let made = (|| -> std::io::Result<()> { + fs::create_dir(&listed)?; + for i in 0..1000 { + File::create(listed.join(format!("entry-{i:04}")))?; + } + Ok(()) + })(); + match made { + Ok(()) => each(&name("readdir.1000"), 5, 50, &[("entries", "1000".into())], |_| { + let mut n = 0; + for entry in io("read_dir", fs::read_dir(&listed))? { + std::hint::black_box(io("entry", entry)?.file_name()); + n += 1; + } + if n == 1000 { Ok(()) } else { Err(format!("listed {n} of 1000")) } + }), + Err(e) => refuse(&name("readdir.1000"), e), + } + let _ = fs::remove_dir_all(&listed); + + // A file renamed within its directory, back and forth: 2,000 after 100. + let (a, b) = (scratch.at("a"), scratch.at("b")); + match File::create(&a) { + Ok(_) => each(&name("rename"), 100, 2000, &[], |i| { + let (from, to) = if i % 2 == 0 { (&a, &b) } else { (&b, &a) }; + io("rename", fs::rename(from, to)) + }), + Err(e) => refuse(&name("rename"), e), + } + + // An empty directory made and removed: 1,000 after 50. + let sub = scratch.at("sub"); + each(&name("mkdir_rmdir"), 50, 1000, &[], |_| { + io("mkdir", fs::create_dir(&sub))?; + io("rmdir", fs::remove_dir(&sub)) + }); + + // A directory of 100 files of 64 bytes made, then every file and the + // directory removed: ns per whole tree, 20 after 2. + let tree = scratch.at("tree"); + each(&name("tree.100"), 2, 20, &[("files", "100".into())], |_| { + io("mkdir", fs::create_dir(&tree))?; + for i in 0..100 { + io("write", fs::write(tree.join(format!("f{i:03}")), [3u8; 64]))?; + } + for i in 0..100 { + io("unlink", fs::remove_file(tree.join(format!("f{i:03}"))))?; + } + io("rmdir", fs::remove_dir(&tree)) + }); + + // 64 MiB written to a new file and read back whole, in 4 KiB and 1 MiB + // calls: MB/s, five rounds after one. Last, as the largest: a server that + // cannot hold it takes no other benchmark's number with it. + sequential(&name("seq"), &scratch.at("seq"), 64 * MIB, 5); +} + +/// `len` bytes written to `path` and read back, in 4 KiB and in 1 MiB calls: +/// `_write.` and `_read.`, MB/s, `rounds` after +/// one. A write round creates the file anew; the read rounds read the last +/// one written. +pub fn sequential(prefix: &str, path: &Path, len: usize, rounds: usize) { + let block: Vec = (0..MIB).map(|i| (i % 253) as u8).collect(); + for call in [4096usize, MIB] { + let extra = [("call_bytes", call.to_string()), ("file_bytes", len.to_string())]; + throughput(&format!("{prefix}_write.{call}"), rounds, len as u64, &extra, || { + let mut f = io("create", File::create(path))?; + for chunk in 0..len / call { + let at = chunk * call % MIB; + io("write", f.write_all(&block[at..at + call]))?; + } + Ok(()) + }); + let mut buf = vec![0u8; call]; + throughput(&format!("{prefix}_read.{call}"), rounds, len as u64, &extra, || { + let mut f = io("open", File::open(path))?; + let mut got = 0; + loop { + match io("read", f.read(&mut buf))? { + 0 => break, + n => got += n, + } + } + if got == len { Ok(()) } else { Err(format!("read {got} of {len} bytes")) } + }); + } + let _ = fs::remove_file(path); +} diff --git a/tests/guest/osbench/src/ipc.rs b/tests/guest/osbench/src/ipc.rs new file mode 100644 index 00000000000..5d338adb98c --- /dev/null +++ b/tests/guest/osbench/src/ipc.rs @@ -0,0 +1,162 @@ +//! A request and its reply between this process and a child serving it, over +//! each system's own IPC: on ToyOS a connection through a port, the native +//! request/reply every service speaks; on Linux a Unix stream socket. **The +//! mechanisms differ by design**, and that difference is what is measured. +//! A ToyOS message past one frame (8 KiB) goes as consecutive frames, which +//! `frames_each_way` counts; a Linux one is one write. +//! +//! The child is this program as `osbench ipc-serve`. Each phase starts with a +//! control message, `[bytes, rounds, mode]` as three little-endian `u32`s; +//! the child then answers `rounds` requests, and a phase of no rounds ends it. + +use std::time::Instant; + +use crate::measure::{each, io, Samples}; +use crate::report::{refuse, result}; +use crate::sys::ipc::{self, Peer}; +use crate::sys::{self, Counts}; +use crate::ns_since; + +const ECHO: u32 = 0; +const HANDLE: u32 = 1; + +const MECHANISM: &str = if cfg!(target_os = "toyos") { "toyos_connection" } else { "unix_stream_socket" }; +const HANDLE_MECHANISM: &str = if cfg!(target_os = "toyos") { "toyos_moved_pipe_end" } else { "scm_rights_then_close" }; + +fn control(peer: &Peer, bytes: u32, rounds: u32, mode: u32) -> std::io::Result<()> { + let mut words = [0u8; 12]; + for (slot, word) in words.as_chunks_mut::<4>().0.iter_mut().zip([bytes, rounds, mode]) { + *slot = word.to_le_bytes(); + } + peer.send(&words) +} + +/// `osbench ipc-serve`: answer every phase its parent asks for. +pub fn serve() { + let peer = ipc::served().expect("osbench ipc-serve is started by osbench with its end"); + loop { + let mut words = [0u8; 12]; + peer.recv(&mut words).expect("a control message"); + let word = |i: usize| u32::from_le_bytes(words[i * 4..i * 4 + 4].try_into().expect("four")); + let (bytes, rounds, mode) = (word(0) as usize, word(1), word(2)); + if rounds == 0 { + return; + } + let mut buf = vec![0u8; bytes]; + for _ in 0..rounds { + match mode { + HANDLE => { + let token = peer.recv_with(&mut buf).expect("a request carrying a handle"); + peer.send_with(&buf, token).expect("a reply carrying it back"); + } + _ => { + peer.recv(&mut buf).expect("a request"); + peer.send(&buf).expect("a reply"); + } + } + } + } +} + +pub fn suite() { + let exe = match std::env::current_exe() { + Ok(exe) => exe, + Err(e) => return refuse("ipc", format!("no path to this program: {e}")), + }; + let (mut child, peer) = match ipc::start_server(&exe) { + Ok(pair) => pair, + Err(e) => return refuse("ipc", format!("the server would not start: {e}")), + }; + + // A request of `bytes` and a reply of as many, round trip: 5,000 after + // 200 at 8 B and 4 KiB, 2,000 after 100 at 64 KiB. + for (bytes, warmup, samples) in [(8usize, 200u32, 5000u32), (4096, 200, 5000), (65536, 100, 2000)] { + let bench = format!("ipc.reqrep.{bytes}"); + let mut buf = vec![0x42u8; bytes]; + let mut run = || -> std::io::Result> { + control(&peer, bytes as u32, warmup + samples, ECHO)?; + for _ in 0..warmup { + peer.send(&buf)?; + peer.recv(&mut buf)?; + } + crate::clock::settle(); + let before = sys::counts(); + let mut ns = Vec::with_capacity(samples as usize); + for _ in 0..samples { + let t = Instant::now(); + peer.send(&buf)?; + peer.recv(&mut buf)?; + ns.push(ns_since(t)); + } + Ok((ns, Counts::per_op(&before, u64::from(samples)))) + }; + match run() { + Ok((mut ns, counts)) => { + let mut extra = vec![ + ("mechanism", MECHANISM.to_string()), + ("frames_each_way", ipc::frames(bytes).to_string()), + ]; + extra.extend(counts); + result(&bench, "ns", &mut ns, &extra); + } + Err(e) => { + refuse(&bench, e); + let _ = child.kill(); + let _ = child.wait(); + return; + } + } + } + + // An 8-byte request carrying one handle, and a reply carrying it back: + // 5,000 after 200. ToyOS moves the handle; Linux's SCM_RIGHTS installs a + // copy in the receiver, which closes the one it sent. + let bench = "ipc.reqrep_handle.8"; + let run = || -> std::io::Result> { + let (warmup, samples) = (200u32, 5000u32); + control(&peer, 8, warmup + samples, HANDLE)?; + let mut buf = [0x17u8; 8]; + let mut token = ipc::token()?; + let mut trip = |token: ipc::Token| -> std::io::Result { + peer.send_with(&buf, token)?; + peer.recv_with(&mut buf) + }; + for _ in 0..warmup { + token = trip(token)?; + } + crate::clock::settle(); + let before = sys::counts(); + let mut ns = Vec::with_capacity(samples as usize); + for _ in 0..samples { + let t = Instant::now(); + token = trip(token)?; + ns.push(ns_since(t)); + } + Ok((ns, Counts::per_op(&before, u64::from(samples)))) + }; + match run() { + Ok((mut ns, counts)) => { + let mut extra = vec![("mechanism", HANDLE_MECHANISM.to_string())]; + extra.extend(counts); + result(bench, "ns", &mut ns, &extra); + } + Err(e) => refuse(bench, e), + } + let _ = control(&peer, 0, 0, ECHO); + match child.wait() { + Ok(status) if status.success() => {} + outcome => refuse("ipc.server", format!("the server ended {outcome:?}")), + } + + // A connection opened and accepted by this one process, both ends then + // closed: ToyOS through a port in a namespace this process built, Linux + // to a listening socket in the abstract namespace. 1,000 after 50. + match ipc::Rendezvous::new() { + Ok(rendezvous) => { + each("ipc.connect_accept", 50, 1000, &[("mechanism", MECHANISM.into())], |_| { + io("connect", rendezvous.connect_accept()) + }) + } + Err(e) => refuse("ipc.connect_accept", e), + } +} diff --git a/tests/guest/osbench/src/main.rs b/tests/guest/osbench/src/main.rs index 8b67bd0be21..a90f83b84e4 100644 --- a/tests/guest/osbench/src/main.rs +++ b/tests/guest/osbench/src/main.rs @@ -1,19 +1,22 @@ -//! `osbench`: the same scheduler and system workloads, built from one source -//! for ToyOS and for Linux, so one machine's two systems can be compared. +//! `osbench`: the same system workloads, built from one source for ToyOS +//! and for Linux, so one machine's two systems can be compared. //! -//! `osbench ` runs a group: `system`, `sched`, `fair` or `all`. A +//! `osbench ` runs a group, or `all` of them in [`GROUPS`]' order. A //! ToyOS job list passes no arguments, so there the group is the name the //! program was started under, `osbench_`. Every other command is one //! this program gives its own children. //! //! Every result is one line of `key=value` words (`report`): a distribution -//! with its sample count, minimum, p50, p90, p99, p99.9, maximum and mean, and -//! the conditions it was taken under. Each benchmark's own comment states its -//! warm-up and repetitions. Benchmarks report and never judge: a group exits -//! non-zero only when one of them could not measure. +//! with its sample count, minimum, p50, p90, p99, p99.9, maximum and mean, +//! the clock it was taken at, and the conditions it was taken under. Each +//! benchmark's own comment states its warm-up and repetitions. Benchmarks +//! report and never judge: a group exits non-zero only when one of them could +//! not measure, and a facility a system does not offer is a result +//! (`unsupported`), not a failure. //! -//! File I/O is not measured: ToyOS's storage on the benches is a USB stick and -//! Linux's an NVMe disk, so a comparison would be of the devices. +//! Where a facility differs the code does too, in `sys` and said at the +//! benchmark: native IPC, persistent storage's medium, the tail group's +//! diagnostics. Everything else is the same source on both. //! //! The Linux build is static (`x86_64-unknown-linux-musl`, linked by the //! toolchain's own LLD per `.cargo/config.toml`), so a bench runs it without a @@ -30,15 +33,26 @@ //! code is generated alike for both; std's platform layer and the C library //! beneath it (musl's on Linux) are each system's own. -#[cfg(target_os = "toyos")] mod arch; +mod boot; +mod clock; mod fair; +mod files; +mod ipc; +mod measure; +mod mem; +mod net; mod pingpong; mod place; +mod procs; mod report; +mod storage; mod sys; mod system; +mod tail; +mod time; mod wake; +mod work; use std::time::Instant; @@ -112,9 +126,37 @@ fn fair() { } } +fn files() { + for target in files::memory_targets() { + files::suite(&target); + } +} + +/// Every group, in the order `all` and the ToyOS job list run them: `boot` +/// first, since it reads how long the boot took to reach it, and `persist` +/// last, since it writes the volume a ToyOS boot's log is on. +const GROUPS: [(&str, fn()); 13] = [ + ("boot", boot::suite), + ("system", system), + ("sched", sched), + ("fair", fair), + ("files", files), + ("ipc", ipc::suite), + ("net", net::suite), + ("procs", procs::suite), + ("mem", mem::suite), + ("time", time::suite), + ("work", work::suite), + ("tail", tail::suite), + ("persist", storage::suite), +]; + +/// A group between its first and last lines, after the machine's conditions +/// and the clock its CPU starts at. fn group(name: &str, run: fn()) { report::group(name, "start"); conditions(); + clock::distribution(); let t = Instant::now(); run(); report::group(name, &format!("done secs={}", t.elapsed().as_secs())); @@ -129,22 +171,21 @@ fn main() { }; let rest = args.get(2..).unwrap_or_default(); match command { - "system" => group("system", system), - "sched" => group("sched", sched), - "fair" => group("fair", fair), - "all" => { - group("system", system); - group("sched", sched); - group("fair", fair); - } + "all" => GROUPS.iter().for_each(|(name, run)| group(name, *run)), "nop" => return, "spin" => return wake::spin(), "fair-job" => return fair::job(rest), "fair-helper" => return fair::helper(rest), - other => { - eprintln!("osbench: no command {other:?}; the groups are system, sched, fair and all"); - std::process::exit(2); - } + "ipc-serve" => return ipc::serve(), + "cc" => return work::cc(rest), + named => match GROUPS.iter().find(|(name, _)| *name == named) { + Some((name, run)) => group(name, *run), + None => { + let names: Vec<&str> = GROUPS.iter().map(|(name, _)| *name).collect(); + eprintln!("osbench: no command {named:?}; the groups are {} and all", names.join(", ")); + std::process::exit(2); + } + }, } if report::any_refused() { std::process::exit(1); diff --git a/tests/guest/osbench/src/measure.rs b/tests/guest/osbench/src/measure.rs new file mode 100644 index 00000000000..c272f4d8294 --- /dev/null +++ b/tests/guest/osbench/src/measure.rs @@ -0,0 +1,75 @@ +//! The two shapes most benchmarks here take: an operation timed alone many +//! times, and a transfer timed whole a few times. + +use std::time::Instant; + +use crate::report::{refuse, result}; +use crate::sys::{self, Counts}; +use crate::ns_since; + +/// Samples and the fields printed beside them. +pub type Samples<'a> = (Vec, Vec<(&'a str, String)>); + +/// `op(i)` `warmup` times unread, then `samples` times each timed alone: ns +/// per operation, with the process's own accounting per operation beside it. +/// An operation that fails refuses the benchmark with its error. +pub fn each( + bench: &str, + warmup: usize, + samples: usize, + extra: &[(&str, String)], + mut op: impl FnMut(usize) -> Result<(), String>, +) { + let mut run = || -> Result, String> { + for i in 0..warmup { + op(i)?; + } + crate::clock::settle(); + let before = sys::counts(); + let mut ns = Vec::with_capacity(samples); + for i in 0..samples { + let t = Instant::now(); + op(warmup + i)?; + ns.push(ns_since(t)); + } + Ok((ns, Counts::per_op(&before, samples as u64))) + }; + match run() { + Ok((mut ns, counts)) => { + let fields: Vec<(&str, String)> = extra.iter().cloned().chain(counts).collect(); + result(bench, "ns", &mut ns, &fields); + } + Err(why) => refuse(bench, why), + } +} + +/// `round()` once unread and `rounds` times timed whole, each moving `bytes`: +/// MB/s per round. +pub fn throughput( + bench: &str, + rounds: usize, + bytes: u64, + extra: &[(&str, String)], + mut round: impl FnMut() -> Result<(), String>, +) { + let mut run = || -> Result, String> { + round()?; + crate::clock::settle(); + (0..rounds) + .map(|_| { + let t = Instant::now(); + round()?; + Ok(bytes * 1000 / ns_since(t).max(1)) + }) + .collect() + }; + match run() { + Ok(mut mbps) => result(bench, "MB/s", &mut mbps, extra), + Err(why) => refuse(bench, why), + } +} + +/// An `io::Result` as this module's error. +pub fn io(what: &str, r: std::io::Result) -> Result { + r.map_err(|e| format!("{what}: {e}")) +} diff --git a/tests/guest/osbench/src/mem.rs b/tests/guest/osbench/src/mem.rs new file mode 100644 index 00000000000..04ace337fcd --- /dev/null +++ b/tests/guest/osbench/src/mem.rs @@ -0,0 +1,218 @@ +//! Memory beyond `system`'s: what a first touch costs per page size, changing +//! and giving back part of a mapping, the allocator under many threads, and a +//! large `realloc`. +//! +//! **Where the cost lands differs by design.** ToyOS commits, zeroes and maps +//! an anonymous range whole in 2 MiB pages inside `mmap`, so a first touch +//! takes no fault there; Linux faults each page on first touch, in 4 KiB +//! pages where huge pages are refused and in 2 MiB pages where they are asked +//! for and given. `map_touch_unmap` is the like-for-like total. The +//! allocator is each system's own: ToyOS std's dlmalloc under one lock, +//! Linux's static musl malloc. + +use std::alloc::{alloc, dealloc, realloc, Layout}; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::{Arc, Barrier}; +use std::thread; +use std::time::{Duration, Instant}; + +use crate::measure::each; +use crate::report::{refuse, result}; +use crate::sys; +use crate::ns_since; + +const MIB: usize = 1 << 20; +const PAGE: usize = 4096; +const HUGE: usize = 2 * MIB; + +pub fn suite() { + first_touch(); + protect(); + unmap_part(); + for size in [16usize, 4096, MIB] { + churn(size, 1); + churn(size, crate::cpus()); + } + realloc_grow(); +} + +/// A fresh 64 MiB mapping written once per page: ns per page touched, each +/// round's mean, and the whole map-touch-unmap per page; 4 KiB pages with +/// huge pages refused, and 2 MiB pages with them asked for. Ten rounds after one. +fn first_touch() { + const LEN: usize = 64 * MIB; + for (name, step, map) in [("4k", PAGE, sys::map_anon_4k as fn(usize) -> *mut u8), ("2m", HUGE, sys::map_anon_huge)] { + let pages = (LEN / step) as u64; + let round = || { + let t = Instant::now(); + let ptr = map(LEN); + let mapped = ns_since(t); + let before = sys::counts(); + let t = Instant::now(); + for page in 0..LEN / step { + // SAFETY: inside the mapping just made. + unsafe { ptr.add(page * step).write_volatile(1) }; + } + let touched = ns_since(t); + let faults = sys::counts().faults.zip(before.faults).map(|(b, a)| b - a); + let t = Instant::now(); + // SAFETY: the whole mapping, unused from here. + unsafe { sys::unmap(ptr, LEN) }; + (touched / pages, (mapped + touched + ns_since(t)) / pages, faults) + }; + round(); + crate::clock::settle(); + let rounds: Vec<(u64, u64, Option)> = (0..10).map(|_| round()).collect(); + let faults = rounds.iter().filter_map(|r| r.2).max().map_or("unread".to_string(), |f| f.to_string()); + let extra = [("page_bytes", step.to_string()), ("faults_per_round_max", faults), ("huge_pages", sys::huge_backing())]; + result(&format!("mem.first_touch.{name}"), "ns/page", &mut rounds.iter().map(|r| r.0).collect::>(), &extra); + result(&format!("mem.map_touch_unmap.{name}"), "ns/page", &mut rounds.iter().map(|r| r.1).collect::>(), &extra); + } +} + +/// One touched 4 KiB page of a 2 MiB mapping made read-only and writable +/// again, each change timed: 2,000 after 100. +fn protect() { + const BENCH: &str = "mem.mprotect.4k"; + let ptr = sys::map_anon(HUGE); + // SAFETY: inside the mapping. + unsafe { ptr.write_volatile(1) }; + match sys::protect(ptr, PAGE, false).and_then(|()| sys::protect(ptr, PAGE, true)) { + Ok(()) => each(BENCH, 100, 2000, &[], |i| sys::protect(ptr, PAGE, i % 2 == 1).map_err(sys::Refused::why)), + Err(refused) => refused.report(BENCH), + } + // SAFETY: the whole mapping, unused from here. + unsafe { sys::unmap(ptr, HUGE) }; +} + +/// The first 4 KiB of a touched 2 MiB mapping given back, timed, then the +/// rest: 500 after 20. +fn unmap_part() { + const BENCH: &str = "mem.munmap_part.4k"; + let once = || -> Result { + let ptr = sys::map_anon(HUGE); + // SAFETY: inside the mapping. + unsafe { ptr.add(PAGE).write_volatile(1) }; + let t = Instant::now(); + // SAFETY: the first page, never used again. + let part = unsafe { sys::unmap_part(ptr, PAGE) }; + let ns = ns_since(t); + match part { + Ok(()) => { + // SAFETY: the rest of the mapping, never used again. + unsafe { sys::unmap_part(ptr.add(PAGE), HUGE - PAGE) }?; + Ok(ns) + } + Err(why) => { + // SAFETY: the whole mapping, untouched by the refused call. + unsafe { sys::unmap(ptr, HUGE) }; + Err(why) + } + } + }; + match once() { + Ok(_) => { + for _ in 0..20 { + let _ = once(); + } + crate::clock::settle(); + match (0..500).map(|_| once()).collect::, sys::Refused>>() { + Ok(mut ns) => result(BENCH, "ns", &mut ns, &[]), + Err(refused) => refuse(BENCH, refused.why()), + } + } + Err(refused) => refused.report(BENCH), + } +} + +/// `threads` threads each freeing and allocating `size`-byte blocks for +/// 200 ms, each keeping a ring of live ones (64, or 4 of a mebibyte) and +/// writing a byte into each new block: thousands of alloc-free pairs a second +/// over all threads, five rounds after one. +fn churn(size: usize, threads: usize) { + let bench = format!("mem.malloc_churn.{size}.t{threads}"); + let ring = if size >= MIB { 4 } else { 64 }; + let layout = Layout::from_size_align(size, 16).expect("a small layout"); + let round = || -> u64 { + let start = Arc::new(Barrier::new(threads + 1)); + let stop = Arc::new(AtomicBool::new(false)); + let done = Arc::new(AtomicU64::new(0)); + let workers: Vec<_> = (0..threads) + .map(|_| { + let (start, stop, done) = (start.clone(), stop.clone(), done.clone()); + thread::spawn(move || { + // SAFETY: `layout` has a non-zero size; every block is + // freed with it once, below. + let mut live: Vec<*mut u8> = (0..ring).map(|_| unsafe { alloc(layout) }).collect(); + start.wait(); + let mut ops = 0u64; + while !stop.load(Ordering::Relaxed) { + for slot in live.iter_mut() { + // SAFETY: `*slot` came from `alloc(layout)`. + unsafe { dealloc(*slot, layout) }; + // SAFETY: as above. + let block = unsafe { alloc(layout) }; + assert!(!block.is_null(), "the allocator refused {size} bytes"); + // SAFETY: a fresh block of at least one byte. + unsafe { block.write_volatile(ops as u8) }; + *slot = block; + } + ops += ring as u64; + } + for block in live { + // SAFETY: as above. + unsafe { dealloc(block, layout) }; + } + done.fetch_add(ops, Ordering::Relaxed); + }) + }) + .collect(); + start.wait(); + let t = Instant::now(); + thread::sleep(Duration::from_millis(200)); + stop.store(true, Ordering::Relaxed); + let ns = ns_since(t); + for w in workers { + w.join().expect("a churn worker panicked"); + } + done.load(Ordering::Relaxed) * 1_000_000 / ns.max(1) + }; + round(); + crate::clock::settle(); + let mut rates: Vec = (0..5).map(|_| round()).collect(); + result(&bench, "kops/s", &mut rates, &[("block_bytes", size.to_string()), ("threads", threads.to_string()), ("ring", ring.to_string())]); +} + +/// A block grown by `realloc` from 1 MiB to 256 MiB, doubling, its first +/// mebibyte written: ns for the whole growth and for its last doubling, five +/// rounds after one. An allocator that can move the pages answers without +/// copying; one that cannot copies each time. +fn realloc_grow() { + let round = || -> (u64, u64) { + let mut size = MIB; + let layout = Layout::from_size_align(size, 16).expect("a layout"); + // SAFETY: a non-zero layout. + let mut ptr = unsafe { alloc(layout) }; + assert!(!ptr.is_null()); + // SAFETY: inside the block. + unsafe { std::ptr::write_bytes(ptr, 0x33, MIB) }; + let (mut total, mut last) = (0, 0); + while size < 256 * MIB { + let t = Instant::now(); + // SAFETY: `ptr` holds `size` bytes allocated with this alignment. + ptr = unsafe { realloc(ptr, Layout::from_size_align(size, 16).expect("a layout"), size * 2) }; + last = ns_since(t); + total += last; + assert!(!ptr.is_null(), "realloc to {} bytes was refused", size * 2); + size *= 2; + } + // SAFETY: the block as last grown. + unsafe { dealloc(ptr, Layout::from_size_align(size, 16).expect("a layout")) }; + (total, last) + }; + round(); + crate::clock::settle(); + let rounds: Vec<(u64, u64)> = (0..5).map(|_| round()).collect(); + result("mem.realloc_grow.1m_256m", "ns", &mut rounds.iter().map(|r| r.0).collect::>(), &[("doublings", "8".into())]); + result("mem.realloc_grow.last_128m_256m", "ns", &mut rounds.iter().map(|r| r.1).collect::>(), &[]); +} diff --git a/tests/guest/osbench/src/net.rs b/tests/guest/osbench/src/net.rs new file mode 100644 index 00000000000..ae5b13551a8 --- /dev/null +++ b/tests/guest/osbench/src/net.rs @@ -0,0 +1,211 @@ +//! Loopback networking through std's `net` on both systems: Linux's TCP and +//! UDP in the kernel, ToyOS's in the netstack process. Netstack runs only +//! beside a network card its row names, and a benchcase boot has none, so +//! ToyOS's socket calls answer `NotConnected`: that answer alone is reported +//! `unsupported`. Where netstack runs it refuses 127/8 and its own addresses +//! as destinations (`system/netstack/ip/src/route.rs`, +//! `RouteLocalDestination`; the UDP layer's `SendLoopback`), and that, like +//! any failure on Linux, refuses the benchmark. +//! +//! Every wait is bounded by [`PATIENCE`], so a stack that accepts a call and +//! never answers it is refused rather than hung. + +use std::io::{ErrorKind, Read, Write}; +use std::net::{Ipv4Addr, SocketAddr, TcpListener, TcpStream, UdpSocket}; +use std::thread; +use std::time::{Duration, Instant}; + +use crate::measure::{each, io}; +use crate::report::refuse; +use crate::sys; + +const PATIENCE: Duration = Duration::from_secs(5); +const LOOPBACK: Ipv4Addr = Ipv4Addr::LOCALHOST; + +fn accept(listener: &TcpListener) -> std::io::Result { + let start = Instant::now(); + loop { + match listener.accept() { + Ok((stream, _)) => { + stream.set_nonblocking(false)?; + return Ok(stream); + } + Err(e) if e.kind() == ErrorKind::WouldBlock && start.elapsed() < PATIENCE => thread::yield_now(), + Err(e) => return Err(e), + } + } +} + +fn connect(addr: SocketAddr) -> std::io::Result { + let stream = TcpStream::connect_timeout(&addr, PATIENCE)?; + stream.set_read_timeout(Some(PATIENCE))?; + stream.set_write_timeout(Some(PATIENCE))?; + Ok(stream) +} + +/// A listener on the loopback, or the reason there is none. +fn listen() -> std::io::Result<(TcpListener, SocketAddr)> { + let listener = TcpListener::bind((LOOPBACK, 0))?; + listener.set_nonblocking(true)?; + let addr = listener.local_addr()?; + // A system can open a socket and still never carry a segment to itself: + // one connection, accepted, is the proof it carries. + let probe = connect(addr)?; + let accepted = accept(&listener)?; + drop((probe, accepted)); + Ok((listener, addr)) +} + +/// Why loopback networking failed: absent only for the answer a system +/// without it gives. A benchcase boot runs no netstack, and std's socket calls +/// then answer `NotConnected`; Linux has loopback, so any failure there is one. +fn refused(what: &str, e: std::io::Error) -> sys::Refused { + let why = format!("{what}: {e} ({:?})", e.kind()); + if cfg!(target_os = "toyos") && e.kind() == std::io::ErrorKind::NotConnected { + sys::Refused::Absent(format!("no network stack answers: {why}")) + } else { + sys::Refused::Failed(why) + } +} + +pub fn suite() { + let (listener, addr) = match listen() { + Ok(pair) => pair, + Err(e) => { + let why = refused("a loopback TCP listener and one connection to it", e); + for bench in ["net.tcp.connect_accept_close", "net.tcp.reqrep.64", "net.tcp.stream.1", "net.tcp.stream.65536"] { + why.clone().report(bench); + } + return udp(); + } + }; + + // Connect, accept and both ends closed: 1,000 after 50. + each("net.tcp.connect_accept_close", 50, 1000, &[], |_| { + let client = io("connect", connect(addr))?; + let server = io("accept", accept(&listener))?; + drop((client, server)); + Ok(()) + }); + + // 64 bytes sent and echoed back by another thread, no Nagle: 5,000 after 200. + let pair = (|| -> std::io::Result<(TcpStream, TcpStream)> { + let client = connect(addr)?; + let server = accept(&listener)?; + client.set_nodelay(true)?; + server.set_nodelay(true)?; + server.set_read_timeout(Some(PATIENCE))?; + Ok((client, server)) + })(); + match pair { + Ok((mut client, mut server)) => { + let echo = thread::spawn(move || { + let mut buf = [0u8; 64]; + while server.read_exact(&mut buf).is_ok() { + if server.write_all(&buf).is_err() { + break; + } + } + }); + let mut buf = [5u8; 64]; + each("net.tcp.reqrep.64", 200, 5000, &[], |_| { + io("send", client.write_all(&buf))?; + io("receive", client.read_exact(&mut buf)) + }); + drop(client); + let _ = echo.join(); + } + Err(e) => refuse("net.tcp.reqrep.64", e), + } + + // One thread writing for 100 ms in `size`-byte writes, Nagle on as an + // ordinary program has it, another reading in 64 KiB reads: MB/s as the + // reader saw it, five rounds after one. + for size in [1usize, 65536] { + let bench = format!("net.tcp.stream.{size}"); + let mut rates = Vec::new(); + let mut failed = None; + for _ in 0..6 { + match stream_round(&listener, addr, size) { + Ok(rate) => rates.push(rate), + Err(e) => { + failed = Some(e); + break; + } + } + } + match failed { + Some(e) => refuse(&bench, e), + None => crate::report::result(&bench, "MB/s", &mut rates[1..].to_vec(), &[("write_bytes", size.to_string())]), + } + } + udp(); +} + +fn stream_round(listener: &TcpListener, addr: SocketAddr, size: usize) -> Result { + let mut writer = io("connect", connect(addr))?; + let mut reader = io("accept", accept(listener))?; + io("timeout", reader.set_read_timeout(Some(PATIENCE)))?; + let writing = thread::spawn(move || -> std::io::Result<()> { + let chunk = vec![0x5au8; size]; + let start = Instant::now(); + while start.elapsed() < Duration::from_millis(100) { + for _ in 0..64 { + writer.write_all(&chunk)?; + } + } + Ok(()) + }); + let mut buf = vec![0u8; 65536]; + io("read", reader.read(&mut buf))?; + let (mut bytes, start) = (0u64, Instant::now()); + loop { + match io("read", reader.read(&mut buf))? { + 0 => break, + n => bytes += n as u64, + } + } + let ns = crate::ns_since(start).max(1); + io("write", writing.join().map_err(|_| "the writer panicked".to_string())?)?; + Ok(bytes * 1000 / ns) +} + +/// 64 bytes sent to a loopback UDP socket another thread echoes from: +/// 5,000 after 200. +fn udp() { + let bench = "net.udp.reqrep.64"; + let sockets = (|| -> std::io::Result<(UdpSocket, UdpSocket)> { + let server = UdpSocket::bind((LOOPBACK, 0))?; + let client = UdpSocket::bind((LOOPBACK, 0))?; + client.connect(server.local_addr()?)?; + server.set_read_timeout(Some(PATIENCE))?; + client.set_read_timeout(Some(PATIENCE))?; + // As for TCP: one datagram there and back is the proof it carries. + let mut buf = [0u8; 64]; + client.send(&buf)?; + let (_, from) = server.recv_from(&mut buf)?; + server.send_to(&buf, from)?; + client.recv(&mut buf)?; + Ok((server, client)) + })(); + let (server, client) = match sockets { + Ok(pair) => pair, + Err(e) => return refused("a loopback UDP exchange", e).report(bench), + }; + let echo = thread::spawn(move || { + let mut buf = [0u8; 64]; + while let Ok((n, from)) = server.recv_from(&mut buf) { + if n == 0 || server.send_to(&buf[..n], from).is_err() { + break; + } + } + }); + let mut buf = [9u8; 64]; + each(bench, 200, 5000, &[], |_| { + io("send", client.send(&buf))?; + let n = io("receive", client.recv(&mut buf))?; + if n == 64 { Ok(()) } else { Err(format!("received {n} bytes")) } + }); + let _ = client.send(&[]); + let _ = echo.join(); +} diff --git a/tests/guest/osbench/src/procs.rs b/tests/guest/osbench/src/procs.rs new file mode 100644 index 00000000000..29d870202d4 --- /dev/null +++ b/tests/guest/osbench/src/procs.rs @@ -0,0 +1,219 @@ +//! Processes and threads in more depth than `system`'s: what a program's +//! size costs its spawn, C's `posix_spawn` beside std's `Command`, a +//! spawn-and-wait loop, and a thread's stack size. +//! +//! **The tiny and large programs are written here**, the same bytes on both +//! systems but the exit call each kernel takes: a position-independent ELF of +//! one `PT_LOAD` holding the code (under 300 bytes), and the same with a +//! second, read-only `PT_LOAD` of [`LARGE`] bytes of file data the program +//! never touches. They live in the directory `files` measures in memory +//! (ToyOS's `/tmp`, Linux's `/dev/shm`), so no disk is read. + +use std::ffi::{c_char, c_int, c_void, CString}; +use std::fs; +use std::path::{Path, PathBuf}; +use std::process::{Command, Stdio}; +use std::thread; + +use crate::files::Scratch; +use crate::measure::{each, io}; +use crate::report::refuse; +use crate::sys; + +/// The large program's untouched data: 32 MiB. +const LARGE: usize = 32 << 20; + +const PT_LOAD: u32 = 1; +const PT_GNU_STACK: u32 = 0x6474_e551; +const EHDR: usize = 64; +const PHDR: usize = 56; + +/// A position-independent executable for this machine that exits 0 at once, with +/// `payload` bytes of read-only data beside its code where `payload` is not +/// zero. Layout per the System V gABI and its x86-64 supplement: the header, +/// the program headers, the code, all in one R+X `PT_LOAD` from offset 0; +/// the payload in a second R `PT_LOAD` at file offset 4 KiB and address +/// 2 MiB; a `PT_GNU_STACK` saying the stack is not executable. +pub fn program(payload: usize) -> Vec { + let phnum = if payload > 0 { 3 } else { 2 }; + let code_at = EHDR + PHDR * phnum; + let first = code_at + crate::arch::EXIT_CODE.len(); + let mut out = vec![0u8; first]; + let put = |out: &mut Vec, at: usize, bytes: &[u8]| out[at..at + bytes.len()].copy_from_slice(bytes); + put(&mut out, 0, b"\x7fELF\x02\x01\x01"); + put(&mut out, 16, &3u16.to_le_bytes()); // ET_DYN + put(&mut out, 18, &crate::arch::ELF_MACHINE.to_le_bytes()); + put(&mut out, 20, &1u32.to_le_bytes()); // EV_CURRENT + put(&mut out, 24, &(code_at as u64).to_le_bytes()); // e_entry + put(&mut out, 32, &(EHDR as u64).to_le_bytes()); // e_phoff + put(&mut out, 52, &(EHDR as u16).to_le_bytes()); // e_ehsize + put(&mut out, 54, &(PHDR as u16).to_le_bytes()); // e_phentsize + put(&mut out, 56, &(phnum as u16).to_le_bytes()); // e_phnum + put(&mut out, 58, &64u16.to_le_bytes()); // e_shentsize, with no sections + let header = |out: &mut Vec, i: usize, kind: u32, flags: u32, offset: u64, vaddr: u64, size: u64| { + let at = EHDR + PHDR * i; + put(out, at, &kind.to_le_bytes()); + put(out, at + 4, &flags.to_le_bytes()); + put(out, at + 8, &offset.to_le_bytes()); + put(out, at + 16, &vaddr.to_le_bytes()); + put(out, at + 24, &vaddr.to_le_bytes()); + put(out, at + 32, &size.to_le_bytes()); + put(out, at + 40, &size.to_le_bytes()); + put(out, at + 48, &(if kind == PT_LOAD { 0x1000u64 } else { 16 }).to_le_bytes()); + }; + header(&mut out, 0, PT_LOAD, 0b101, 0, 0, first as u64); + header(&mut out, 1, PT_GNU_STACK, 0b110, 0, 0, 0); + if payload > 0 { + header(&mut out, 2, PT_LOAD, 0b100, 0x1000, 0x20_0000, payload as u64); + } + put(&mut out, code_at, &crate::arch::EXIT_CODE); + if payload > 0 { + out.resize(0x1000, 0); + out.extend((0..payload).map(|i| (i % 249) as u8 | 1)); + } + out +} + +fn write_program(dir: &Scratch, name: &str, payload: usize) -> std::io::Result { + let path = dir.at(name); + fs::write(&path, program(payload))?; + #[cfg(unix)] + { + use std::os::unix::fs::PermissionsExt; + fs::set_permissions(&path, fs::Permissions::from_mode(0o755))?; + } + Ok(path) +} + +/// A generated program refused for its directory's mount: Linux answers a +/// `noexec` mount with `EACCES`, and that alone is an absence; ToyOS has none. +fn refused(why: String, permission_denied: bool) -> sys::Refused { + if cfg!(target_os = "linux") && permission_denied { + sys::Refused::Absent(format!("the directory's mount runs no program: {why}")) + } else { + sys::Refused::Failed(why) + } +} + +fn spawn_wait(path: &Path) -> Result<(), sys::Refused> { + let status = Command::new(path) + .stdin(Stdio::null()) + .stdout(Stdio::null()) + .stderr(Stdio::null()) + .status() + .map_err(|e| refused(format!("spawn {}: {e}", path.display()), e.kind() == std::io::ErrorKind::PermissionDenied))?; + if status.success() { Ok(()) } else { Err(sys::Refused::Failed(format!("{} ended {status}", path.display()))) } +} + +// ToyOS's C library is no part of std there; a Rust program calling it links +// the sysroot's archive of it, built for linking beside std +// (`build/libc.rs`). Linux's is musl, which std already links. +#[cfg_attr(target_os = "toyos", link(name = "toyos_c", kind = "static"))] +extern "C" { + fn posix_spawn( + pid: *mut i32, + path: *const c_char, + file_actions: *const c_void, + attributes: *const c_void, + argv: *const *const c_char, + envp: *const *const c_char, + ) -> c_int; + fn waitpid(pid: i32, status: *mut c_int, options: c_int) -> i32; +} + +/// C's `posix_spawn` with no file actions and no attributes, then `waitpid`: +/// the child inherits this process's descriptors as they are. +fn c_spawn_wait(path: &CString, argv: &[&CString]) -> Result<(), sys::Refused> { + let mut args: Vec<*const c_char> = argv.iter().map(|a| a.as_ptr()).collect(); + args.push(std::ptr::null()); + let envp: [*const c_char; 1] = [std::ptr::null()]; + let mut pid = 0i32; + // SAFETY: every pointer names a NUL-terminated string or the null that + // ends its array, live across the call. + let err = unsafe { posix_spawn(&mut pid, path.as_ptr(), std::ptr::null(), std::ptr::null(), args.as_ptr(), envp.as_ptr()) }; + if err != 0 { + const EACCES: c_int = 13; + return Err(refused(format!("posix_spawn answered {err}"), err == EACCES)); + } + let mut status = 0; + // SAFETY: `status` is a valid out-pointer and `pid` this process's child. + let reaped = unsafe { waitpid(pid, &mut status, 0) }; + if reaped != pid { + return Err(sys::Refused::Failed(format!("waitpid answered {reaped}: {}", std::io::Error::last_os_error()))); + } + if status != 0 { Err(sys::Refused::Failed(format!("the child's wait status was {status:#x}"))) } else { Ok(()) } +} + +pub fn suite() { + let memory = crate::files::memory_targets().remove(0).dir; + let dir = match Scratch::new(memory) { + Ok(d) => d, + Err(e) => return refuse("proc", format!("no scratch directory under {memory}: {e}")), + }; + let (tiny, large) = match (write_program(&dir, "tiny", 0), write_program(&dir, "large", LARGE)) { + (Ok(t), Ok(l)) => (t, l), + (Err(e), _) | (_, Err(e)) => return refuse("proc", format!("the generated programs: {e}")), + }; + let size = |p: &Path| fs::metadata(p).map(|m| m.len().to_string()).unwrap_or_default(); + + // The tiny program spawned by `Command` and waited for: 200 after 20. + let spawn = |p: &Path| spawn_wait(p).map_err(sys::Refused::why); + if let Err(refused) = spawn_wait(&tiny) { + refused.report("proc.spawn_wait.tiny"); + } else { + each("proc.spawn_wait.tiny", 20, 200, &[("file_bytes", size(&tiny))], |_| spawn(&tiny)); + + // The same program with 32 MiB of data it never reads: 100 after 10. + each("proc.spawn_wait.large", 10, 100, &[("file_bytes", size(&large))], |_| spawn(&large)); + + // A hundred spawn-and-waits back to back, ns per hundred: 10 after 1. + each("proc.spawn_wait_loop.100", 1, 10, &[("spawns", "100".into())], |_| { + (0..100).try_for_each(|_| spawn(&tiny)) + }); + + // C's `posix_spawn` and `waitpid` of the tiny program: 200 after 20. + let c_tiny = CString::new(tiny.to_string_lossy().as_bytes()).expect("a path without NUL"); + match c_spawn_wait(&c_tiny, &[&c_tiny]) { + Ok(()) => each("proc.posix_spawn_wait.tiny", 20, 200, &[], |_| { + c_spawn_wait(&c_tiny, &[&c_tiny]).map_err(sys::Refused::why) + }), + Err(refused) => refused.report("proc.posix_spawn_wait.tiny"), + } + } + + // This program, std and all, as `osbench nop`, by C's `posix_spawn`, to + // set beside `process.spawn_wait`, std's `Command` of the same: 100 after 10. + match std::env::current_exe() { + Ok(exe) => { + let path = CString::new(exe.to_string_lossy().as_bytes()).expect("a path without NUL"); + let nop = CString::new("nop").expect("no NUL"); + match c_spawn_wait(&path, &[&path, &nop]) { + Ok(()) => each("proc.posix_spawn_wait.std", 10, 100, &[("file_bytes", size(&exe))], |_| { + c_spawn_wait(&path, &[&path, &nop]).map_err(sys::Refused::why) + }), + Err(refused) => refused.report("proc.posix_spawn_wait.std"), + } + } + Err(e) => refuse("proc.posix_spawn_wait.std", e), + } + + // `thread::spawn` and `join` of an empty closure with std's default stack + // and with a 64 KiB one asked for: 1,000 after 50 each. + for (name, stack) in [("default", None), ("stack64k", Some(64 << 10))] { + let asked = stack.map_or("default".to_string(), |s: usize| s.to_string()); + each( + &format!("thread.spawn_join.{name}"), + 50, + 1000, + &[("stack_asked", asked), ("stack_floor", sys::STACK_FLOOR.into())], + |_| { + let builder = match stack { + Some(bytes) => thread::Builder::new().stack_size(bytes), + None => thread::Builder::new(), + }; + let handle = io("spawn", builder.spawn(|| {}))?; + handle.join().map_err(|_| "an empty thread panicked".to_string()) + }, + ); + } +} diff --git a/tests/guest/osbench/src/report.rs b/tests/guest/osbench/src/report.rs index 455dab0c6a7..3d45bba87df 100644 --- a/tests/guest/osbench/src/report.rs +++ b/tests/guest/osbench/src/report.rs @@ -1,4 +1,4 @@ -//! The one output format: every line starts `osbench v=1 os=` and is +//! The one output format: every line starts `osbench v=2 os=` and is //! otherwise `key=value` words, so a run's stdout is its data. use std::sync::atomic::{AtomicBool, Ordering}; @@ -13,7 +13,7 @@ pub fn word(value: impl std::fmt::Display) -> String { } fn emit(body: &str) { - println!("osbench v=1 os={OS} {body}"); + println!("osbench v=2 os={OS} {body}"); } /// A fact about the machine or the run that its numbers depend on. @@ -38,12 +38,31 @@ pub fn unmeasured(bench: &str, why: &str, extra: &[(&str, String)]) { emit(&line); } +/// A facility this system does not offer, which is a result and not a +/// failure: its line says what was asked and what the system answered. +pub fn unsupported(bench: &str, why: impl std::fmt::Display) { + emit(&format!("bench={bench} unsupported={}", word(why))); +} + +/// An investigation's record, not a distribution: ` key=value...`. +pub fn note(what: &str, fields: &[(&str, String)]) { + let mut line = format!("note={what}"); + for (key, value) in fields { + line.push_str(&format!(" {key}={}", word(value))); + } + emit(&line); +} + pub fn any_refused() -> bool { REFUSED.load(Ordering::Relaxed) } /// One measured distribution, by nearest rank. A percentile the sample count /// cannot resolve prints `-`: p99 needs 100 samples and p99.9 a thousand. +/// `mhz` is the reporting CPU's clock read just after the measurement +/// (`clock::mhz`), and `mhz_settled` the clock the benchmark's warm-up +/// reached before it (`clock::settle`), so every number says the clock it +/// was taken at. pub fn result(bench: &str, unit: &str, samples: &mut [u64], extra: &[(&str, String)]) { if samples.is_empty() { refuse(bench, "no samples"); @@ -66,6 +85,11 @@ pub fn result(bench: &str, unit: &str, samples: &mut [u64], extra: &[(&str, Stri for (key, value) in extra { line.push_str(&format!(" {key}={}", word(value))); } + match crate::clock::take_settled() { + 0 => {} + settled => line.push_str(&format!(" mhz_settled={settled}")), + } + line.push_str(&format!(" mhz={}", crate::clock::mhz())); emit(&line); } diff --git a/tests/guest/osbench/src/storage.rs b/tests/guest/osbench/src/storage.rs new file mode 100644 index 00000000000..c44b91133ae --- /dev/null +++ b/tests/guest/osbench/src/storage.rs @@ -0,0 +1,99 @@ +//! Persistent storage, each system on the medium it has, so **not like for +//! like**: what these say is what a durable write costs on the storage a +//! measured boot has, never which kernel is faster. +//! +//! On a ToyOS benchcase boot that is the boot USB stick's `TOYOS-LOG` +//! partition, FAT32, through the LOG file server and usbd: the boot has no +//! DATA partition, so `/home` and `/state` are memory (`files`'s `served`), +//! and the stick's other volumes are read-only. On Linux it is a directory in +//! the runner's home, on whatever disk and filesystem hold it, which the +//! conditions name. Every file here is removed at the end; the most alive at +//! once is under 10 MiB, inside what the log volume leaves free. + +use std::fs::{self, File, OpenOptions}; +use std::io::{Read, Seek, SeekFrom, Write}; + +use crate::files::Scratch; +use crate::measure::{each, io, throughput}; +use crate::report::{condition, refuse}; +use crate::sys; + +const MIB: usize = 1 << 20; + +pub fn suite() { + let Some((dir, medium)) = sys::persistent_dir() else { + return refuse("persist", "no persistent directory to write in"); + }; + condition("persist.medium", medium); + let scratch = match Scratch::new(&dir) { + Ok(s) => s, + Err(e) => return refuse("persist", format!("no scratch directory: {e}")), + }; + let block = [0x6bu8; 4096]; + + // 4 KiB written over the start of a 1 MiB file, then `sync_all`: 100 after 5. + let file = scratch.at("over"); + let made = (|| -> std::io::Result { + fs::write(&file, vec![1u8; MIB])?; + OpenOptions::new().read(true).write(true).open(&file) + })(); + match made { + Ok(mut f) => { + each("persist.write_4k_fsync", 5, 100, &[], |_| { + io("seek", f.seek(SeekFrom::Start(0)))?; + io("write", f.write_all(&block))?; + io("fsync", f.sync_all()) + }); + // `sync_all` of the same file with nothing new in it: 200 after 10. + each("persist.fsync_clean", 10, 200, &[], |_| io("fsync", f.sync_all())); + } + Err(e) => refuse("persist.write_4k_fsync", e), + } + + // 4 KiB appended, then `sync_data`: 100 after 5, so the file grows by 420 KiB. + match OpenOptions::new().create(true).append(true).open(scratch.at("log")) { + Ok(mut f) => each("persist.append_4k_fsync", 5, 100, &[], |_| { + io("write", f.write_all(&block))?; + io("fsync", f.sync_data()) + }), + Err(e) => refuse("persist.append_4k_fsync", e), + } + + // A new file, 4 KiB written and `sync_all`ed, closed and removed: 50 + // after 5. The directory is not synced. + let fresh = scratch.at("fresh"); + each("persist.create_fsync_unlink", 5, 50, &[], |_| { + let mut f = io("create", File::create(&fresh))?; + io("write", f.write_all(&block))?; + io("fsync", f.sync_all())?; + drop(f); + io("unlink", fs::remove_file(&fresh)) + }); + + // 8 MiB written in 1 MiB calls to a new file and `sync_all`ed: MB/s + // including the sync, three rounds after one; then read back in 1 MiB + // calls, which both systems answer from their caches. + let seq = scratch.at("seq"); + let chunk = vec![0x2du8; MIB]; + let extra = [("file_bytes", (8 * MIB).to_string()), ("call_bytes", MIB.to_string())]; + throughput("persist.seq_write_fsync", 3, 8 * MIB as u64, &extra, || { + let mut f = io("create", File::create(&seq))?; + for _ in 0..8 { + io("write", f.write_all(&chunk))?; + } + io("fsync", f.sync_all()) + }); + let mut buf = vec![0u8; MIB]; + throughput("persist.seq_read_cached", 3, 8 * MIB as u64, &extra, || { + let mut f = io("open", File::open(&seq))?; + let mut got = 0; + loop { + match io("read", f.read(&mut buf))? { + 0 => break, + n => got += n, + } + } + if got == 8 * MIB { Ok(()) } else { Err(format!("read {got} bytes")) } + }); + let _ = fs::remove_file(&seq); +} diff --git a/tests/guest/osbench/src/sys/linux.rs b/tests/guest/osbench/src/sys/linux.rs index f20957bd0a3..739ee9c7371 100644 --- a/tests/guest/osbench/src/sys/linux.rs +++ b/tests/guest/osbench/src/sys/linux.rs @@ -301,3 +301,285 @@ pub fn autogroup_enabled() -> bool { pub fn autogroup() -> String { read("/proc/self/autogroup").and_then(|s| s.split_whitespace().next().map(str::to_string)).unwrap_or_default() } + +/// This process's own accounting, from `getrusage`: Linux counts no +/// syscalls for a process to read. +pub fn counts() -> super::Counts { + // SAFETY: a zeroed rusage is a valid out-buffer. + let mut usage: libc::rusage = unsafe { std::mem::zeroed() }; + // SAFETY: `usage` is a valid out-pointer. + assert_eq!(unsafe { libc::getrusage(libc::RUSAGE_SELF, &mut usage) }, 0); + super::Counts { + switches: Some((usage.ru_nvcsw + usage.ru_nivcsw) as u64), + faults: Some((usage.ru_minflt + usage.ru_majflt) as u64), + } +} + +/// `CLOCK_MONOTONIC` is the clock Linux's own timestamps use. +pub fn log_time_ns(monotonic: u64) -> u64 { + monotonic +} + +/// Linux gives a thread the stack its builder asks for. +pub const STACK_FLOOR: &str = "none"; + +/// What [`current_cpu`] names a CPU by, for the fields that print one. +pub const CPU_NAMING: &str = "cpu"; + +pub fn protect(ptr: *mut u8, len: usize, writable: bool) -> Result<(), super::Refused> { + let prot = if writable { libc::PROT_READ | libc::PROT_WRITE } else { libc::PROT_READ }; + // SAFETY: the caller's mapping; a protection change moves no memory. + match unsafe { libc::mprotect(ptr.cast(), len, prot) } { + 0 => Ok(()), + _ => Err(super::Refused::Failed(format!("mprotect: {}", std::io::Error::last_os_error()))), + } +} + +/// # Safety +/// `ptr` and `len` lie inside one mapping from [`map_anon`] that nothing +/// reaches in that range afterwards. +pub unsafe fn unmap_part(ptr: *mut u8, len: usize) -> Result<(), super::Refused> { + // SAFETY: as the caller promises. + match unsafe { libc::munmap(ptr.cast(), len) } { + 0 => Ok(()), + _ => Err(super::Refused::Failed(format!("munmap: {}", std::io::Error::last_os_error()))), + } +} + +/// An anonymous mapping that faults in 4 KiB pages: transparent huge pages +/// are refused for it. +pub fn map_anon_4k(len: usize) -> *mut u8 { + let ptr = map_anon(len); + // SAFETY: an advice changes no contents. + unsafe { libc::madvise(ptr.cast(), len, libc::MADV_NOHUGEPAGE) }; + ptr +} + +/// IPC between this process and a child: a Unix stream socket pair, the +/// child's end its stdin; a descriptor rides as `SCM_RIGHTS`. +pub mod ipc { + use std::io::{self, Read, Write}; + use std::os::fd::{AsRawFd, FromRawFd, OwnedFd}; + use std::os::linux::net::SocketAddrExt; + use std::os::unix::net::{SocketAddr, UnixListener, UnixStream}; + use std::process::{Child, Command, Stdio}; + + pub struct Peer(UnixStream); + + /// What a message carries beside its bytes: one end of a pipe. + pub type Token = OwnedFd; + + /// A stream carries a message of any length as one write. + pub fn frames(_len: usize) -> usize { + 1 + } + + const CONTROL: usize = 64; + + impl Peer { + pub fn send(&self, data: &[u8]) -> io::Result<()> { + (&self.0).write_all(data) + } + + pub fn recv(&self, buf: &mut [u8]) -> io::Result<()> { + (&self.0).read_exact(buf) + } + + /// `data` and `token` in one `sendmsg`, then this process's copy + /// closed, so the descriptor ends up the peer's alone as a ToyOS + /// handle moved would. + pub fn send_with(&self, data: &[u8], token: Token) -> io::Result<()> { + let mut control = [0u8; CONTROL]; + let mut iov = libc::iovec { iov_base: data.as_ptr() as *mut _, iov_len: data.len() }; + // SAFETY: a zeroed msghdr is an empty one. + let mut msg: libc::msghdr = unsafe { std::mem::zeroed() }; + msg.msg_iov = &mut iov; + msg.msg_iovlen = 1; + msg.msg_control = control.as_mut_ptr().cast(); + // SAFETY: CMSG_SPACE is arithmetic. + msg.msg_controllen = unsafe { libc::CMSG_SPACE(size_of::() as u32) } as _; + // SAFETY: `msg`'s control buffer holds one header and one int, + // which CMSG_SPACE just sized. + unsafe { + let header = libc::CMSG_FIRSTHDR(&msg); + (*header).cmsg_level = libc::SOL_SOCKET; + (*header).cmsg_type = libc::SCM_RIGHTS; + (*header).cmsg_len = libc::CMSG_LEN(size_of::() as u32) as _; + libc::CMSG_DATA(header).cast::().write_unaligned(token.as_raw_fd()); + } + // SAFETY: every pointer in `msg` is live for the call. + let sent = unsafe { libc::sendmsg(self.0.as_raw_fd(), &msg, 0) }; + if sent < 0 { + return Err(io::Error::last_os_error()); + } + if sent as usize != data.len() { + return Err(io::Error::other(format!("sendmsg sent {sent} of {} bytes", data.len()))); + } + drop(token); + Ok(()) + } + + pub fn recv_with(&self, buf: &mut [u8]) -> io::Result { + let mut control = [0u8; CONTROL]; + let mut iov = libc::iovec { iov_base: buf.as_mut_ptr().cast(), iov_len: buf.len() }; + // SAFETY: a zeroed msghdr is an empty one. + let mut msg: libc::msghdr = unsafe { std::mem::zeroed() }; + msg.msg_iov = &mut iov; + msg.msg_iovlen = 1; + msg.msg_control = control.as_mut_ptr().cast(); + msg.msg_controllen = CONTROL as _; + // SAFETY: every pointer in `msg` is live for the call. + let got = unsafe { libc::recvmsg(self.0.as_raw_fd(), &mut msg, libc::MSG_CMSG_CLOEXEC | libc::MSG_WAITALL) }; + if got < 0 { + return Err(io::Error::last_os_error()); + } + if got as usize != buf.len() { + return Err(io::Error::other(format!("recvmsg read {got} of {} bytes", buf.len()))); + } + // SAFETY: the kernel wrote `msg_controllen` bytes of headers. + unsafe { + let header = libc::CMSG_FIRSTHDR(&msg); + if header.is_null() || (*header).cmsg_type != libc::SCM_RIGHTS { + return Err(io::Error::other("no descriptor came")); + } + let fd = libc::CMSG_DATA(header).cast::().read_unaligned(); + Ok(OwnedFd::from_raw_fd(fd)) + } + } + } + + pub fn token() -> io::Result { + let (read, _write) = std::io::pipe()?; + Ok(OwnedFd::from(read)) + } + + pub fn start_server(exe: &std::path::Path) -> io::Result<(Child, Peer)> { + let (ours, theirs) = UnixStream::pair()?; + let child = Command::new(exe).arg("ipc-serve").stdin(Stdio::from(OwnedFd::from(theirs))).spawn()?; + Ok((child, Peer(ours))) + } + + /// The child's end, which its parent made its stdin. + pub fn served() -> io::Result { + // SAFETY: the parent made descriptor 0 a socket this process owns + // and nothing else here reads stdin. + Ok(Peer(UnixStream::from(unsafe { OwnedFd::from_raw_fd(0) }))) + } + + /// A listening socket in the abstract namespace, which this process both + /// connects to and accepts on, for timing a connection's setup alone. + pub struct Rendezvous { + listener: UnixListener, + addr: SocketAddr, + } + + impl Rendezvous { + pub fn new() -> io::Result { + let addr = SocketAddr::from_abstract_name(format!("osbench-{}", std::process::id()))?; + let listener = UnixListener::bind_addr(&addr)?; + Ok(Self { listener, addr }) + } + + pub fn connect_accept(&self) -> io::Result<()> { + let client = UnixStream::connect_addr(&self.addr)?; + let (server, _) = self.listener.accept()?; + drop((client, server)); + Ok(()) + } + } +} + +/// The mount holding `path`, off `/proc/self/mountinfo`: its filesystem +/// type, its source and its options. +fn mount_of(path: &str) -> Option<(String, String, String)> { + let mounts = fs::read_to_string("/proc/self/mountinfo").ok()?; + // `id parent major:minor root mountpoint options... - fstype source superoptions` + mounts + .lines() + .filter_map(|line| { + let (left, right) = line.split_once(" - ")?; + let mut left = left.split_whitespace(); + let point = left.nth(4)?; + let options = left.next()?; + let mut right = right.split_whitespace(); + let (fstype, source) = (right.next()?, right.next()?); + let under = path == point || point == "/" || path.starts_with(&format!("{point}/")); + under.then(|| (point.len(), (fstype.to_string(), source.to_string(), options.to_string()))) + }) + .max_by_key(|(len, _)| *len) + .map(|(_, mount)| mount) +} + +/// How `dir` is mounted, for a condition: its filesystem and options. +pub fn mount_options(dir: &str) -> String { + mount_of(dir).map_or_else(|| "unknown".into(), |(fstype, _, options)| format!("{fstype} {options}")) +} + +/// The runner's home, and the filesystem and disk model holding it; the +/// path itself names the user and is never printed. +pub fn persistent_dir() -> Option<(String, String)> { + let home = std::env::var("HOME").ok()?; + let (fstype, source, _) = mount_of(&home)?; + // btrfs reports an anonymous `0:NN` that names no block device; its + // source device's own number does. + let sysfs = |devno: String| fs::canonicalize(format!("/sys/dev/block/{devno}")).ok(); + let device = device_number_of(&home).and_then(sysfs).or_else(|| { + use std::os::unix::fs::{FileTypeExt, MetadataExt}; + let meta = fs::metadata(source.strip_prefix("/dev/").map(|_| source.as_str())?).ok()?; + let rdev = meta.file_type().is_block_device().then(|| meta.rdev())?; + sysfs(format!("{}:{}", libc::major(rdev), libc::minor(rdev))) + }); + let Some(device) = device else { + return Some((home, format!("{fstype}, on no block device"))); + }; + let (disk, mapped) = backing_disk(device); + let model = read(&disk.join("device/model").to_string_lossy()).unwrap_or_else(|| "unknown".into()); + let name = disk.file_name().map(|n| n.to_string_lossy().into_owned()).unwrap_or_default(); + let kind = [("nvme", "NVMe"), ("sd", "SCSI, SATA or USB"), ("mmcblk", "MMC"), ("vd", "virtio")] + .iter() + .find(|(prefix, _)| name.starts_with(prefix)) + .map_or("other", |(_, kind)| kind); + let through = if mapped { " through device-mapper" } else { "" }; + // The device's own name is never printed: an installer or a user chose + // a mapper's (`luks-`, a volume group named for the host). + Some((home, format!("{fstype}{through}, {kind} disk, model {model}"))) +} + +/// The `major:minor` of the filesystem holding `path`, off mountinfo's third +/// field for the deepest mount over it. +fn device_number_of(path: &str) -> Option { + let mounts = fs::read_to_string("/proc/self/mountinfo").ok()?; + mounts + .lines() + .filter_map(|line| { + let mut fields = line.split_whitespace(); + let devno = fields.nth(2)?; + let point = fields.nth(1)?; + let under = path == point || point == "/" || path.starts_with(&format!("{point}/")); + under.then(|| (point.len(), devno.to_string())) + }) + .max_by_key(|(len, _)| *len) + .map(|(_, devno)| devno) +} + +/// The whole disk under a sysfs block device: through each device-mapper +/// layer's first `slaves` entry, then from a partition to its disk; and +/// whether a mapper was crossed. +fn backing_disk(mut device: std::path::PathBuf) -> (std::path::PathBuf, bool) { + let mut mapped = false; + while let Some(lower) = fs::read_dir(device.join("slaves")).ok().and_then(|mut d| d.next()).and_then(Result::ok) { + match fs::canonicalize(lower.path()) { + Ok(next) => { + device = next; + mapped = true; + } + Err(_) => break, + } + } + if device.join("partition").exists() { + if let Some(parent) = device.parent() { + device = parent.to_path_buf(); + } + } + (device, mapped) +} diff --git a/tests/guest/osbench/src/sys/mod.rs b/tests/guest/osbench/src/sys/mod.rs index 0851bbfd84e..d3c8105fd2d 100644 --- a/tests/guest/osbench/src/sys/mod.rs +++ b/tests/guest/osbench/src/sys/mod.rs @@ -1,8 +1,9 @@ //! What std does not offer portably, as each OS offers it: the cheapest -//! syscall, a futex, a clock every process shares, anonymous mappings and the -//! machine's conditions. Both modules export the same names; Linux adds -//! affinity, which ToyOS has none of, and the readers of its cgroup and -//! autogroup. +//! syscall, a futex, a clock every process shares, anonymous mappings, IPC +//! between processes, a process's own accounting and the machine's +//! conditions. Both modules export the same names; Linux adds affinity, +//! which ToyOS has none of, and the readers of its cgroup and autogroup, and +//! ToyOS the diagnostics the tail group reads (`diag`). #[cfg(target_os = "linux")] #[path = "linux.rs"] @@ -14,6 +15,58 @@ mod imp; pub use imp::*; +/// What a process can read of its own accounting: Linux its context +/// switches and page faults; ToyOS nothing. +pub struct Counts { + pub switches: Option, + pub faults: Option, +} + +impl Counts { + /// The accounting from `before` to now, per one of `ops` operations, + /// in hundredths, as result fields. + pub fn per_op(before: &Counts, ops: u64) -> Vec<(&'static str, String)> { + let now = counts(); + let ops = ops.max(1); + let hundredths = |d: u64| format!("{}.{:02}", d / ops, d * 100 / ops % 100); + let mut fields = Vec::new(); + if let (Some(a), Some(b)) = (before.switches, now.switches) { + fields.push(("switches_per_op", hundredths(b - a))); + } + if let (Some(a), Some(b)) = (before.faults, now.faults) { + fields.push(("faults_per_op", hundredths(b - a))); + } + fields + } +} + +/// Why a call did not do its work: a facility the system does not offer, by +/// the one answer that says so, or any other failure. +#[derive(Clone)] +pub enum Refused { + Absent(String), + Failed(String), +} + +impl Refused { + /// Report `bench` as unsupported for an absence, and refused for anything + /// else. + pub fn report(self, bench: &str) { + match self { + Refused::Absent(why) => crate::report::unsupported(bench, why), + Refused::Failed(why) => crate::report::refuse(bench, why), + } + } + + /// What it says, whichever it is, for a call that already succeeded once + /// and so is failing now. + pub fn why(self) -> String { + match self { + Refused::Absent(why) | Refused::Failed(why) => why, + } + } +} + /// A whole anonymous read-write mapping, unmapped on drop. pub struct Mapping { ptr: *mut u8, diff --git a/tests/guest/osbench/src/sys/toyos.rs b/tests/guest/osbench/src/sys/toyos.rs index 44df6eef0ee..4c1accefb30 100644 --- a/tests/guest/osbench/src/sys/toyos.rs +++ b/tests/guest/osbench/src/sys/toyos.rs @@ -59,3 +59,318 @@ pub unsafe fn unmap(ptr: *mut u8, len: usize) { /// Nothing a program can read: the kernel's frequency request and the /// machine's power source are the boot log's and the operator's to record. pub fn conditions() {} + +/// Nothing: a process's handle to itself carries no `READ`, which reading +/// its accounting takes (`kernel/src/loader/start.rs`'s `own_handle`). The +/// kernel's exit record of each job counts its syscalls instead. +pub fn counts() -> super::Counts { + super::Counts { switches: None, faults: None } +} + +/// A log line's time for a reading of [`monotonic_ns`]: the kernel log's +/// stamps count from the counter's zero, not from boot. +pub fn log_time_ns(monotonic: u64) -> u64 { + monotonic + toyos_abi::clock::page().stamp_at_boot +} + +/// ToyOS raises every thread stack to std's floor (`sys/thread.rs`'s +/// `DEFAULT_MIN_STACK_SIZE`), whatever the builder asks. +pub const STACK_FLOOR: &str = "2MiB"; + +/// What [`current_cpu`] names a CPU by, for the fields that print one. +pub const CPU_NAMING: &str = "apic"; + +/// Native IPC: a connection through a port, between this process and a child +/// it endows the port's acceptor. +pub mod ipc { + use std::io; + use std::os::toyos::process::CommandExt; + use std::process::{Child, Command, Stdio}; + + use toyos::endow::{Endowments, FromHandle}; + use toyos::ipc::{Connection, MAX_FRAME_LEN}; + use toyos::port::{self, Acceptor}; + use toyos::{OwnedHandle, Pipe}; + + const LABEL: &str = "osbench-ipc"; + const NAME: &str = "osbench"; + const FRAME: usize = MAX_FRAME_LEN as usize; + + /// One end of a connection. A message longer than one frame + /// ([`MAX_FRAME_LEN`]) goes as consecutive frames: a ToyOS connection + /// frames each message, and a frame carries at most that much. + pub struct Peer(Connection); + + /// What a message carries beside its bytes: one end of a pipe. + pub type Token = Pipe; + + fn failed(what: &str, e: impl std::fmt::Debug) -> io::Error { + io::Error::other(format!("{what}: {e:?}")) + } + + /// Frames one message takes. + pub fn frames(len: usize) -> usize { + len.div_ceil(FRAME).max(1) + } + + impl Peer { + pub fn send(&self, data: &[u8]) -> io::Result<()> { + if data.is_empty() { + return self.0.send_bytes(1, data).map_err(|e| failed("send", e)); + } + for chunk in data.chunks(FRAME) { + self.0.send_bytes(1, chunk).map_err(|e| failed("send", e))?; + } + Ok(()) + } + + pub fn recv(&self, buf: &mut [u8]) -> io::Result<()> { + let mut at = 0; + loop { + let header = self.0.recv_header().map_err(|e| failed("receive", e))?; + at += self.0.recv_bytes(&header, &mut buf[at..]).map_err(|e| failed("receive", e))?; + if at >= buf.len() { + return Ok(()); + } + } + } + + /// One frame of `data` (at most one frame's worth) and `token`, moved. + pub fn send_with(&self, data: &[u8], token: Token) -> io::Result<()> { + self.0.send_bytes_with(1, data, [OwnedHandle::from(token)]).map_err(|e| failed("send", e)) + } + + pub fn recv_with(&self, buf: &mut [u8]) -> io::Result { + let header = self.0.recv_header().map_err(|e| failed("receive", e))?; + self.0.recv_bytes(&header, buf).map_err(|e| failed("receive", e))?; + let [raw] = self.0.recv_handles_exact::<1>(&header).ok_or_else(|| io::Error::other("no handle came"))?; + // SAFETY: the kernel moved this handle into this process's table + // for this frame alone, and the peer sends only pipe ends. + Ok(unsafe { Pipe::from_handle(raw) }) + } + } + + pub fn token() -> io::Result { + let (read, _write) = toyos::pipe_pair().map_err(|e| failed("pipe", e))?; + Ok(read) + } + + /// `exe ipc-serve`, endowed a fresh port's acceptor, and this process's + /// connection to it. + pub fn start_server(exe: &std::path::Path) -> io::Result<(Child, Peer)> { + let (acceptor, connector) = port::create().map_err(|e| failed("port", e))?; + let names = toyos::namespace::build().add(NAME, &connector).finish().map_err(|e| failed("namespace", e))?; + let conn = names.open(NAME).map_err(|e| failed("connect", e))?; + let child = Command::new(exe) + .arg("ipc-serve") + .endow(LABEL, acceptor.into_raw().0) + .stdin(Stdio::null()) + .spawn()?; + Ok((child, Peer(conn))) + } + + /// The child's end: the connection its parent made to the port it was + /// endowed. + pub fn served() -> io::Result { + let acceptor: Acceptor = Endowments::get().take(LABEL).ok_or_else(|| io::Error::other("no port endowed"))?; + acceptor.accept().map(Peer).map_err(|e| failed("accept", e)) + } + + /// A port this process both connects to and accepts on, for timing a + /// connection's setup alone. + pub struct Rendezvous { + acceptor: Acceptor, + names: toyos::namespace::Namespace, + } + + impl Rendezvous { + pub fn new() -> io::Result { + let (acceptor, connector) = port::create().map_err(|e| failed("port", e))?; + let names = toyos::namespace::build().add(NAME, &connector).finish().map_err(|e| failed("namespace", e))?; + Ok(Self { acceptor, names }) + } + + /// Open a connection and accept it; both ends close on return. + pub fn connect_accept(&self) -> io::Result<()> { + let client = self.names.open(NAME).map_err(|e| failed("connect", e))?; + let server = self.acceptor.accept().map_err(|e| failed("accept", e))?; + drop((client, server)); + Ok(()) + } + } +} + +/// What the tail group reads to say where a late wake's time went, through +/// the runner's capability: each CPU's firmware interrupts and clock, the +/// scheduler's diary and the roster's names. Read-only observation rights; +/// `None` where this boot did not grant them. +pub mod diag { + use std::collections::BTreeMap; + + use toyos::endow::{Endowments, SYSCAP_LABEL}; + use toyos::syscap::{SysCap, TraceCursor}; + use toyos_abi::counters::{Counter, RawRecord, Record}; + use toyos_abi::syscall::{SYSINFO_ENTRY_SIZE, SYSINFO_HEADER_SIZE}; + use toyos_abi::trace::TraceRecord; + use toyos_trace::{Entry, Event}; + + pub struct Diag { + cap: SysCap, + cursor: Option>>, + } + + /// One CPU's counters, by the kernel's index of the CPU and the APIC id + /// it read off itself, which is what [`current_cpu`](super::current_cpu) + /// names it by. + #[derive(Clone)] + pub struct CpuCounts { + pub cpu: u32, + pub apic: u32, + pub smi: Option, + pub aperf: Option, + pub mperf: Option, + pub kicks: Option, + } + + pub fn open() -> Option { + let cap: SysCap = Endowments::get().take(SYSCAP_LABEL)?; + let cursor = cap.trace_cursor_words().ok().map(|n| TraceCursor::new(vec![0u64; n])); + Some(Diag { cap, cursor }) + } + + impl Diag { + /// Every CPU's counters, or why the read failed. + pub fn counters(&self) -> Result, String> { + let mut raw = vec![RawRecord::EMPTY; toyos_abi::syscall::cpu_count() as usize]; + let read = self.cap.counters(&mut raw).map_err(|e| format!("the counters read was refused: {e:?}"))?; + raw[..read] + .iter() + .map(|r| { + let r = Record::decode(r).map_err(|e| format!("a counters record did not decode: {e:?}"))?; + Ok(CpuCounts { + cpu: r.cpu, + apic: r.hardware_id, + smi: r.get(Counter::Smi), + aperf: r.get(Counter::Aperf), + mperf: r.get(Counter::Mperf), + kicks: r.get(Counter::Kicks), + }) + }) + .collect() + } + + pub fn has_diary(&self) -> bool { + self.cursor.is_some() + } + + /// Every diary record since the last read, decoded, with its time as + /// nanoseconds since boot, oldest first; how many the rings had + /// overwritten before this read reached them; and why the read ended + /// early, if it did. + pub fn diary(&mut self) -> (Vec<(u64, Entry)>, u64, Option) { + let Some(cursor) = self.cursor.as_mut() else { return (Vec::new(), 0, None) }; + let page = toyos_abi::clock::page(); + let lost_before = cursor.lost(); + let mut out = Vec::new(); + let mut buf = vec![TraceRecord::EMPTY; 4096]; + let mut failed = None; + loop { + let n = match self.cap.trace(cursor, &mut buf) { + Ok(n) => n, + Err(e) => { + failed = Some(format!("the diary read was refused: {e:?}")); + break; + } + }; + for raw in &buf[..n] { + if let Ok(entry) = Entry::decode(raw) { + let since_boot = page.stamp_of(entry.stamp).saturating_sub(page.stamp_at_boot); + out.push((since_boot, entry)); + } + } + if n < buf.len() { + break; + } + } + (out, cursor.lost() - lost_before, failed) + } + + /// Every live thread's process and name, and the CPU nanoseconds it + /// has run, by `(pid, tid)`. + pub fn roster(&self) -> BTreeMap<(u32, u32), (String, u64)> { + const ENTRIES: usize = 2048; + let mut buf = vec![0u8; SYSINFO_HEADER_SIZE + SYSINFO_ENTRY_SIZE * ENTRIES]; + let n = self.cap.roster(&mut buf).min(buf.len()); + let mut rows = BTreeMap::new(); + if n < SYSINFO_HEADER_SIZE { + return rows; + } + let mut pos = SYSINFO_HEADER_SIZE; + while pos + SYSINFO_ENTRY_SIZE <= n { + let u32_at = |at: usize| u32::from_le_bytes(buf[at..at + 4].try_into().expect("four")); + let name = &buf[pos + 32..pos + 60]; + let len = name.iter().position(|&b| b == 0).unwrap_or(name.len()); + let cpu_ns = u64::from_le_bytes(buf[pos + 24..pos + 32].try_into().expect("eight")); + rows.insert((u32_at(pos), u32_at(pos + 4)), (String::from_utf8_lossy(&name[..len]).into_owned(), cpu_ns)); + pos += SYSINFO_ENTRY_SIZE; + } + rows + } + } + + /// An event's short name and its thread, for a note. + pub fn describe(entry: &Entry) -> String { + let what = match entry.event { + Event::Pick => "pick", + Event::Wake => "wake", + Event::Park => "park", + Event::Preempt => "preempt", + Event::Migrate { .. } => "migrate", + Event::Adopt => "adopt", + Event::Retire => "retire", + Event::IdleEnter => "idle", + Event::TimerArm { .. } => "arm", + Event::TimerStop => "stop", + Event::TimerFire => "fire", + Event::TimerFireBurst { .. } => "fires", + Event::Mark { .. } => "mark", + }; + match entry.thread { + Some(t) => format!("{what}:{}/{}", t.pid, t.tid), + None => what.to_string(), + } + } +} + +/// ToyOS has no call that changes a mapping's protection: `toyos_abi` +/// declares none. +pub fn protect(_ptr: *mut u8, _len: usize, _writable: bool) -> Result<(), super::Refused> { + Err(super::Refused::Absent("toyos_abi has no mprotect: a mapping keeps the protection mmap gave it".into())) +} + +/// Give back part of a mapping, which ToyOS refuses: `munmap` takes a whole +/// mapping (`toyos_abi::syscall::munmap`). +/// +/// # Safety +/// `ptr` and `len` lie inside one mapping from [`map_anon`] that nothing +/// reaches in that range afterwards. +pub unsafe fn unmap_part(ptr: *mut u8, len: usize) -> Result<(), super::Refused> { + // SAFETY: as the caller promises. + unsafe { syscall::munmap(ptr, len) }.map_err(|e| match e { + syscall::SyscallError::InvalidArgument => { + super::Refused::Absent("munmap takes a whole mapping and answers InvalidArgument for a part".into()) + } + e => super::Refused::Failed(format!("munmap of a part answered {e:?}")), + }) +} + +/// A mapping whose first touch of each 4 KiB page is what is measured: every +/// ToyOS anonymous mapping is in 2 MiB pages, committed inside `mmap`. +pub fn map_anon_4k(len: usize) -> *mut u8 { + map_anon(len) +} + +/// The one writable persistent volume a benchcase boot has, and what it is. +pub fn persistent_dir() -> Option<(String, String)> { + Some(("/log".into(), "boot USB stick TOYOS-LOG partition, FAT32, LOG file server over usbd mass storage".into())) +} diff --git a/tests/guest/osbench/src/system.rs b/tests/guest/osbench/src/system.rs index 6ffb67e8bac..2c064ffd78d 100644 --- a/tests/guest/osbench/src/system.rs +++ b/tests/guest/osbench/src/system.rs @@ -18,6 +18,7 @@ const MIB: usize = 1 << 20; /// the clock a CPU leaving idle has, not the clock it settles at. pub fn chunk_rate() { chunk(); + crate::clock::settle(); let mut ns: Vec = (0..200) .map(|_| { let t = Instant::now(); @@ -40,6 +41,7 @@ pub fn null_syscall() { ns_since(t) * 1000 / CALLS }; round(); + crate::clock::settle(); let mut picos: Vec = (0..15).map(|_| round()).collect(); result("syscall.null", "ps", &mut picos, &[("calls_per_sample", CALLS.to_string())]); } @@ -54,6 +56,7 @@ pub fn thread_spawn() { for _ in 0..50 { once(); } + crate::clock::settle(); let mut ns: Vec = (0..1000).map(|_| once()).collect(); result("thread.spawn_join", "ns", &mut ns, &[]); } @@ -84,6 +87,7 @@ pub fn process_spawn() { for _ in 0..10 { once()?; } + crate::clock::settle(); (0..100).map(|_| once()).collect() }; match run() { @@ -127,6 +131,7 @@ pub fn pipe_throughput(size: usize) { }; let run = || -> std::io::Result> { round()?; + crate::clock::settle(); (0..7).map(|_| round()).collect() }; match run() { @@ -160,6 +165,7 @@ pub fn anon_memory() { [map, touch, unmap] }; round(); + crate::clock::settle(); let rounds: Vec<[u64; 3]> = (0..10).map(|_| round()).collect(); let per_mib = |pick: &dyn Fn(&[u64; 3]) -> u64| -> Vec { rounds.iter().map(|r| pick(r) / MIBS).collect() }; let extra = [("mapping_bytes", LEN.to_string())]; @@ -181,6 +187,7 @@ pub fn map_unmap_small() { for _ in 0..50 { once(); } + crate::clock::settle(); let mut ns: Vec = (0..2000).map(|_| once()).collect(); result("mem.map_unmap_4k", "ns", &mut ns, &[]); } @@ -209,6 +216,7 @@ pub fn bandwidth() { (LEN as u64) * 1000 / ns_since(t).max(1) }; round(); + crate::clock::settle(); let mut mbps: Vec = (0..7).map(|_| round()).collect(); result(&format!("mem.bw.{name}"), "MB/s", &mut mbps, &huge); }; diff --git a/tests/guest/osbench/src/tail.rs b/tests/guest/osbench/src/tail.rs new file mode 100644 index 00000000000..d29e18fbb4a --- /dev/null +++ b/tests/guest/osbench/src/tail.rs @@ -0,0 +1,320 @@ +//! The tail: where a millisecond goes. Investigation output as much as +//! numbers, so beside each distribution it prints every outlier with its +//! time, in the clock the system's own log uses, and the CPU it ran on. +//! +//! - `tail.wake.periodic.60s`: round 1's periodic wake (500 µs, absolute +//! targets), for 60 s, and every wake later than [`OUTLIER`]. +//! - `tail.stolen.10s`: a spinner per CPU reading the clock for 10 s; a gap +//! between two reads is time the thread did not run, an interrupt's or +//! another thread's or the firmware's. Every gap past [`GAP`] is counted +//! and every one past [`OUTLIER`] printed. +//! - ToyOS only, where the boot grants the observation rights (`diag`): the +//! wake again for 30 s, and at each late one the scheduler's diary around +//! it, every CPU's firmware interrupts (SMI) and clock (APERF/MPERF) either +//! side of the run, and each process's CPU time over it. Linux has no +//! unprivileged equivalent. + +use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::{Arc, Barrier, Mutex}; +use std::thread; +use std::time::{Duration, Instant}; + +use crate::report::{note, result}; +use crate::{ns_since, sys}; + +const PERIOD: Duration = Duration::from_micros(500); +/// A wake this late is printed whole. +const OUTLIER: u64 = 1_000_000; +/// A clock gap this long is counted as time taken from a spinner. +const GAP: u64 = 20_000; +/// The most outliers one run prints. +const PRINTED: usize = 200; + +/// A late wake: when it was due, how late, and the CPU before and after, as +/// [`sys::current_cpu`] names them. +struct Late { + target_ns: u64, + late_ns: u64, + slept_on: u32, + woke_on: u32, +} + +fn log_s(monotonic_ns: u64) -> String { + let at = sys::log_time_ns(monotonic_ns); + format!("{}.{:06}", at / 1_000_000_000, at % 1_000_000_000 / 1000) +} + +pub fn suite() { + #[cfg(target_os = "toyos")] + let diag = sys::diag::open(); + #[cfg(target_os = "toyos")] + let before = diag.as_ref().map(|d| d.counters()); + + let late = periodic("tail.wake.periodic.60s", Duration::from_secs(60), &mut |_| {}); + print_outliers("tail.wake.periodic.60s", &late); + + #[cfg(target_os = "toyos")] + if let (Some(d), Some(before)) = (diag.as_ref(), before) { + counters_over("tail.wake.periodic.60s", before, d); + } + + stolen(Duration::from_secs(10)); + + #[cfg(target_os = "toyos")] + match diag { + Some(d) if d.has_diary() => diary_run(d), + Some(_) => note("tail.diary", &[("absent", "the capability carries no TRACE".into())]), + None => note("tail.diary", &[("absent", "this boot endows no capability".into())]), + } +} + +/// The periodic wake for `span`, its distribution reported as `bench`, and +/// every outlier; `on_late` runs after each outlier is recorded, and the +/// targets start again after it, so one stall is one outlier and what +/// `on_late` spends delays no later wake. Targets and wakes are read on +/// [`sys::monotonic_ns`], the clock `Instant` reads on both systems. A run +/// that has not taken its samples in twice its span ends there, with the +/// samples it has. +fn periodic(bench: &str, span: Duration, on_late: &mut dyn FnMut(&Late)) -> Vec { + const WARMUP: u64 = 200; + let period = PERIOD.as_nanos() as u64; + let samples = (span.as_nanos() as u64 / period) as usize; + let mut lateness = Vec::with_capacity(samples); + let mut outliers = Vec::new(); + let began = sys::monotonic_ns(); + let give_up = began + 2 * span.as_nanos() as u64; + let mut start = began; + let mut i = 0u64; + while lateness.len() < samples && sys::monotonic_ns() < give_up { + i += 1; + let target_ns = start + period * i; + let slept_on = sys::current_cpu(); + if let Some(left) = target_ns.checked_sub(sys::monotonic_ns()) { + thread::sleep(Duration::from_nanos(left)); + } + let woke = sys::monotonic_ns(); + let late_ns = woke.saturating_sub(target_ns); + if i <= WARMUP && start == began { + continue; + } + lateness.push(late_ns); + if late_ns > OUTLIER { + let late = Late { target_ns, late_ns, slept_on, woke_on: sys::current_cpu() }; + on_late(&late); + outliers.push(late); + start = sys::monotonic_ns(); + i = 0; + } + } + let over = outliers.len(); + result( + bench, + "ns", + &mut lateness, + &[ + ("period_ns", period.to_string()), + ("late_over_1ms", over.to_string()), + ("ran_ms", ((sys::monotonic_ns() - began) / 1_000_000).to_string()), + ], + ); + outliers +} + +/// Each outlier as a note, and the spacing between them: a source that +/// strikes on a period shows as gaps that agree. +fn print_outliers(bench: &str, late: &[Late]) { + let (slept, woke) = (format!("slept_{}", sys::CPU_NAMING), format!("woke_{}", sys::CPU_NAMING)); + for (i, l) in late.iter().take(PRINTED).enumerate() { + note( + &format!("{bench}.outlier"), + &[ + ("i", i.to_string()), + ("log_s", log_s(l.target_ns)), + ("late_us", (l.late_ns / 1000).to_string()), + (&slept, l.slept_on.to_string()), + (&woke, l.woke_on.to_string()), + ], + ); + } + let mut gaps: Vec = late.windows(2).map(|w| w[1].target_ns.saturating_sub(w[0].target_ns) / 1000).collect(); + if !gaps.is_empty() { + result(&format!("{bench}.outlier_spacing"), "us", &mut gaps, &[]); + } +} + +/// A spinner per CPU reading the clock for `span`: every gap past [`GAP`] +/// between two of one thread's reads, ns, with the outliers printed. +fn stolen(span: Duration) { + const BENCH: &str = "tail.stolen.10s"; + let threads = crate::cpus(); + let start = Arc::new(Barrier::new(threads)); + let stop = Arc::new(AtomicBool::new(false)); + let found: Arc>> = Arc::new(Mutex::new(Vec::new())); + let spinners: Vec<_> = (0..threads) + .map(|_| { + let (start, stop, found) = (start.clone(), stop.clone(), found.clone()); + thread::spawn(move || { + let mut mine = Vec::new(); + start.wait(); + let mut last = sys::monotonic_ns(); + while !stop.load(Ordering::Relaxed) { + let now = sys::monotonic_ns(); + let gap = now.saturating_sub(last); + if gap > GAP { + mine.push((last, gap, sys::current_cpu())); + } + last = now; + } + found.lock().expect("no spinner panics holding it").extend(mine); + }) + }) + .collect(); + let t = Instant::now(); + thread::sleep(span); + stop.store(true, Ordering::Relaxed); + let ran = ns_since(t); + for s in spinners { + s.join().expect("a spinner panicked"); + } + let mut gaps = std::mem::take(&mut *found.lock().expect("joined")); + gaps.sort_unstable_by_key(|g| g.0); + let stolen: u64 = gaps.iter().map(|g| g.1).sum(); + let permille = stolen * 1000 / (ran * threads as u64).max(1); + let mut lengths: Vec = gaps.iter().map(|g| g.1).collect(); + let extra = [ + ("threads", threads.to_string()), + ("gap_floor_ns", GAP.to_string()), + ("stolen_permille", permille.to_string()), + ("over_1ms", gaps.iter().filter(|g| g.1 > OUTLIER).count().to_string()), + ]; + if lengths.is_empty() { + lengths.push(0); + } + result(BENCH, "ns", &mut lengths, &extra); + for (i, (at, gap, cpu)) in gaps.iter().filter(|g| g.1 > OUTLIER).take(PRINTED).enumerate() { + note( + &format!("{BENCH}.outlier"), + &[ + ("i", i.to_string()), + ("log_s", log_s(*at)), + ("gap_us", (gap / 1000).to_string()), + (sys::CPU_NAMING, cpu.to_string()), + ], + ); + } +} + +/// Each CPU's SMIs, its average clock and its kicks between `before` and now, +/// by the kernel's index of the CPU and its APIC id. +#[cfg(target_os = "toyos")] +fn counters_over(bench: &str, before: Result, String>, d: &sys::diag::Diag) { + let (before, after) = match (before, d.counters()) { + (Ok(before), Ok(after)) => (before, after), + (Err(why), _) | (_, Err(why)) => return note(&format!("{bench}.counters"), &[("failed", why)]), + }; + for b in &after { + let Some(a) = before.iter().find(|a| a.cpu == b.cpu) else { continue }; + let delta = |x: Option, y: Option| match (x, y) { + (Some(x), Some(y)) => Some(y.wrapping_sub(x)), + _ => None, + }; + let shown = |v: Option| v.map_or("-".to_string(), |v| v.to_string()); + let (aperf, mperf) = (delta(a.aperf, b.aperf), delta(a.mperf, b.mperf)); + note( + &format!("{bench}.counters"), + &[ + ("cpu", b.cpu.to_string()), + ("apic", b.apic.to_string()), + ("smi", shown(delta(a.smi, b.smi))), + ("kicks", shown(delta(a.kicks, b.kicks))), + ("aperf_per_mperf_permille", shown(aperf.zip(mperf).map(|(a, m)| a * 1000 / m.max(1)))), + ("mperf", shown(mperf)), + ], + ); + } +} + +/// The wake for 30 s with the diary read at each outlier: every record from +/// 2 ms before the missed target to the wake, as `offset_us:event:pid/tid`, +/// by the kernel's index of the CPU it was written on, the CPUs the sleeper +/// slept and woke on first; then each process's CPU time over the run and the +/// counters across it. +#[cfg(target_os = "toyos")] +fn diary_run(mut d: sys::diag::Diag) { + const BENCH: &str = "tail.diag.periodic.30s"; + const SHOWN: usize = 16; + let before = d.counters(); + // The diary names a CPU by the kernel's index, and the sleeper's CPUs + // are APIC ids: the counters records carry both. + let index_of: std::collections::BTreeMap = + before.iter().flatten().map(|c| (c.apic, c.cpu)).collect(); + let names_before = d.roster(); + d.diary(); + let mut shown = 0usize; + let mut lost_total = 0u64; + // Printed after the run: a line logged inside it is work the log's + // writers do while the wake is measured. + let mut notes: Vec<(String, Vec<(&str, String)>)> = Vec::new(); + let late = { + let d = &mut d; + periodic(BENCH, Duration::from_secs(30), &mut |l: &Late| { + if shown >= SHOWN { + return; + } + let (records, lost, failed) = d.diary(); + lost_total += lost; + let (from, to) = (l.target_ns.saturating_sub(2_000_000), l.target_ns + l.late_ns); + let mut by_cpu: std::collections::BTreeMap> = std::collections::BTreeMap::new(); + for (at, entry) in records.iter().filter(|(at, _)| (from..=to).contains(at)) { + let offset = *at as i64 - l.target_ns as i64; + by_cpu.entry(entry.cpu).or_default().push(format!("{}:{}", offset / 1000, sys::diag::describe(entry))); + } + notes.push(( + format!("{BENCH}.outlier"), + vec![ + ("i", shown.to_string()), + ("log_s", log_s(l.target_ns)), + ("late_us", (l.late_ns / 1000).to_string()), + ("slept_apic", l.slept_on.to_string()), + ("woke_apic", l.woke_on.to_string()), + ("slept_cpu", index_of.get(&l.slept_on).map_or("-".into(), u32::to_string)), + ("woke_cpu", index_of.get(&l.woke_on).map_or("-".into(), u32::to_string)), + ("records", records.len().to_string()), + ("lost", lost.to_string()), + ("read_failed", failed.unwrap_or_else(|| "no".into())), + ], + )); + for (cpu, events) in by_cpu { + let first = + [l.slept_on, l.woke_on].iter().any(|apic| index_of.get(apic) == Some(&u32::from(cpu))); + let keep = if first { 120 } else { 24 }; + let dropped = events.len().saturating_sub(keep); + let tail: Vec = events.into_iter().rev().take(keep).rev().collect(); + notes.push(( + format!("{BENCH}.diary"), + vec![ + ("i", shown.to_string()), + ("cpu", cpu.to_string()), + ("older_not_shown", dropped.to_string()), + ("events", tail.join(",")), + ], + )); + } + shown += 1; + }) + }; + for (what, fields) in ¬es { + note(what, fields); + } + note(&format!("{BENCH}.summary"), &[("outliers", late.len().to_string()), ("diary_lost", lost_total.to_string())]); + let names_after = d.roster(); + let mut by_process: std::collections::BTreeMap<(u32, String), u64> = std::collections::BTreeMap::new(); + for (&(pid, tid), (name, cpu_after)) in &names_after { + let cpu_before = names_before.get(&(pid, tid)).map_or(0, |(_, ns)| *ns); + *by_process.entry((pid, name.clone())).or_default() += cpu_after.saturating_sub(cpu_before); + } + for ((pid, name), ns) in by_process.into_iter().filter(|(_, ns)| *ns > 0) { + note(&format!("{BENCH}.cpu_time"), &[("pid", pid.to_string()), ("name", name), ("us", (ns / 1000).to_string())]); + } + counters_over(BENCH, before, &d); +} diff --git a/tests/guest/osbench/src/time.rs b/tests/guest/osbench/src/time.rs new file mode 100644 index 00000000000..aaa24422c42 --- /dev/null +++ b/tests/guest/osbench/src/time.rs @@ -0,0 +1,87 @@ +//! Time: what reading the clock costs, how close a sleep lands to what was +//! asked, and what yielding costs. + +use std::thread; +use std::time::{Duration, Instant}; + +use crate::report::result; +use crate::ns_since; + +/// What std's `yield_now` is on each system: Linux's is `sched_yield`; +/// ToyOS's enters no kernel (`sdk/std/sys/thread.rs`: there is no yield +/// syscall, and it is a spin-loop hint). +const YIELD: &str = if cfg!(target_os = "toyos") { "spin_hint_no_syscall" } else { "sched_yield" }; + +pub fn suite() { + clock_read(); + sleeps(""); + #[cfg(target_os = "linux")] + { + // As the periodic wake does: an ordinary Linux sleep is padded by up + // to the thread's timer slack, 50 µs by default. ToyOS has none. + let slack = crate::sys::timer_slack_ns(); + crate::sys::set_timer_slack_ns(1); + sleeps(".slack1ns"); + crate::sys::set_timer_slack_ns(slack); + } + yields(); +} + +/// `Instant::now`, which Linux answers from its vDSO and ToyOS from the clock +/// page, both without entering the kernel: 15 rounds of 1,000,000 calls after +/// one, picoseconds per call. +fn clock_read() { + const CALLS: u64 = 1_000_000; + let round = || { + let t = Instant::now(); + for _ in 0..CALLS { + std::hint::black_box(Instant::now()); + } + ns_since(t) * 1000 / CALLS + }; + round(); + crate::clock::settle(); + let mut ps: Vec = (0..15).map(|_| round()).collect(); + result("time.now", "ps", &mut ps, &[("calls_per_sample", CALLS.to_string())]); +} + +/// `thread::sleep` of each length, and how much later than asked it +/// returned, ns: 1,000 each of 1, 10 and 100 µs, 300 of 1 ms and 100 of +/// 10 ms, after 20 of each. +fn sleeps(suffix: &str) { + for (name, asked, samples) in [ + ("1us", Duration::from_micros(1), 1000), + ("10us", Duration::from_micros(10), 1000), + ("100us", Duration::from_micros(100), 1000), + ("1ms", Duration::from_millis(1), 300), + ("10ms", Duration::from_millis(10), 100), + ] { + let once = || { + let t = Instant::now(); + thread::sleep(asked); + ns_since(t).saturating_sub(asked.as_nanos() as u64) + }; + for _ in 0..20 { + once(); + } + let mut late: Vec = (0..samples).map(|_| once()).collect(); + result(&format!("time.sleep_late.{name}{suffix}"), "ns", &mut late, &[("asked_ns", asked.as_nanos().to_string())]); + } +} + +/// `thread::yield_now` with nothing else to run: 15 rounds of 100,000 calls +/// after one, picoseconds per call. +fn yields() { + const CALLS: u64 = 100_000; + let round = || { + let t = Instant::now(); + for _ in 0..CALLS { + thread::yield_now(); + } + ns_since(t) * 1000 / CALLS + }; + round(); + crate::clock::settle(); + let mut ps: Vec = (0..15).map(|_| round()).collect(); + result("time.yield", "ps", &mut ps, &[("yield_is", YIELD.into()), ("calls_per_sample", CALLS.to_string())]); +} diff --git a/tests/guest/osbench/src/work.rs b/tests/guest/osbench/src/work.rs new file mode 100644 index 00000000000..b5430e530de --- /dev/null +++ b/tests/guest/osbench/src/work.rs @@ -0,0 +1,128 @@ +//! A build-shaped workload, **a proxy and not a compiler**: a fixed set of +//! source-like text files, each turned into an output file by a child +//! process of its own, as many at once as there are CPUs, a new one started +//! each time the oldest running child ends. Each child (`osbench cc +//! `) reads its file, compresses it with `miniz_oxide`'s deflate (level +//! 6) and writes the result, the same code on both systems; the files are in +//! the directory `files` measures in memory. `work.compress_inproc` is the +//! same compression in this one process with no spawn and no file, so the +//! difference between the two is what the system adds. + +use std::fs; +use std::path::PathBuf; +use std::process::{Child, Command, Stdio}; +use std::time::Instant; + +use crate::files::Scratch; +use crate::report::{refuse, result}; +use crate::ns_since; + +const FILES: usize = 256; +const FILE_BYTES: usize = 32 << 10; + +/// One deterministic file of C-like text: words from a fixed vocabulary in +/// an order an LCG picks, so it compresses as source does rather than as +/// noise or as zeros. +fn source(seed: u64) -> Vec { + const WORDS: [&str; 24] = [ + "int", "return", "if", "else", "for", "while", "struct", "static", "const", "char", "void", "size_t", + "(", ")", "{", "}", ";", "=", "+", "*", "->", "0", "1", "\n", + ]; + let mut x = seed.wrapping_mul(6_364_136_223_846_793_005).wrapping_add(1); + let mut out = Vec::with_capacity(FILE_BYTES); + while out.len() < FILE_BYTES { + x = x.wrapping_mul(6_364_136_223_846_793_005).wrapping_add(1_442_695_040_888_963_407); + let word = WORDS[(x >> 33) as usize % WORDS.len()]; + out.extend_from_slice(word.as_bytes()); + out.push(b' '); + } + out.truncate(FILE_BYTES); + out +} + +/// `osbench cc `: one "compile". +pub fn cc(args: &[String]) { + let [input, output] = args else { + eprintln!("osbench cc: wants "); + std::process::exit(2); + }; + let text = fs::read(input).unwrap_or_else(|e| panic!("read {input}: {e}")); + let packed = miniz_oxide::deflate::compress_to_vec(&text, 6); + fs::write(output, packed).unwrap_or_else(|e| panic!("write {output}: {e}")); +} + +pub fn suite() { + let memory = crate::files::memory_targets().remove(0).dir; + let dir = match Scratch::new(memory) { + Ok(d) => d, + Err(e) => return refuse("work", format!("no scratch directory under {memory}: {e}")), + }; + let inputs: Vec = (0..FILES).map(|i| dir.at(&format!("src{i:03}.c"))).collect(); + for (i, path) in inputs.iter().enumerate() { + if let Err(e) = fs::write(path, source(i as u64)) { + return refuse("work", format!("the sources: {e}")); + } + } + let exe = match std::env::current_exe() { + Ok(exe) => exe, + Err(e) => return refuse("work", format!("no path to this program: {e}")), + }; + + // Every source compressed in this process, one after another: ns for the + // set, five rounds after one. + let texts: Vec> = (0..FILES).map(|i| source(i as u64)).collect(); + let inproc = || { + let t = Instant::now(); + let packed: usize = texts.iter().map(|t| miniz_oxide::deflate::compress_to_vec(t, 6).len()).sum(); + std::hint::black_box(packed); + ns_since(t) + }; + inproc(); + crate::clock::settle(); + let mut ns: Vec = (0..5).map(|_| inproc()).collect(); + result("work.compress_inproc", "ns", &mut ns, &[("files", FILES.to_string()), ("file_bytes", FILE_BYTES.to_string())]); + + // The set built by a child per file, `jobs` at once: ns for the set, + // five rounds after one, at one job and at one per CPU. + for jobs in [1, crate::cpus()] { + let bench = format!("work.build_shaped.j{jobs}"); + let build = || -> Result { + let t = Instant::now(); + let mut running: Vec = Vec::new(); + for (i, input) in inputs.iter().enumerate() { + if running.len() == jobs { + let child = running.remove(0); + finish(child)?; + } + let output = dir.at(&format!("obj{i:03}.o")); + let child = Command::new(&exe) + .arg("cc") + .arg(input) + .arg(&output) + .stdin(Stdio::null()) + .stdout(Stdio::null()) + .spawn() + .map_err(|e| format!("spawn a compile: {e}"))?; + running.push(child); + } + for child in running { + finish(child)?; + } + Ok(ns_since(t)) + }; + let rounds = || -> Result, String> { + build()?; + crate::clock::settle(); + (0..5).map(|_| build()).collect() + }; + match rounds() { + Ok(mut ns) => result(&bench, "ns", &mut ns, &[("files", FILES.to_string()), ("jobs", jobs.to_string())]), + Err(why) => refuse(&bench, why), + } + } +} + +fn finish(mut child: Child) -> Result<(), String> { + let status = child.wait().map_err(|e| format!("wait for a compile: {e}"))?; + if status.success() { Ok(()) } else { Err(format!("a compile ended {status}")) } +} diff --git a/tests/images/benchcase.toml b/tests/images/benchcase.toml index 3fcc3b67062..15141bda82e 100644 --- a/tests/images/benchcase.toml +++ b/tests/images/benchcase.toml @@ -3,10 +3,15 @@ # # Only what a job list needs to run and to reach the log on the boot stick: no # compositor, sound, ACPI server or network, so little but the measurement asks -# for a CPU. +# for a CPU. DATA is memory here, the stick having no DATA partition, and the +# log volume is the one persistent volume a job can write (`osbench persist`). # # The runner's capability carries `jobs`, for the fairness run that starts each -# workload as a job of its own, and `dup`, to hand it down. +# workload as a job of its own; `counters`, `trace` and `roster`, so `osbench +# tail` can read each CPU's SMIs and clock, the scheduler's diary and each +# process's name and CPU time around a late wake; and `dup`, so each job is +# handed a duplicate. No other benchmark's path uses them. An unprivileged +# Linux program has no observation rights to match, which the report says. [boot] start = ["logkeeper", "diskserver", "fileserver", "test-runner"] @@ -14,19 +19,48 @@ start = ["logkeeper", "diskserver", "fileserver", "test-runner"] service = true syscap = ["logread"] +# The order `osbench all` runs the groups in. The bound is the metal row's, its +# 240 s on the 60 s every list has (`tests/toyos.rs`), restated for a boot of +# this config built without the row; a derived metal config states its own. [programs.test-runner] receives = ["power"] -args = ["osbench_system", "osbench_sched", "osbench_fair", "reboot"] -syscap = ["jobs", "dup"] +syscap = ["jobs", "counters", "trace", "roster", "dup"] +args = [ + "--bound-ms=300000", + "osbench_boot", + "osbench_system", + "osbench_sched", + "osbench_fair", + "osbench_files", + "osbench_ipc", + "osbench_net", + "osbench_procs", + "osbench_mem", + "osbench_time", + "osbench_work", + "osbench_tail", + "osbench_persist", + "reboot", +] [programs.osbench] [programs.toybox] [symlinks] +"bin/osbench_boot" = "/system/bin/osbench" "bin/osbench_system" = "/system/bin/osbench" "bin/osbench_sched" = "/system/bin/osbench" "bin/osbench_fair" = "/system/bin/osbench" +"bin/osbench_files" = "/system/bin/osbench" +"bin/osbench_ipc" = "/system/bin/osbench" +"bin/osbench_net" = "/system/bin/osbench" +"bin/osbench_procs" = "/system/bin/osbench" +"bin/osbench_mem" = "/system/bin/osbench" +"bin/osbench_time" = "/system/bin/osbench" +"bin/osbench_work" = "/system/bin/osbench" +"bin/osbench_tail" = "/system/bin/osbench" +"bin/osbench_persist" = "/system/bin/osbench" "bin/reboot" = "/system/bin/toybox" # The block service: every disk a driver offers on `disk`, listed and opened diff --git a/tests/toyos.rs b/tests/toyos.rs index 2998c713f94..03855b3bc90 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -995,6 +995,7 @@ const METAL: &[(&str, metal::Metal)] = &[ // The numbers compared with the same program on the bench's own Linux. // Evidence and not a verdict: they are read off the log, and the row // holds only that every group ran to its end. The T14 and the AMD bench. + // One boot runs the whole suite, so three readbacks are three runs. "osbench", metal::Metal { arms: BENCHCASE, judge: |b| osbench_ran(b[0]) }, ), @@ -1422,10 +1423,34 @@ const TESTCASES: &[metal::Arm] = &[metal::once( ], )]; -/// `osbench`'s groups, each a job named by its symlink. -const OSBENCH_GROUPS: [&str; 3] = ["osbench_system", "osbench_sched", "osbench_fair"]; +/// `osbench`'s groups, each a job named by its symlink, in `osbench all`'s +/// order: `boot` first, which reads how long the boot took to reach it, and +/// `persist` last, which writes the log volume. +const OSBENCH_GROUPS: [&str; 13] = [ + "osbench_boot", + "osbench_system", + "osbench_sched", + "osbench_fair", + "osbench_files", + "osbench_ipc", + "osbench_net", + "osbench_procs", + "osbench_mem", + "osbench_time", + "osbench_work", + "osbench_tail", + "osbench_persist", +]; -const BENCHCASE: &[metal::Arm] = &[metal::once("benchcase", "tests/images/benchcase.toml", &[], &OSBENCH_GROUPS)]; +/// The suite runs past every boot's bound on purpose: `tail` alone waits out +/// 100 s of wakes and spinners. Six boots of `e5573b7fe` ended their last job +/// at 175 to 191 s on five, and at 244 s on the T14's first, where one +/// served 64 MiB write stalled and `files` took 80 s against 13; so a list +/// bound of 300 s leaves that stall 56 s. +const BENCHCASE: &[metal::Arm] = &[metal::Arm { + adds_ms: 240_000, + ..metal::once("benchcase", "tests/images/benchcase.toml", &[], &OSBENCH_GROUPS) +}]; /// Every group exited 0, which `osbench` does only once each of its /// benchmarks measured, and said it was done.