diff --git a/.gitignore b/.gitignore index ea8c4bf..ac339f2 100644 --- a/.gitignore +++ b/.gitignore @@ -1 +1,2 @@ +/docs/superpowers/ /target diff --git a/Cargo.lock b/Cargo.lock index e1f4736..f03abba 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -381,24 +381,24 @@ checksum = "a06f77d526c1a601b7c4cdd98f54b5eaabffc14d5f2f0296febdc7f357c6d3ba" [[package]] name = "futures-channel" -version = "0.3.13" +version = "0.3.32" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8c2dd2df839b57db9ab69c2c9d8f3e8c81984781937fe2807dc6dcf3b2ad2939" +checksum = "07bbe89c50d7a535e539b8c17bc0b49bdb77747034daa8087407d655f3f7cc1d" dependencies = [ "futures-core", ] [[package]] name = "futures-core" -version = "0.3.13" +version = "0.3.32" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "15496a72fabf0e62bdc3df11a59a3787429221dd0710ba8ef163d6f7a9112c94" +checksum = "7e3450815272ef58cec6d564423f6e755e25379b217b0bc688e295ba24df6b1d" [[package]] name = "futures-io" -version = "0.3.13" +version = "0.3.32" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d71c2c65c57704c32f5241c1223167c2c3294fd34ac020c807ddbe6db287ba59" +checksum = "cecba35d7ad927e23624b22ad55235f2239cfa44fd10428eecbeba6d6a717718" [[package]] name = "futures-lite" @@ -780,18 +780,18 @@ dependencies = [ [[package]] name = "proc-macro2" -version = "1.0.24" +version = "1.0.106" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1e0704ee1a7e00d7bb417d0770ea303c1bccbabf0ef1667dae92b5967f5f8a71" +checksum = "8fd00f0bb2e90d81d1044c2b32617f68fcb9fa3bb7640c23e9c748e53fb30934" dependencies = [ - "unicode-xid", + "unicode-ident", ] [[package]] name = "quote" -version = "1.0.9" +version = "1.0.45" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c3d0b9745dc2debf507c8422de05d7226cc1f0644216dfdfead988f9b1ab32a7" +checksum = "41f2619966050689382d2b44f664f4bc593e129785a36d6ee376ddf37259b924" dependencies = [ "proc-macro2", ] @@ -1126,6 +1126,12 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a7f741b240f1a48843f9b8e0444fb55fb2a4ff67293b50a9179dfd5ea67f8d41" +[[package]] +name = "unicode-ident" +version = "1.0.24" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e6e4313cd5fcd3dad5cafa179702e2b244f760991f45397d14d4ebf38247da75" + [[package]] name = "unicode-xid" version = "0.2.1" diff --git a/README.md b/README.md index 7834e43..2ad8a8f 100644 --- a/README.md +++ b/README.md @@ -99,6 +99,17 @@ Create a JSON or YAML file with the following properties: communication between tested processes and sirun. By default a random port will be assigned. You should read this variable from tested programs to determine which port to send data to. +* **`SIRUN_READY_FD`**: A writable file descriptor provided by sirun to the + benchmarked process. Write any byte to this descriptor to signal that startup + is complete; sirun will reset `wall.time` (and `instructions` on Linux) to + measure only the post-ready period. `user.time`, `system.time`, + `cpu.pct.wall.time`, and `max.res.size` always cover the full process + lifetime regardless of the signal. If the process exits without writing to + this descriptor, sirun falls back to measuring the full process lifetime. + Example (Node.js): + ```js + require('fs').writeSync(parseInt(process.env.SIRUN_READY_FD), 'x'); + ``` ### Example diff --git a/examples/ready-signal-cpu.json b/examples/ready-signal-cpu.json new file mode 100644 index 0000000..6f4627c --- /dev/null +++ b/examples/ready-signal-cpu.json @@ -0,0 +1,3 @@ +{ + "run": "python3 -c \"import os,time; [None for _ in range(1000000)]; os.write(int(os.environ['SIRUN_READY_FD']),b'x'); time.sleep(0.3)\"" +} diff --git a/examples/ready-signal.json b/examples/ready-signal.json new file mode 100644 index 0000000..5b94efd --- /dev/null +++ b/examples/ready-signal.json @@ -0,0 +1,3 @@ +{ + "run": "bash -c 'sleep 0.5; echo x >&$SIRUN_READY_FD'" +} diff --git a/src/main.rs b/src/main.rs index 6ddaa91..07942ed 100644 --- a/src/main.rs +++ b/src/main.rs @@ -11,7 +11,12 @@ use async_std::{ task::{sleep, spawn}, }; use serde_json::json; -use std::{collections::HashMap, env, os::unix::process::ExitStatusExt, process::exit}; +use std::{ + collections::HashMap, + env, + os::unix::{io::{FromRawFd, RawFd}, process::ExitStatusExt}, + process::exit, +}; use which::which; use indexmap::IndexMap; @@ -48,29 +53,82 @@ async fn test_timeout(timeout: u64) { exit(1); } +async fn read_one_byte(fd: RawFd) -> bool { + use async_std::io::ReadExt; + let mut buf = [0u8; 1]; + let mut f = unsafe { async_std::fs::File::from_raw_fd(fd) }; + f.read(&mut buf).await.map(|n| n > 0).unwrap_or(false) +} + +async fn wait_with_ready_signal( + child: &mut Child, + read_fd: RawFd, + start_time: &mut std::time::Instant, +) -> Result<(ExitStatus, Option<(f64, f64)>)> { + // Returns true if the app wrote to SIRUN_READY_FD; false if it exited + // without signaling (parent closed write end, so child exit → EOF). + let got_signal = read_one_byte(read_fd).await; + let startup_cpu = if got_signal { + let cpu = read_child_cpu_us(child.id()); + *start_time = std::time::Instant::now(); + cpu + } else { + None + }; + Ok((child.status().await?, startup_cpu)) +} + #[cfg(target_os = "linux")] -async fn run_with_instruction_count(child: &mut Child, config: &Config) -> Result<(ExitStatus, Option)> { +async fn run_with_instruction_count( + child: &mut Child, + config: &Config, + read_fd: RawFd, + start_time: &mut std::time::Instant, +) -> Result<(ExitStatus, Option, Option<(f64, f64)>)> { use perfcnt::AbstractPerfCounter; - use perfcnt::linux::{PerfCounterBuilderLinux, HardwareEventType}; - if config.instructions { - let pid = child.id(); - let mut counter = PerfCounterBuilderLinux::from_hardware_event(HardwareEventType::Instructions) + use perfcnt::linux::{HardwareEventType, PerfCounterBuilderLinux}; + + if !config.instructions { + let (status, startup_cpu) = + wait_with_ready_signal(child, read_fd, start_time).await?; + return Ok((status, None, startup_cpu)); + } + + let pid = child.id(); + let mut counter = + PerfCounterBuilderLinux::from_hardware_event(HardwareEventType::Instructions) .for_pid(pid as i32) .finish()?; - counter.start()?; - let status = child.status().await?; - counter.stop()?; - let instructions = counter.read()?; + counter.start()?; - Ok((status, Some(instructions))) + let got_signal = read_one_byte(read_fd).await; + let (startup_instructions, startup_cpu) = if got_signal { + let cpu = read_child_cpu_us(pid); + *start_time = std::time::Instant::now(); + counter.stop()?; + let val = counter.read()?; + counter.start()?; + (val, cpu) } else { - Ok((child.status().await?, None)) - } + (0, None) + }; + + let status = child.status().await?; + counter.stop()?; + let total = counter.read()?; + Ok((status, Some(total - startup_instructions), startup_cpu)) } #[cfg(not(target_os = "linux"))] -async fn run_with_instruction_count(child: &mut Child, _config: &Config) -> Result<(ExitStatus, Option)> { - Ok((child.status().await?, None)) +async fn run_with_instruction_count( + child: &mut Child, + _config: &Config, + read_fd: RawFd, + start_time: &mut std::time::Instant, +) -> Result<(ExitStatus, Option, Option<(f64, f64)>)> { + let (status, startup_cpu) = + wait_with_ready_signal(child, read_fd, start_time).await?; + Ok((status, None, startup_cpu)) } async fn run_test(config: &Config, mut metrics: &mut HashMap) -> Result<()> { @@ -78,13 +136,37 @@ async fn run_test(config: &Config, mut metrics: &mut HashMap Result> { Ok(match &config.service { - Some(command_arr) => Some(run_cmd(command_arr, &config.env)?), + Some(command_arr) => Some(run_cmd(command_arr, &config.env, None)?), None => None, }) } @@ -128,6 +210,7 @@ async fn run_iteration( let mut child = run_cmd( &env::args().take(1).collect::>(), &sub_config.env, + None, )?; let status = child.status().await?; let status = status.code().expect("no exit code"); diff --git a/src/rusage.rs b/src/rusage.rs index 150eafa..32e244b 100644 --- a/src/rusage.rs +++ b/src/rusage.rs @@ -45,3 +45,115 @@ impl Sub for Rusage { } } } + +/// Returns the CPU time (user_µs, system_µs) of a running process by reading +/// `/proc/{pid}/stat`. Returns `None` if the file cannot be read or parsed. +#[cfg(target_os = "linux")] +pub(crate) fn read_child_cpu_us(pid: u32) -> Option<(f64, f64)> { + let contents = std::fs::read_to_string(format!("/proc/{}/stat", pid)).ok()?; + // The second field (process name) is wrapped in parentheses and may contain + // spaces. Find the last ')' to reliably skip past it. + let after_name = contents.rfind(')')? + 1; + let fields: Vec<&str> = contents[after_name..].split_whitespace().collect(); + // After ')': state(0) ppid(1) pgrp(2) session(3) tty_nr(4) tpgid(5) + // flags(6) minflt(7) cminflt(8) majflt(9) cmajflt(10) utime(11) stime(12) + let utime_jiffies: u64 = fields.get(11)?.parse().ok()?; + let stime_jiffies: u64 = fields.get(12)?.parse().ok()?; + let ticks_raw = unsafe { nix::libc::sysconf(nix::libc::_SC_CLK_TCK) }; + if ticks_raw <= 0 { + return None; + } + let ticks = ticks_raw as f64; + Some(( + utime_jiffies as f64 * 1_000_000.0 / ticks, + stime_jiffies as f64 * 1_000_000.0 / ticks, + )) +} + +/// Returns the CPU time (user_µs, system_µs) of a running process via +/// `proc_pidinfo(PROC_PIDTASKINFO)`. Returns `None` on failure. +#[cfg(target_os = "macos")] +pub(crate) fn read_child_cpu_us(pid: u32) -> Option<(f64, f64)> { + const PROC_PIDTASKINFO: nix::libc::c_int = 4; + + #[repr(C)] + struct ProcTaskInfo { + pti_virtual_size: u64, + pti_resident_size: u64, + pti_total_user: u64, // nanoseconds — XNU bsd/kern/proc_info.c fill_taskprocinfo() + pti_total_system: u64, // nanoseconds — XNU bsd/kern/proc_info.c fill_taskprocinfo() + pti_threads_user: u64, + pti_threads_system: u64, + pti_policy: i32, + pti_faults: i32, + pti_pageins: i32, + pti_cow_faults: i32, + pti_messages_sent: i32, + pti_messages_received: i32, + pti_syscalls_mach: i32, + pti_syscalls_unix: i32, + pti_csw: i32, + pti_threadnum: i32, + pti_numrunning: i32, + pti_priority: i32, + } + + extern "C" { + fn proc_pidinfo( + pid: nix::libc::c_int, + flavor: nix::libc::c_int, + arg: u64, + buffer: *mut nix::libc::c_void, + buffersize: nix::libc::c_int, + ) -> nix::libc::c_int; + } + + let mut info = std::mem::MaybeUninit::::zeroed(); + let ret = unsafe { + proc_pidinfo( + pid as nix::libc::c_int, + PROC_PIDTASKINFO, + 0, + info.as_mut_ptr() as *mut nix::libc::c_void, + std::mem::size_of::() as nix::libc::c_int, + ) + }; + if ret < std::mem::size_of::() as nix::libc::c_int { + return None; + } + let info = unsafe { info.assume_init() }; + // Convert nanoseconds to microseconds. + Some(( + info.pti_total_user as f64 / 1_000.0, + info.pti_total_system as f64 / 1_000.0, + )) +} + +#[cfg(not(any(target_os = "linux", target_os = "macos")))] +pub(crate) fn read_child_cpu_us(_pid: u32) -> Option<(f64, f64)> { + None +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn read_child_cpu_us_returns_some_for_current_process() { + let pid = std::process::id(); + let result = read_child_cpu_us(pid); + #[cfg(any(target_os = "linux", target_os = "macos"))] + assert!(result.is_some(), "expected CPU reading for pid {}", pid); + #[cfg(not(any(target_os = "linux", target_os = "macos")))] + let _ = result; + } + + #[test] + fn read_child_cpu_us_values_are_non_negative() { + let pid = std::process::id(); + if let Some((utime, stime)) = read_child_cpu_us(pid) { + assert!(utime >= 0.0); + assert!(stime >= 0.0); + } + } +} diff --git a/src/subproc.rs b/src/subproc.rs index c841dc6..466c57b 100644 --- a/src/subproc.rs +++ b/src/subproc.rs @@ -3,7 +3,7 @@ use async_std::{ process::{Command, Child, Stdio}, task::sleep, }; -use std::{collections::HashMap, env, os::unix::process::ExitStatusExt, time::Duration}; +use std::{collections::HashMap, env, os::unix::{io::RawFd, process::ExitStatusExt}, time::Duration}; use crate::config::*; @@ -27,7 +27,7 @@ async fn run_setup_or_teardown(typ: &str, config: &Config) -> Result<()> { if attempts == 100 { bail!("{} script did not complete successfully. aborting.", typ); } - let mut child = run_cmd(command_arr, env)?; + let mut child = run_cmd(command_arr, env, None)?; let status = child.status().await?; let maybe_code = status.code(); if let Some(maybe_code) = maybe_code { @@ -67,12 +67,17 @@ fn get_stdio() -> Stdio { pub(crate) fn run_cmd( command_arr: &[String], env: &HashMap, + ready_fd: Option, ) -> Result { + let mut env = env.clone(); + if let Some(fd) = ready_fd { + env.insert("SIRUN_READY_FD".into(), fd.to_string()); + } let command = command_arr[0].clone(); let args = command_arr.iter().skip(1); Command::new(command) .args(args) - .envs(env.clone()) + .envs(env) .stdout(get_stdio()) .stderr(get_stdio()) .spawn() diff --git a/tests/examples.rs b/tests/examples.rs index 1b0cf41..c5c8316 100644 --- a/tests/examples.rs +++ b/tests/examples.rs @@ -297,3 +297,132 @@ fn insctrution_counts() { fn service() { run!("./examples/service.json").assert().success(); } + +#[test] +#[serial] +fn ready_signal_resets_wall_time() { + json_has!( + "./examples/ready-signal.json", + |map: &serde_yaml::Mapping| { + let wall_time = map + .get(&"iterations".into()) + .unwrap() + .as_sequence() + .unwrap()[0] + .as_mapping() + .unwrap() + .get(&"wall.time".into()) + .unwrap() + .as_f64() + .unwrap(); + // Startup is 500ms; post-ready work is ~0ms. + // With ready signal: wall.time << 500_000μs. + // Threshold of 200_000μs gives generous headroom. + wall_time < 200_000.0 + } + ); +} + +#[test] +#[serial] +fn ready_signal_fallback_when_no_signal() { + // App exits without writing to SIRUN_READY_FD — full timing used. + json_has!("./examples/simple.json", |map: &serde_yaml::Mapping| { + // simple.json has no ready signal; we just verify it still runs normally. + map.get(&"iterations".into()) + .unwrap() + .as_sequence() + .unwrap() + .len() + == 1 + }); +} + +#[test] +#[serial] +fn ready_signal_cpu_pct_bounded() { + json_has!( + "./examples/ready-signal-cpu.json", + |map: &serde_yaml::Mapping| { + let iter = map + .get(&"iterations".into()) + .unwrap() + .as_sequence() + .unwrap()[0] + .as_mapping() + .unwrap(); + let cpu_pct = iter + .get(&"cpu.pct.wall.time".into()) + .unwrap() + .as_f64() + .unwrap(); + // Without the fix, user.time covers the full CPU-intensive startup + // while wall.time covers only the post-ready period (near zero), + // making cpu.pct.wall.time >> 100%. With the fix it must stay <= 100%. + cpu_pct <= 100.0 + } + ); +} + +#[test] +#[serial] +fn ready_signal_cpu_pct_100x() { + let mut passes = 0u32; + let mut failures = 0u32; + let mut cpu_pcts: Vec = Vec::new(); + + for _ in 0..100 { + let output = assert_cmd::Command::cargo_bin("sirun") + .unwrap() + .arg("./examples/ready-signal-cpu.json") + .env("SIRUN_NO_STDIO", "1") + .output() + .unwrap(); + + if output.status.success() { + if let Ok(val) = + serde_yaml::from_slice::(&output.stdout) + { + if let Some(cpu_pct) = val + .as_mapping() + .and_then(|m| m.get(&"iterations".into())) + .and_then(|v| v.as_sequence()) + .and_then(|s| s.get(0)) + .and_then(|v| v.as_mapping()) + .and_then(|m| m.get(&"cpu.pct.wall.time".into())) + .and_then(|v| v.as_f64()) + { + cpu_pcts.push(cpu_pct); + if cpu_pct <= 100.0 { + passes += 1; + } else { + failures += 1; + } + } else { + failures += 1; + } + } else { + failures += 1; + } + } else { + failures += 1; + } + } + + let max_pct = cpu_pcts + .iter() + .cloned() + .fold(f64::NEG_INFINITY, f64::max); + eprintln!( + "async_std::fs::File 100x: {}/100 passed, \ + max cpu.pct.wall.time = {:.1}%", + passes, max_pct + ); + assert!( + passes >= 95, + "async_std::fs::File: {}/100 passed \ + (max cpu.pct.wall.time = {:.1}%)", + passes, + max_pct + ); +}