From a1885ac746016e10cb6d754dad7c5d4ee09a3b7d Mon Sep 17 00:00:00 2001
From: David Peter <mail@david-peter.de>
Date: Tue, 22 Feb 2022 08:36:56 +0100
Subject: [PATCH] Add debug/mock mode

---
 src/app.rs                 |   6 +
 src/benchmark/executor.rs  | 230 +++++++++++++++++++++++++++++++++++++
 src/benchmark/mod.rs       | 183 +++--------------------------
 src/benchmark/scheduler.rs |  17 +--
 src/options.rs             |  27 ++++-
 tests/integration_tests.rs |  94 +++++++++++++++
 6 files changed, 376 insertions(+), 181 deletions(-)
 create mode 100644 src/benchmark/executor.rs

diff --git a/src/app.rs b/src/app.rs
index b1f1ef2..a0e76c4 100644
--- a/src/app.rs
+++ b/src/app.rs
@@ -249,6 +249,12 @@ fn build_app() -> App<'static> {
                 .help("Give a meaningful name to a command. This can be specified multiple times \
                        if several commands are benchmarked."),
         )
+        .arg(
+            Arg::new("debug-mode")
+            .long("debug-mode")
+            .hide(true)
+            .help("Enable debug mode which does not actually run commands, but returns fake times when the command is 'sleep <time>'")
+        )
 }
 
 #[test]
diff --git a/src/benchmark/executor.rs b/src/benchmark/executor.rs
new file mode 100644
index 0000000..9022cad
--- /dev/null
+++ b/src/benchmark/executor.rs
@@ -0,0 +1,230 @@
+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::{TimerStart, TimerStop};
+use crate::util::units::Second;
+
+use super::timing_result::TimingResult;
+
+use anyhow::{bail, Result};
+use statistical::mean;
+
+pub trait Executor {
+    fn time_command(
+        &self,
+        command: &Command<'_>,
+        command_failure_action: Option<CmdFailureAction>,
+    ) -> Result<(TimingResult, ExitStatus)>;
+
+    fn calibrate(&mut self) -> Result<()>;
+
+    fn time_overhead(&self) -> Second;
+}
+
+pub struct ShellExecutor<'a> {
+    options: &'a Options,
+    shell: &'a Shell,
+    shell_spawning_time: Option<TimingResult>,
+}
+
+impl<'a> ShellExecutor<'a> {
+    /// Correct for shell spawning time
+    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,
+            options,
+            shell_spawning_time: None,
+        }
+    }
+}
+
+impl<'a> Executor for ShellExecutor<'a> {
+    /// Run the given shell command and measure the execution time
+    fn time_command(
+        &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 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)
+                )
+            );
+        }
+
+        // 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);
+        }
+
+        Ok((
+            TimingResult {
+                time_real,
+                time_user,
+                time_system,
+            },
+            result.status,
+        ))
+    }
+
+    /// Measure the average shell spawning time
+    fn calibrate(&mut self) -> Result<()> {
+        const COUNT: u64 = 50;
+        let progress_bar = if self.options.output_style != OutputStyleOption::Disabled {
+            Some(get_progress_bar(
+                COUNT,
+                "Measuring shell spawning time",
+                self.options.output_style,
+            ))
+        } else {
+            None
+        };
+
+        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 = self.time_command(&Command::new(None, ""), None);
+
+            match res {
+                Err(_) => {
+                    let shell_cmd = if cfg!(windows) {
+                        format!("{} /C \"\"", self.shell)
+                    } else {
+                        format!("{} -c \"\"", self.shell)
+                    };
+
+                    bail!(
+                        "Could not measure shell execution time. Make sure you can run '{}'.",
+                        shell_cmd
+                    );
+                }
+                Ok((r, _)) => {
+                    times_real.push(r.time_real);
+                    times_user.push(r.time_user);
+                    times_system.push(r.time_system);
+                }
+            }
+
+            if let Some(bar) = progress_bar.as_ref() {
+                bar.inc(1)
+            }
+        }
+
+        if let Some(bar) = progress_bar.as_ref() {
+            bar.finish_and_clear()
+        }
+
+        self.shell_spawning_time = Some(TimingResult {
+            time_real: mean(&times_real),
+            time_user: mean(&times_user),
+            time_system: mean(&times_system),
+        });
+
+        Ok(())
+    }
+
+    fn time_overhead(&self) -> Second {
+        self.shell_spawning_time.unwrap().time_real
+    }
+}
+
+#[derive(Clone)]
+pub struct MockExecutor<'a> {
+    shell: &'a Shell,
+}
+
+impl<'a> MockExecutor<'a> {
+    pub fn new(shell: &'a Shell) -> Self {
+        MockExecutor { shell }
+    }
+
+    fn extract_time<S: AsRef<str>>(sleep_command: S) -> Second {
+        assert!(sleep_command.as_ref().starts_with("sleep "));
+        sleep_command
+            .as_ref()
+            .trim_start_matches("sleep ")
+            .parse::<Second>()
+            .unwrap()
+    }
+}
+
+impl<'a> Executor for MockExecutor<'a> {
+    fn time_command(
+        &self,
+        command: &Command<'_>,
+        _command_failure_action: Option<CmdFailureAction>,
+    ) -> Result<(TimingResult, ExitStatus)> {
+        #[cfg(unix)]
+        let status = {
+            use std::os::unix::process::ExitStatusExt;
+            ExitStatus::from_raw(0)
+        };
+
+        #[cfg(windows)]
+        let status = {
+            use std::os::windows::process::ExitStatusExt;
+            ExitStatus::from_raw(0)
+        };
+
+        Ok((
+            TimingResult {
+                time_real: Self::extract_time(command.get_shell_command()),
+                time_user: 0.0,
+                time_system: 0.0,
+            },
+            status,
+        ))
+    }
+
+    fn calibrate(&mut self) -> Result<()> {
+        Ok(())
+    }
+
+    fn time_overhead(&self) -> Second {
+        match self.shell {
+            Shell::Default(_) => 0.0,
+            Shell::Custom(shell) => Self::extract_time(&shell[0]),
+        }
+    }
+}
+
+#[test]
+fn test_mock_executor_extract_time() {
+    assert_eq!(MockExecutor::extract_time("sleep 0.1"), 0.1);
+}
diff --git a/src/benchmark/mod.rs b/src/benchmark/mod.rs
index 42fc6e1..59f07fb 100644
--- a/src/benchmark/mod.rs
+++ b/src/benchmark/mod.rs
@@ -1,166 +1,38 @@
 pub mod benchmark_result;
