diff options
author | David Peter <mail@david-peter.de> | 2022-02-22 08:36:56 +0100 |
---|---|---|
committer | David Peter <mail@david-peter.de> | 2022-02-22 08:36:56 +0100 |
commit | a1885ac746016e10cb6d754dad7c5d4ee09a3b7d (patch) | |
tree | ee0d907150439f38635994f84ffa45f1c55ab2b5 | |
parent | 319cfac4ab92edea41e845c6c09fd6b08084e85d (diff) |
Add debug/mock mode
-rw-r--r-- | src/app.rs | 6 | ||||
-rw-r--r-- | src/benchmark/executor.rs | 230 | ||||
-rw-r--r-- | src/benchmark/mod.rs | 183 | ||||
-rw-r--r-- | src/benchmark/scheduler.rs | 17 | ||||
-rw-r--r-- | src/options.rs | 27 | ||||
-rw-r--r-- | tests/integration_tests.rs | 94 |
6 files changed, 376 insertions, 181 deletions
@@ -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(×_real), + time_user: mean(×_user), + time_system: mean(×_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(×_real), - time_user: mean(×_user), - time_system: mean(×_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()), + ); +} |