Extract common functionality

src/benchmark/executor.rs

@@ -3,27 +3,67 @@ use std::process::{ExitStatus, Stdio};
 use crate::command::Command;
 use crate::options::{CmdFailureAction, CommandOutputPolicy, Options, OutputStyleOption, Shell};
 use crate::output::progress_bar::get_progress_bar;
-use crate::shell::execute_and_time;
-use crate::timer::wallclocktimer::WallClockTimer;
+use crate::timer::{execute_and_measure, TimerResult};
+use crate::util::randomized_environment_offset;
 use crate::util::units::Second;
 
 use super::timing_result::TimingResult;
 
-use anyhow::{bail, Result};
+use anyhow::{bail, Context, Result};
 use statistical::mean;
 
 pub trait Executor {
-    fn time_command(
+    /// Run the given command and measure the execution time
+    fn run_command_and_measure(
         &self,
         command: &Command<'_>,
         command_failure_action: Option<CmdFailureAction>,
     ) -> Result<(TimingResult, ExitStatus)>;
 
+    /// Perform a calibration of this executor. For example,
+    /// when running commands through a shell, we need to
+    /// measure the shell spawning time separately in order
+    /// to subtract it from the full runtime later.
     fn calibrate(&mut self) -> Result<()>;
 
+    /// Return the time overhead for this executor when
+    /// performing a measurement. This should return the time
+    /// that is being used in addition to the actual runtime
+    /// of the command.
     fn time_overhead(&self) -> Second;
 }
 
+fn run_command_and_measure_common(
+    mut command: std::process::Command,
+    command_failure_action: CmdFailureAction,
+    command_output_policy: CommandOutputPolicy,
+    command_name: &str,
+) -> Result<TimerResult> {
+    let (stdout, stderr) = command_output_policy.get_stdout_stderr();
+    command.stdin(Stdio::null()).stdout(stdout).stderr(stderr);
+
+    command.env(
+        "HYPERFINE_RANDOMIZED_ENVIRONMENT_OFFSET",
+        randomized_environment_offset::value(),
+    );
+
+    let result = execute_and_measure(command)
+        .with_context(|| format!("Failed to run command '{}'", command_name))?;
+
+    if command_failure_action == CmdFailureAction::RaiseError && !result.status.success() {
+        bail!(
+            "{}. Use the '-i'/'--ignore-failure' option if you want to ignore this. \
+            Alternatively, use the '--show-output' option to debug what went wrong.",
+            result.status.code().map_or(
+                "The process has been terminated by a signal".into(),
+                |c| format!("Command terminated with non-zero exit code: {}", c)
+            )
+        );
+    }
+
+    Ok(result)
+}
+
 pub struct ShellExecutor<'a> {
     options: &'a Options,
     shell: &'a Shell,
@@ -31,14 +71,6 @@ pub struct ShellExecutor<'a> {
 }
 
 impl<'a> ShellExecutor<'a> {
-    fn subtract_shell_spawning_time(&self, time: Second, shell_spawning_time: Second) -> Second {
-        if time < shell_spawning_time {
-            0.0
-        } else {
-            time - shell_spawning_time
-        }
-    }
-
     pub fn new(shell: &'a Shell, options: &'a Options) -> Self {
         ShellExecutor {
             shell,
@@ -49,50 +81,35 @@ impl<'a> ShellExecutor<'a> {
 }
 
 impl<'a> Executor for ShellExecutor<'a> {
-    /// Run the given shell command and measure the execution time
-    fn time_command(
+    fn run_command_and_measure(
         &self,
         command: &Command<'_>,
         command_failure_action: Option<CmdFailureAction>,
     ) -> Result<(TimingResult, ExitStatus)> {
-        let (stdout, stderr) = match self.options.command_output_policy {
-            CommandOutputPolicy::Discard => (Stdio::null(), Stdio::null()),
-            CommandOutputPolicy::Forward => (Stdio::inherit(), Stdio::inherit()),
-        };
+        let mut command_builder = self.shell.command();
+        command_builder
+            .arg(if cfg!(windows) { "/C" } else { "-c" })
+            .arg(command.get_command_line());
 
-        let wallclock_timer = WallClockTimer::start();
-        let result = execute_and_time(stdout, stderr, &command.get_shell_command(), self.shell)?;
-        let mut time_real = wallclock_timer.stop();
-
-        let mut time_user = result.user_time;
-        let mut time_system = result.system_time;
-
-        if command_failure_action.unwrap_or(self.options.command_failure_action)
-            == CmdFailureAction::RaiseError
-            && !result.status.success()
-        {
-            bail!(
-                "{}. Use the '-i'/'--ignore-failure' option if you want to ignore this. \
-                Alternatively, use the '--show-output' option to debug what went wrong.",
-                result.status.code().map_or(
-                    "The process has been terminated by a signal".into(),
-                    |c| format!("Command terminated with non-zero exit code: {}", c)
-                )
-            );
-        }
+        let mut result = run_command_and_measure_common(
+            command_builder,
+            command_failure_action.unwrap_or(self.options.command_failure_action),
+            self.options.command_output_policy,
+            &command.get_command_line(),
+        )?;
 
         // Subtract shell spawning time
         if let Some(spawning_time) = self.shell_spawning_time {
-            time_real = self.subtract_shell_spawning_time(time_real, spawning_time.time_real);
-            time_user = self.subtract_shell_spawning_time(time_user, spawning_time.time_user);
-            time_system = self.subtract_shell_spawning_time(time_system, spawning_time.time_system);
+            result.time_real = (result.time_real - spawning_time.time_real).max(0.0);
+            result.time_user = (result.time_user - spawning_time.time_user).max(0.0);
+            result.time_system = (result.time_system - spawning_time.time_system).max(0.0);
         }
 
         Ok((
             TimingResult {
-                time_real,
-                time_user,
-                time_system,
+                time_real: result.time_real,
+                time_user: result.time_user,
+                time_system: result.time_system,
             },
             result.status,
         ))
@@ -117,7 +134,7 @@ impl<'a> Executor for ShellExecutor<'a> {
 
         for _ in 0..COUNT {
             // Just run the shell without any command
-            let res = self.time_command(&Command::new(None, ""), None);
+            let res = self.run_command_and_measure(&Command::new(None, ""), None);
 
             match res {
                 Err(_) => {
@@ -183,7 +200,7 @@ impl MockExecutor {
 }
 
 impl Executor for MockExecutor {
-    fn time_command(
+    fn run_command_and_measure(
         &self,
         command: &Command<'_>,
         _command_failure_action: Option<CmdFailureAction>,
@@ -202,7 +219,7 @@ impl Executor for MockExecutor {
 
         Ok((
             TimingResult {
-                time_real: Self::extract_time(command.get_shell_command()),
+                time_real: Self::extract_time(command.get_command_line()),
                 time_user: 0.0,
                 time_system: 0.0,
             },

src/benchmark/mod.rs

@@ -57,7 +57,7 @@ impl<'a> Benchmark<'a> {
         error_output: &'static str,
     ) -> Result<TimingResult> {
         self.executor
-            .time_command(command, Some(CmdFailureAction::RaiseError))
+            .run_command_and_measure(command, Some(CmdFailureAction::RaiseError))
             .map(|r| r.0)
             .map_err(|_| anyhow!(error_output))
     }
@@ -163,7 +163,7 @@ impl<'a> Benchmark<'a> {
 
             for _ in 0..self.options.warmup_count {
                 let _ = run_preparation_command()?;
-                let _ = self.executor.time_command(self.command, None)?;
+                let _ = self.executor.run_command_and_measure(self.command, None)?;
                 if let Some(bar) = progress_bar.as_ref() {
                     bar.inc(1)
                 }
@@ -189,7 +189,7 @@ impl<'a> Benchmark<'a> {
             preparation_result.map_or(0.0, |res| res.time_real + self.executor.time_overhead());
 
         // Initial timing run
-        let (res, status) = self.executor.time_command(self.command, None)?;
+        let (res, status) = self.executor.run_command_and_measure(self.command, None)?;
         let success = status.success();
 
         // Determine number of benchmark runs
@@ -239,7 +239,7 @@ impl<'a> Benchmark<'a> {
                 bar.set_message(msg.to_owned())
             }
 
-            let (res, status) = self.executor.time_command(self.command, None)?;
+            let (res, status) = self.executor.run_command_and_measure(self.command, None)?;
             let success = status.success();
 
             times_real.push(res.time_real);

src/command.rs

@@ -55,12 +55,12 @@ impl<'a> Command<'a> {
 
     pub fn get_name(&self) -> String {
         self.name.map_or_else(
-            || self.get_shell_command(),
+            || self.get_command_line(),
             |name| self.replace_parameters_in(name),
         )
     }
 
-    pub fn get_shell_command(&self) -> String {
+    pub fn get_command_line(&self) -> String {
         self.replace_parameters_in(self.expression)
     }
 
@@ -82,7 +82,7 @@ impl<'a> Command<'a> {
         //
         //     hyperfine -L foo 'a,{bar}' -L bar 'baz,quux' 'echo {foo} {bar}'
         //
-        // should not ever run 'echo baz baz'. See `test_get_shell_command_nonoverlapping`.
+        // should not ever run 'echo baz baz'. See `test_get_command_line_nonoverlapping`.
         'outer: while let Some(head) = remaining.chars().next() {
             for (k, v) in &replacements {
                 if remaining.starts_with(k.as_str()) {
@@ -318,7 +318,7 @@ impl<'a> Commands<'a> {
 }
 
 #[test]
-fn test_get_shell_command_nonoverlapping() {
+fn test_get_command_line_nonoverlapping() {
     let cmd = Command::new_parametrized(
         None,
         "echo {foo} {bar}",
@@ -327,7 +327,7 @@ fn test_get_shell_command_nonoverlapping() {
             ("bar", ParameterValue::Text("quux".into())),
         ],
     );
-    assert_eq!(cmd.get_shell_command(), "echo {bar} baz quux");
+    assert_eq!(cmd.get_command_line(), "echo {bar} baz quux");
 }
 
 #[test]
@@ -345,7 +345,7 @@ fn test_get_parameterized_command_name() {
 
 impl<'a> fmt::Display for Command<'a> {
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(f, "{}", self.get_shell_command())
+        write!(f, "{}", self.get_command_line())
     }
 }
 
@@ -404,8 +404,8 @@ fn test_build_parameter_list_commands() {
     assert_eq!(commands.len(), 2);
     assert_eq!(commands[0].get_name(), "name-1");
     assert_eq!(commands[1].get_name(), "name-2");
-    assert_eq!(commands[0].get_shell_command(), "echo 1");
-    assert_eq!(commands[1].get_shell_command(), "echo 2");
+    assert_eq!(commands[0].get_command_line(), "echo 1");
+    assert_eq!(commands[1].get_command_line(), "echo 2");
 }
 
 #[test]
@@ -427,8 +427,8 @@ fn test_build_parameter_scan_commands() {
     assert_eq!(commands.len(), 2);
     assert_eq!(commands[0].get_name(), "name-1");
     assert_eq!(commands[1].get_name(), "name-2");
-    assert_eq!(commands[0].get_shell_command(), "echo 1");
-    assert_eq!(commands[1].get_shell_command(), "echo 2");
+    assert_eq!(commands[0].get_command_line(), "echo 1");
+    assert_eq!(commands[1].get_command_line(), "echo 2");
 }
 
 #[test]
@@ -444,7 +444,7 @@ fn test_parameter_scan_commands_int() {
     .unwrap();
     assert_eq!(commands.len(), 3);
     assert_eq!(commands[2].get_name(), "echo 7");
-    assert_eq!(commands[2].get_shell_command(), "echo 7");
+    assert_eq!(commands[2].get_command_line(), "echo 7");
 }
 
 #[test]
@@ -464,7 +464,7 @@ fn test_parameter_scan_commands_decimal() {
     .unwrap();
     assert_eq!(commands.len(), 4);
     assert_eq!(commands[3].get_name(), "echo 0.99");
-    assert_eq!(commands[3].get_shell_command(), "echo 0.99");
+    assert_eq!(commands[3].get_command_line(), "echo 0.99");
 }
 
 #[test]

src/main.rs

@@ -18,7 +18,6 @@ pub mod options;
 pub mod outlier_detection;
 pub mod output;
 pub mod parameter;
-pub mod shell;
 pub mod timer;
 pub mod util;
 

src/options.rs

@@ -1,4 +1,4 @@
-use std::process::Command;
+use std::process::{Command, Stdio};
 use std::{cmp, fmt};
 
 use anyhow::ensure;
@@ -124,6 +124,15 @@ impl Default for CommandOutputPolicy {
     }
 }
 
+impl CommandOutputPolicy {
+    pub fn get_stdout_stderr(&self) -> (Stdio, Stdio) {
+        match self {
+            CommandOutputPolicy::Discard => (Stdio::null(), Stdio::null()),
+            CommandOutputPolicy::Forward => (Stdio::inherit(), Stdio::inherit()),
+        }
+    }
+}
+
 pub enum ExecutorKind {
     Shell(Shell),
     Mock(Option<String>),

src/shell.rs

@@ -1,87 +0,0 @@
-use std::process::{ExitStatus, Stdio};
-
-use crate::options::Shell;
-
-use anyhow::{Context, Result};
-
-/// Used to indicate the result of running a command
-#[derive(Debug, Copy, Clone)]
-pub struct ExecuteResult {
-    /// The amount of user time the process used
-    pub user_time: f64,
-
-    /// The amount of cpu time the process used
-    pub system_time: f64,
-
-    /// The exit status of the process
-    pub status: ExitStatus,
-}
-
-fn randomized_environment_offset_value() -> String {
-    "X".repeat(rand::random::<usize>() % 4096usize)
-}
-
-/// Execute the given command and return a timing summary
-#[cfg(not(windows))]
-pub fn execute_and_time(
-    stdout: Stdio,
-    stderr: Stdio,
-    command: &str,
-    shell: &Shell,
-) -> Result<ExecuteResult> {
-    let cpu_timer = crate::timer::unix_timer::CPUTimer::start();
-
-    let status = shell
-        .command()
-        .arg("-c")
-        .arg(command)
-        .env(
-            "HYPERFINE_RANDOMIZED_ENVIRONMENT_OFFSET",
-            randomized_environment_offset_value(),
-        )
-        .stdin(Stdio::null())
-        .stdout(stdout)
-        .stderr(stderr)
-        .status()
-        .with_context(|| format!("Failed to run command '{}'", command))?;
-
-    let (user_time, system_time) = cpu_timer.stop();
-
-    Ok(ExecuteResult {
-        user_time,
-        system_time,
-        status,
-    })
-}
-
-/// Execute the given command and return a timing summary
-#[cfg(windows)]
-pub fn execute_and_time(
-    stdout: Stdio,
-    stderr: Stdio,
-    command: &str,
-    shell: &Shell,
-) -> Result<ExecuteResult> {
-    let mut child = shell
-        .command()
-        .arg("/C")
-        .arg(command)
-        .env(
-            "HYPERFINE_RANDOMIZED_ENVIRONMENT_OFFSET",
-            randomized_environment_offset_value(),
-        )
-        .stdin(Stdio::null())
-        .stdout(stdout)
-        .stderr(stderr)
-        .spawn()
-        .with_context(|| format!("Failed to run command '{}'", command))?;
-    let cpu_timer = crate::timer::windows_timer::CPUTimer::start_for_process(&child);
-    let status = child.wait()?;
-
-    let (user_time, system_time) = cpu_timer.stop();
-    Ok(ExecuteResult {
-        user_time,
-        system_time,
-        status,
-    })
-}

src/timer/mod.rs

@@ -1,15 +1,20 @@
-use crate::util::units::Second;
-
-pub mod wallclocktimer;
+mod wall_clock_timer;
 
 #[cfg(windows)]
-pub mod windows_timer;
+mod windows_timer;
 
 #[cfg(not(windows))]
-pub mod unix_timer;
+mod unix_timer;
+
+use crate::util::units::Second;
+use wall_clock_timer::WallClockTimer;
+
+use std::process::{Command, ExitStatus};
+
+use anyhow::Result;
 
 #[derive(Debug, Copy, Clone)]
-pub struct CPUTimes {
+struct CPUTimes {
     /// Total amount of time spent executing in user mode
     pub user_usec: i64,
 
@@ -17,11 +22,43 @@ pub struct CPUTimes {
     pub system_usec: i64,
 }
 
+/// Used to indicate the result of running a command
 #[derive(Debug, Copy, Clone)]
-pub struct CPUInterval {
-    /// Total amount of time spent executing in user mode
-    pub user: Second,
+pub struct TimerResult {
+    pub time_real: Second,
+    pub time_user: Second,
+    pub time_system: Second,
 
-    /// Total amount of time spent executing in kernel mode
-    pub system: Second,
+    /// The exit status of the process
+    pub status: ExitStatus,
+}
+
+/// Execute the given command and return a timing summary
+pub fn execute_and_measure(mut command: Command) -> Result<TimerResult> {
+    let wallclock_timer = WallClockTimer::start();
+
+    #[cfg(not(windows))]
+    let ((time_user, time_system), status) = {
+        let cpu_timer = self::unix_timer::CPUTimer::start();
+        let status = command.status()?;
+        (cpu_timer.stop(), status)
+    };
+
+    #[cfg(windows)]
+    let ((time_user, time_system), status) = {
+        let mut child = command.spawn()?;
+        let cpu_timer = self::windows_timer::CPUTimer::start_for_process(&child);
+        let status = child.wait()?;
+
+        (cpu_timer.stop(), status)
+    };
+
+    let time_real = wallclock_timer.stop();
+
+    Ok(TimerResult {
+        time_real,
+        time_user,
+        time_system,
+        status,
+    })
 }

src/timer/unix_timer.rs

@@ -2,9 +2,18 @@
 
 use std::mem;
 
-use crate::timer::{CPUInterval, CPUTimes};
+use crate::timer::CPUTimes;
 use crate::util::units::Second;
 
+#[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,
+}
+
 pub struct CPUTimer {
     start_cpu: CPUTimes,
 }

src/util/mod.rs

@@ -1,4 +1,5 @@
 pub mod exit_code;
 pub mod min_max;
 pub mod number;
+pub mod randomized_environment_offset;
 pub mod units;

src/util/randomized_environment_offset.rs

@@ -0,0 +1,8 @@
+/// Returns a string with a random length. This value will be set as an environment
+/// variable to account for offset effects. See [1] for more details.
+///
+/// [1] Mytkowicz, 2009. Producing Wrong Data Without Doing Anything Obviously Wrong!.
+///     Sigplan Notices - SIGPLAN. 44. 265-276. 10.1145/1508284.1508275.
+pub fn value() -> String {
+    "X".repeat(rand::random::<usize>() % 4096usize)
+}

tests/integration_tests.rs

@@ -147,6 +147,18 @@ fn can_run_failing_commands_with_ignore_failure_option() {
         .success();
 }
 
+#[test]
+fn shows_output_of_benchmarked_command() {
+    hyperfine()
+        .arg("--runs=2")
+        .arg("--command-name=dummy")
+        .arg("--show-output")
+        .arg("echo 4fd47015")
+        .assert()
+        .success()
+        .stdout(predicate::str::contains("4fd47015").count(2));
+}
+
 #[test]
 fn runs_commands_using_user_defined_shell() {
     hyperfine()