+pub mod executor;
 pub mod relative_speed;
 pub mod scheduler;
 pub mod timing_result;
 
 use std::cmp;
-use std::process::{ExitStatus, Stdio};
 
 use crate::command::Command;
-use crate::options::{CmdFailureAction, CommandOutputPolicy, Options, OutputStyleOption, Shell};
+use crate::options::{CmdFailureAction, Options, OutputStyleOption};
 use crate::outlier_detection::{modified_zscores, OUTLIER_THRESHOLD};
 use crate::output::format::{format_duration, format_duration_unit};
 use crate::output::progress_bar::get_progress_bar;
 use crate::output::warnings::Warnings;
 use crate::parameter::ParameterNameAndValue;
-use crate::shell::execute_and_time;
-use crate::timer::wallclocktimer::WallClockTimer;
-use crate::timer::{TimerStart, TimerStop};
 use crate::util::exit_code::extract_exit_code;
 use crate::util::min_max::{max, min};
 use crate::util::units::Second;
 use benchmark_result::BenchmarkResult;
 use timing_result::TimingResult;
 
-use anyhow::{anyhow, bail, Result};
+use anyhow::{anyhow, Result};
 use colored::*;
 use statistical::{mean, median, standard_deviation};
 
+use self::executor::Executor;
+
 /// Threshold for warning about fast execution time
 pub const MIN_EXECUTION_TIME: Second = 5e-3;
 
