experiment: async_std::fs::File cpu.pct reliability 100x

.gitignore

@@ -1 +1,2 @@
+/docs/superpowers/
 /target

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
 

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)\""
+}

examples/ready-signal.json

@@ -0,0 +1,3 @@
+{
+  "run": "bash -c 'sleep 0.5; echo x >&$SIRUN_READY_FD'"
+}

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,43 +53,120 @@ 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<u64>)> {
+async fn run_with_instruction_count(
+    child: &mut Child,
+    config: &Config,
+    read_fd: RawFd,
+    start_time: &mut std::time::Instant,
+) -> Result<(ExitStatus, Option<u64>, 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<u64>)> {
-    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<u64>, 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<String, MetricValue>) -> Result<()> {
     if let Some(timeout) = config.timeout {
         spawn(test_timeout(timeout));
     }
 
-    let start_time = std::time::Instant::now();
+    let (read_fd, write_fd) = nix::unistd::pipe()?;
+    // Set CLOEXEC on read_fd so the child does not inherit the read end.
+    nix::fcntl::fcntl(
+        read_fd,
+        nix::fcntl::FcntlArg::F_SETFD(nix::fcntl::FdFlag::FD_CLOEXEC),
+    )?;
+
+    let mut start_time = std::time::Instant::now();
+    // RUSAGE_CHILDREN cannot be snapshotted mid-run (it only updates after a child
+    // exits), so we use read_child_cpu_us to snapshot the live process CPU at
+    // signal time and subtract it from the final RUSAGE_CHILDREN delta.
     let rusage_start = Rusage::new();
-    let mut child = run_cmd(&config.run, &config.env)?;
-    let (status, instructions) = run_with_instruction_count(&mut child, config).await?;
+    let mut child = run_cmd(&config.run, &config.env, Some(write_fd))?;
+    // Close parent's write end so the child's exit causes EOF on the read end.
+    nix::unistd::close(write_fd)?;
+
+    let (status, instructions, startup_cpu) = run_with_instruction_count(
+        &mut child,
+        config,
+        read_fd,
+        &mut start_time,
+    )
+    .await?;
+
     let duration = start_time.elapsed().as_micros();
     metrics.insert("wall.time".to_owned(), (duration as f64).into());
-    let rusage_result = Rusage::new() - rusage_start;
+    let mut rusage_result = Rusage::new() - rusage_start;
+    if let Some((startup_utime, startup_stime)) = startup_cpu {
+        rusage_result.user_time = (rusage_result.user_time - startup_utime).max(0.0);
+        rusage_result.system_time = (rusage_result.system_time - startup_stime).max(0.0);
+    }
     if let Some(instructions) = instructions {
         metrics.insert("instructions".to_owned(), (instructions as f64).into());
     }
@@ -111,7 +193,7 @@ async fn run_test(config: &Config, mut metrics: &mut HashMap<String, MetricValue
 
 fn run_service(config: &Config) -> Result<Option<Child>> {
     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::<Vec<String>>(),
         &sub_config.env,
+        None,
     )?;
     let status = child.status().await?;
     let status = status.code().expect("no exit code");

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::<ProcTaskInfo>::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::<ProcTaskInfo>() as nix::libc::c_int,
+        )
+    };
+    if ret < std::mem::size_of::<ProcTaskInfo>() 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);
+        }
+    }
+}