Initial support for user and system time

Cargo.lock

@@ -82,11 +82,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
 name = "hyperfine"
-version = "0.2.0"
+version = "0.3.0"
 dependencies = [
  "ansi_term 0.10.2 (registry+https://github.com/rust-lang/crates.io-index)",
  "clap 2.29.2 (registry+https://github.com/rust-lang/crates.io-index)",
  "indicatif 0.9.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "libc 0.2.36 (registry+https://github.com/rust-lang/crates.io-index)",
  "statistical 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 

Cargo.toml

@@ -7,12 +7,13 @@ license = "MIT/Apache-2.0"
 name = "hyperfine"
 readme = "README.md"
 repository = "https://github.com/sharkdp/hyperfine"
-version = "0.2.0"
+version = "0.3.0"
 
 [dependencies]
 ansi_term = "0.10"
 indicatif = "0.9"
 statistical = "0.1"
+libc = "0.2"
 
 [dependencies.clap]
 version = "2"

src/hyperfine/benchmark.rs

@@ -2,28 +2,33 @@ use std::io;
 use std::process::{Command, Stdio};
 use std::time::Instant;
 
-use ansi_term::Colour::{Cyan, Green, Purple, White, Yellow};
+use ansi_term::Colour::{Blue, Cyan, Green, Purple, White, Yellow};
 use statistical::{mean, standard_deviation};
 
 use hyperfine::internal::{get_progress_bar, max, min, CmdFailureAction, HyperfineOptions, Second,
                           Warnings, MIN_EXECUTION_TIME};
 use hyperfine::format::{format_duration, format_duration_unit};
+use hyperfine::cputime::{get_cpu_interval, get_cpu_times};
 
 /// Results from timing a single shell command
+#[derive(Debug, Copy, Clone)]
 pub struct TimingResult {
-    /// Execution time in seconds
+    /// Wall clock time
-    pub execution_time: Second,
+    pub time_real: Second,
 
-    /// True if the command finished with exit code zero
+    /// Time spent in user mode
-    pub success: bool,
+    pub time_user: Second,
+
+    /// Time spent in kernel mode
+    pub time_system: Second,
 }
 
-impl TimingResult {
+/// Correct for shell spawning time
-    fn new(execution_time: Second, success: bool) -> TimingResult {
+fn subtract_shell_spawning_time(time: Second, shell_spawning_time: Second) -> Second {
-        TimingResult {
+    if time < shell_spawning_time {
-            execution_time,
+        0.0
-            success,
+    } else {
-        }
+        time - shell_spawning_time
     }
 }
 
@@ -31,9 +36,10 @@ impl TimingResult {
 pub fn time_shell_command(
     shell_cmd: &str,
     failure_action: CmdFailureAction,
-    shell_spawning_time: Option<Second>,
+    shell_spawning_time: Option<TimingResult>,
-) -> io::Result<TimingResult> {
+) -> io::Result<(TimingResult, bool)> {
     let start = Instant::now();
+    let start_cpu = get_cpu_times();
 
     let status = Command::new("sh")
         .arg("-c")
@@ -43,6 +49,9 @@ pub fn time_shell_command(
         .stderr(Stdio::null())
         .status()?;
 
+    let end_cpu = get_cpu_times();
+    let duration = start.elapsed();
+
     if failure_action == CmdFailureAction::RaiseError && !status.success() {
         return Err(io::Error::new(
             io::ErrorKind::Other,
@@ -51,33 +60,40 @@ pub fn time_shell_command(
         ));
     }
 
-    let duration = start.elapsed();
+    // Real time
+    let mut time_real = duration.as_secs() as f64 + (duration.subsec_nanos() as f64) * 1e-9;
 
-    let execution_time = duration.as_secs() as f64 + (duration.subsec_nanos() as f64) * 1e-9;
+    // User and system time
+    let cpu_interval = get_cpu_interval(&start_cpu, &end_cpu);
+    let mut time_user = cpu_interval.user;
+    let mut time_system = cpu_interval.system;
 
     // Correct for shell spawning time
-    let execution_time_corrected = if let Some(spawning_time) = shell_spawning_time {
+    if let Some(spawning_time) = shell_spawning_time {
-        if execution_time < spawning_time {
+        time_real = subtract_shell_spawning_time(time_real, spawning_time.time_real);
-            0.0
+        time_user = subtract_shell_spawning_time(cpu_interval.user, spawning_time.time_user);
-        } else {
+        time_system = subtract_shell_spawning_time(cpu_interval.system, spawning_time.time_system);
-            execution_time - spawning_time
+    }
-        }
-    } else {
-        execution_time
-    };
 
-    Ok(TimingResult::new(
+    Ok((
-        execution_time_corrected,
+        TimingResult {
+            time_real,
+            time_user,
+            time_system,
+        },
         status.success(),
     ))
 }
 
 /// Measure the average shell spawning time
-pub fn mean_shell_spawning_time() -> io::Result<Second> {
+pub fn mean_shell_spawning_time() -> io::Result<TimingResult> {
     const COUNT: u64 = 200;
     let progress_bar = get_progress_bar(COUNT, "Measuring shell spawning time");
 
-    let mut times: Vec<Second> = vec![];
+    let mut times_real: Vec<Second> = vec![];
+    let mut times_user: Vec<Second> = vec![];
+    let mut times_system: Vec<Second> = vec![];
+
     for _ in 0..COUNT {
         // Just run the shell without any command
         let res = time_shell_command("", CmdFailureAction::RaiseError, None);
@@ -90,22 +106,28 @@ pub fn mean_shell_spawning_time() -> io::Result<Second> {
                      Make sure you can run 'sh -c \"\"'.",
                 ))
             }
-            Ok(r) => {
+            Ok((r, _)) => {
-                times.push(r.execution_time);
+                times_real.push(r.time_real);
+                times_user.push(r.time_user);
+                times_system.push(r.time_system);
             }
         }
         progress_bar.inc(1);
     }
     progress_bar.finish_and_clear();
 
-    Ok(mean(&times))
+    Ok(TimingResult {
+        time_real: mean(&times_real),
+        time_user: mean(&times_user),
+        time_system: mean(&times_system),
+    })
 }
 
 /// Run the benchmark for a single shell command
 pub fn run_benchmark(
     num: usize,
     cmd: &str,
-    shell_spawning_time: Second,
+    shell_spawning_time: TimingResult,
     options: &HyperfineOptions,
 ) -> io::Result<()> {
     println!(
@@ -116,7 +138,9 @@ pub fn run_benchmark(
     );
     println!();
 
-    let mut execution_times: Vec<Second> = vec![];
+    let mut times_real: Vec<Second> = vec![];
+    let mut times_user: Vec<Second> = vec![];
+    let mut times_system: Vec<Second> = vec![];
     let mut all_succeeded = true;
 
     // Warmup phase
@@ -142,11 +166,12 @@ pub fn run_benchmark(
     run_preparation_command();
 
     // Initial timing run
-    let res = time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?;
+    let (res, success) =
+        time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?;
 
     // Determine number of benchmark runs
     let runs_in_min_time =
-        (options.min_time_sec / (res.execution_time + shell_spawning_time)) as u64;
+        (options.min_time_sec / (res.time_real + shell_spawning_time.time_real)) as u64;
 
     let count = if runs_in_min_time >= options.min_runs {
         runs_in_min_time
@@ -157,8 +182,11 @@ pub fn run_benchmark(
     let count_remaining = count - 1;
 
     // Save the first result
-    execution_times.push(res.execution_time);
+    times_real.push(res.time_real);
-    all_succeeded = all_succeeded && res.success;
+    times_user.push(res.time_user);
+    times_system.push(res.time_system);
+
+    all_succeeded = all_succeeded && success;
 
     // Re-configure the progress bar
     progress_bar.set_length(count_remaining);
@@ -168,25 +196,32 @@ pub fn run_benchmark(
         run_preparation_command();
 
         let msg = {
-            let mean = format_duration(mean(&execution_times), None);
+            let mean = format_duration(mean(&times_real), None);
             format!("Current estimate: {}", Green.paint(mean))
         };
         progress_bar.set_message(&msg);
 
-        let res = time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?;
+        let (res, success) =
+            time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?;
 
-        execution_times.push(res.execution_time);
+        times_real.push(res.time_real);
-        all_succeeded = all_succeeded && res.success;
+        times_user.push(res.time_user);
+        times_system.push(res.time_system);
+
+        all_succeeded = all_succeeded && success;
 
         progress_bar.inc(1);
     }
     progress_bar.finish_and_clear();
 
     // Compute statistical quantities
-    let t_mean = mean(&execution_times);
+    let t_mean = mean(&times_real);
-    let t_stddev = standard_deviation(&execution_times, Some(t_mean));
+    let t_stddev = standard_deviation(&times_real, Some(t_mean));
-    let t_min = min(&execution_times);
+    let t_min = min(&times_real);
-    let t_max = max(&execution_times);
+    let t_max = max(&times_real);
+
+    let user_mean = mean(&times_user);
+    let system_mean = mean(&times_system);
 
     // Formatting and console output
     let (mean_str, unit_mean) = format_duration_unit(t_mean, None);
@@ -194,12 +229,17 @@ pub fn run_benchmark(
     let min_str = format_duration(t_min, Some(unit_mean));
     let max_str = format_duration(t_max, Some(unit_mean));
 
+    let (user_str, user_unit) = format_duration_unit(user_mean, None);
+    let system_str = format_duration(system_mean, Some(user_unit));
+
     println!(
-        "  Time ({} ± {}):     {} ± {}",
+        "  Time ({} ± {}):     {} ± {}    [User: {}, System: {}]",
         Green.bold().paint("mean"),
         Green.paint("σ"),
         Green.bold().paint(mean_str),
-        Green.paint(stddev_str)
+        Green.paint(stddev_str),
+        Blue.paint(user_str),
+        Blue.paint(system_str)
     );
     println!(" ");
 
@@ -215,7 +255,7 @@ pub fn run_benchmark(
     let mut warnings = vec![];
 
     // Check execution time
-    if execution_times.iter().any(|&t| t < MIN_EXECUTION_TIME) {
+    if times_real.iter().any(|&t| t < MIN_EXECUTION_TIME) {
         warnings.push(Warnings::FastExecutionTime);
     }
 

src/hyperfine/cputime.rs

@@ -0,0 +1,49 @@
+use libc::{getrusage, rusage, RUSAGE_CHILDREN};
+use std::mem;
+
+use hyperfine::internal::Second;
+
+#[derive(Debug, Copy, Clone)]
+pub struct CPUTimes {
+    /// Total amount of time spent executing in user mode
+    user_usec: i64,
+
+    /// Total amount of time spent executing in kernel mode
+    system_usec: i64,
+}
+
+#[derive(Debug, Copy, Clone)]
+pub struct CPUInterval {
+    /// Total amount of time spent executing in user mode
+    pub user: Second,
+
+    /// Total amount of time spent executing in kernel mode
+    pub system: Second,
+}
+
+/// Read CPU execution times (user and system time) from kernel
+pub fn get_cpu_times() -> CPUTimes {
+    let result: rusage = unsafe {
+        let mut buf = mem::zeroed();
+        let success = getrusage(RUSAGE_CHILDREN, &mut buf);
+        assert_eq!(0, success);
+        buf
+    };
+
+    const USEC_PER_SEC: i64 = 1000 * 1000;
+
+    CPUTimes {
+        user_usec: i64::from(result.ru_utime.tv_sec) * USEC_PER_SEC
+            + i64::from(result.ru_utime.tv_usec),
+        system_usec: i64::from(result.ru_stime.tv_sec) * USEC_PER_SEC
+            + i64::from(result.ru_stime.tv_usec),
+    }
+}
+
+/// Compute the time intervals in between two CPUTimes snapshots
+pub fn get_cpu_interval(start: &CPUTimes, end: &CPUTimes) -> CPUInterval {
+    CPUInterval {
+        user: ((end.user_usec - start.user_usec) as f64) * 1e-6,
+        system: ((end.system_usec - start.system_usec) as f64) * 1e-6,
+    }
+}

src/hyperfine/mod.rs

@@ -1,3 +1,4 @@
 pub mod benchmark;
 pub mod format;
 pub mod internal;
+pub mod cputime;

src/main.rs

@@ -2,6 +2,7 @@ extern crate ansi_term;
 #[macro_use]
 extern crate clap;
 extern crate indicatif;
+extern crate libc;
 extern crate statistical;
 
 use std::cmp;