-/////////////// TODO: refactor the following part
-
-/// Correct for shell spawning time
-fn subtract_shell_spawning_time(time: Second, shell_spawning_time: Second) -> Second {
-    if time < shell_spawning_time {
-        0.0
-    } else {
-        time - shell_spawning_time
-    }
-}
-
-/// Run the given shell command and measure the execution time
-pub fn time_shell_command(
-    shell: &Shell,
-    command: &Command<'_>,
-    command_output_policy: CommandOutputPolicy,
-    failure_action: CmdFailureAction,
-    shell_spawning_time: Option<&TimingResult>,
-) -> Result<(TimingResult, ExitStatus)> {
-    let (stdout, stderr) = match command_output_policy {
-        CommandOutputPolicy::Discard => (Stdio::null(), Stdio::null()),
-        CommandOutputPolicy::Forward => (Stdio::inherit(), Stdio::inherit()),
-    };
-
-    let wallclock_timer = WallClockTimer::start();
-    let result = execute_and_time(stdout, stderr, &command.get_shell_command(), shell)?;
-    let mut time_real = wallclock_timer.stop();
-
-    let mut time_user = result.user_time;
-    let mut time_system = result.system_time;
-
-    if 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)
-            )
-        );
-    }
-
-    // Correct for shell spawning time
-    if let Some(spawning_time) = shell_spawning_time {
-        time_real = subtract_shell_spawning_time(time_real, spawning_time.time_real);
-        time_user = subtract_shell_spawning_time(time_user, spawning_time.time_user);
-        time_system = subtract_shell_spawning_time(time_system, spawning_time.time_system);
-    }
-
-    Ok((
-        TimingResult {
-            time_real,
-            time_user,
-            time_system,
-        },
-        result.status,
-    ))
-}
-
-/// Measure the average shell spawning time
-pub fn mean_shell_spawning_time(
-    shell: &Shell,
-    style: OutputStyleOption,
-    command_output_policy: CommandOutputPolicy,
-) -> Result<TimingResult> {
-    const COUNT: u64 = 50;
-    let progress_bar = if style != OutputStyleOption::Disabled {
-        Some(get_progress_bar(
-            COUNT,
-            "Measuring shell spawning time",
-            style,
-        ))
-    } else {
-        None
-    };
-
-    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(
-            shell,
-            &Command::new(None, ""),
-            command_output_policy,
-            CmdFailureAction::RaiseError,
-            None,
-        );
-
-        match res {
-            Err(_) => {
-                let shell_cmd = if cfg!(windows) {
-                    format!("{} /C \"\"", shell)
-                } else {
-                    format!("{} -c \"\"", shell)
-                };
-
-                bail!(
-                    "Could not measure shell execution time. Make sure you can run '{}'.",
-                    shell_cmd
-                );
-            }
-            Ok((r, _)) => {
-                times_real.push(r.time_real);
-                times_user.push(r.time_user);
-                times_system.push(r.time_system);
-            }
-        }
-
-        if let Some(bar) = progress_bar.as_ref() {
-            bar.inc(1)
-        }
-    }
-
-    if let Some(bar) = progress_bar.as_ref() {
-        bar.finish_and_clear()
-    }
-
-    Ok(TimingResult {
-        time_real: mean(&times_real),
-        time_user: mean(&times_user),
-        time_system: mean(&times_system),
-    })
-}
-///////////////
-
 pub struct Benchmark<'a> {
     number: usize,
     command: &'a Command<'a>,
     options: &'a Options,
-    shell_spawning_time: &'a TimingResult,
+    executor: &'a dyn Executor,
 }
 
 impl<'a> Benchmark<'a> {
@@ -168,13 +40,13 @@ impl<'a> Benchmark<'a> {
         number: usize,
         command: &'a Command<'a>,
         options: &'a Options,
-        shell_spawning_time: &'a TimingResult,
+        executor: &'a dyn Executor,
     ) -> Self {
         Benchmark {
             number,
             command,
             options,
-            shell_spawning_time,
+            executor,
         }
     }
 
@@ -184,15 +56,10 @@ impl<'a> Benchmark<'a> {
         command: &Command<'_>,
         error_output: &'static str,
     ) -> Result<TimingResult> {
-        time_shell_command(
-            &self.options.shell,
-            command,
-            self.options.command_output_policy,
-            CmdFailureAction::RaiseError,
-            None,
-        )
-        .map(|r| r.0)
-        .map_err(|_| anyhow!(error_output))
+        self.executor
+            .time_command(command, Some(CmdFailureAction::RaiseError))
+            .map(|r| r.0)
+            .map_err(|_| anyhow!(error_output))
     }
 
     /// Run the command specified by `--setup`.
@@ -297,13 +164,7 @@ impl<'a> Benchmark<'a> {
 
             for _ in 0..self.options.warmup_count {
                 let _ = run_preparation_command()?;
-                let _ = time_shell_command(
-                    &self.options.shell,
-                    self.command,
-                    self.options.command_output_policy,
-                    self.options.command_failure_action,
-                    None,
-                )?;
+                let _ = self.executor.time_command(self.command, None)?;
                 if let Some(bar) = progress_bar.as_ref() {
                     bar.inc(1)
                 }
@@ -327,18 +188,12 @@ impl<'a> Benchmark<'a> {
         let preparation_result = run_preparation_command()?;
 
         // Initial timing run
-        let (res, status) = time_shell_command(
-            &self.options.shell,
-            self.command,
-            self.options.command_output_policy,
-            self.options.command_failure_action,
-            Some(&self.shell_spawning_time),
-        )?;
+        let (res, status) = self.executor.time_command(self.command, None)?;
         let success = status.success();
 
         // Determine number of benchmark runs
         let runs_in_min_time = (self.options.min_benchmarking_time
-            / (res.time_real + preparation_result.time_real + self.shell_spawning_time.time_real))
+            / (res.time_real + preparation_result.time_real + self.executor.time_overhead()))
             as u64;
 
         let count = {
@@ -383,13 +238,7 @@ impl<'a> Benchmark<'a> {
                 bar.set_message(msg.to_owned())
             }
 
-            let (res, status) = time_shell_command(
-                &self.options.shell,
-                self.command,
-                self.options.command_output_policy,
-                self.options.command_failure_action,
-                Some(self.shell_spawning_time),
-            )?;
+            let (res, status) = self.executor.time_command(self.command, None)?;
             let success = status.success();
 
             times_real.push(res.time_real);
diff --git a/src/benchmark/scheduler.rs b/src/benchmark/scheduler.rs
index 9853e2b..c4e3603 100644
--- a/src/benchmark/scheduler.rs
+++ b/src/benchmark/scheduler.rs
@@ -1,11 +1,12 @@
 use colored::*;
 
 use super::benchmark_result::BenchmarkResult;
+use super::executor::{Executor, MockExecutor, ShellExecutor};
 use super::{relative_speed, Benchmark};
 
 use crate::command::Commands;
 use crate::export::ExportManager;
-use crate::options::{Options, OutputStyleOption};
+use crate::options::{ExecutorKind, Options, OutputStyleOption};
 
 use anyhow::Result;
 
@@ -31,16 +32,16 @@ impl<'a> Scheduler<'a> {
     }
 
     pub fn run_benchmarks(&mut self) -> Result<()> {
-        let shell_spawning_time = super::mean_shell_spawning_time(
-            // TODO
-            &self.options.shell,
-            self.options.output_style,
-            self.options.command_output_policy,
-        )?;
+        let mut executor: Box<dyn Executor> = match self.options.executor_kind {
+            ExecutorKind::Mock(ref shell) => Box::new(MockExecutor::new(shell)),
+            ExecutorKind::Shell(ref shell) => Box::new(ShellExecutor::new(shell, &self.options)),
+        };
+
+        executor.calibrate()?;
 
         for (number, cmd) in self.commands.iter().enumerate() {
             self.results
-                .push(Benchmark::new(number, cmd, self.options, &shell_spawning_time).run()?);
+                .push(Benchmark::new(number, cmd, self.options, &*executor).run()?);
 
             // We export (all results so far) after each individual benchmark, because
             // we would risk losing all results if a later benchmark fails.
diff --git a/src/options.rs b/src/options.rs
index e0edb73..7d82e39 100644
--- a/src/options.rs
+++ b/src/options.rs
@@ -124,6 +124,17 @@ impl Default for CommandOutputPolicy {
     }
 }
 
+pub enum ExecutorKind {
+    Shell(Shell),
+    Mock(Shell),
+}
+
+impl Default for ExecutorKind {
+    fn default() -> Self {
+        ExecutorKind::Shell(Shell::default())
+    }
+}
+
 /// The main settings for a hyperfine benchmark session
 pub struct Options {
     /// Upper and lower bound for the number of benchmark runs
@@ -150,8 +161,8 @@ pub struct Options {
     /// What color mode to use for the terminal output
     pub output_style: OutputStyleOption,
 
-    /// The shell to use for executing commands.
-    pub shell: Shell,
+    /// Determines how we run commands
+    pub executor_kind: ExecutorKind,
 
     /// What to do with the output of the benchmarked command
     pub command_output_policy: CommandOutputPolicy,
@@ -171,7 +182,7 @@ impl Default for Options {
             setup_command: None,
             cleanup_command: None,
             output_style: OutputStyleOption::Full,
-            shell: Shell::default(),
+            executor_kind: ExecutorKind::default(),
             command_output_policy: CommandOutputPolicy::Discard,
             time_unit: None,
         }
@@ -261,9 +272,13 @@ impl Options {
             OutputStyleOption::Disabled => {}
         };
 
-        if let Some(shell) = matches.value_of("shell") {
-            options.shell = Shell::from_str(shell)?;
-        }
+        options.executor_kind = match (matches.is_present("debug-mode"), matches.value_of("shell"))
+        {
+            (false, Some(shell)) => ExecutorKind::Shell(Shell::from_str(shell)?),
+            (false, None) => ExecutorKind::Shell(Shell::default()),
+            (true, Some(shell)) => ExecutorKind::Mock(Shell::from_str(shell)?),
+            (true, None) => ExecutorKind::Mock(Shell::default()),
+        };
 
         if matches.is_present("ignore-failure") {
             options.command_failure_action = CmdFailureAction::Ignore;
diff --git a/tests/integration_tests.rs b/tests/integration_tests.rs
index 29652ce..42aa787 100644
--- a/tests/integration_tests.rs
+++ b/tests/integration_tests.rs
@@ -3,6 +3,12 @@ use common::hyperfine;
 
 use predicates::prelude::*;
 
+pub fn hyperfine_debug() -> assert_cmd::Command {
+    let mut cmd = hyperfine();
+    cmd.arg("--debug-mode");
+    cmd
+}
+
 #[test]
 fn hyperfine_runs_successfully() {
     hyperfine()
@@ -157,3 +163,91 @@ fn runs_commands_using_user_defined_shell() {
             ),
         );
 }
+
+#[test]
+fn returns_mean_time_in_correct_unit() {
+    hyperfine_debug()
+        .arg("sleep 1.234")
+        .assert()
+        .success()
+        .stdout(predicate::str::contains("Time (mean ± σ):      1.234 s ±"));
+
+    hyperfine_debug()
+        .arg("sleep 0.123")
+        .assert()
+        .success()
+        .stdout(predicate::str::contains("Time (mean ± σ):     123.0 ms ±"));
+
+    hyperfine_debug()
+        .arg("--time-unit=millisecond")
+        .arg("sleep 1.234")
+        .assert()
+        .success()
+        .stdout(predicate::str::contains("Time (mean ± σ):     1234.0 ms ±"));
+}
+
+#[test]
+fn performs_ten_runs_for_slow_commands() {
+    hyperfine_debug()
+        .arg("--time-unit=millisecond")
+        .arg("sleep 0.5")
+        .assert()
+        .success()
+        .stdout(predicate::str::contains("10 runs"));
+}
+
+#[test]
+fn performs_three_seconds_of_benchmarking_for_fast_commands() {
+    hyperfine_debug()
+        .arg("--time-unit=millisecond")
+        .arg("sleep 0.01")
+        .assert()
+        .success()
+        .stdout(predicate::str::contains("300 runs"));
+}
+
+#[test]
+fn takes_time_of_preparation_command_into_account() {
+    hyperfine_debug()
+        .arg("--time-unit=millisecond")
+        .arg("--prepare=sleep 0.02")
+        .arg("sleep 0.01")
+        .assert()
+        .success()
+        .stdout(predicate::str::contains("100 runs"));
+}
+
+#[test]
+fn shows_benchmark_comparison_with_relative_times() {
+    hyperfine_debug()
+        .arg("sleep 1.0")
+        .arg("sleep 2.0")
+        .arg("sleep 3.0")
+        .assert()
+        .success()
+        .stdout(
+            predicate::str::contains("2.00 ± 0.00 times faster")
+                .and(predicate::str::contains("3.00 ± 0.00 times faster")),
+        );
+}
+
+#[test]
+fn performs_all_benchmarks_in_parameter_scan() {
+    hyperfine_debug()
+        .arg("--parameter-scan")
+        .arg("time")
+        .arg("30")
+        .arg("45")
+        .arg("--parameter-step-size")
+        .arg("5")
+        .arg("sleep {time}")
+        .assert()
+        .success()
+        .stdout(
+            predicate::str::contains("Benchmark 1: sleep 30")
+                .and(predicate::str::contains("Benchmark 2: sleep 35"))
+                .and(predicate::str::contains("Benchmark 3: sleep 40"))
+                .and(predicate::str::contains("Benchmark 4: sleep 45"))
+                .and(predicate::str::contains("Benchmark 5: sleep 50").not()),
+        );
+}