summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorDavid Peter <mail@david-peter.de>2022-02-22 08:36:56 +0100
committerDavid Peter <mail@david-peter.de>2022-02-22 08:36:56 +0100
commita1885ac746016e10cb6d754dad7c5d4ee09a3b7d (patch)
treeee0d907150439f38635994f84ffa45f1c55ab2b5
parent319cfac4ab92edea41e845c6c09fd6b08084e85d (diff)
Add debug/mock mode
-rw-r--r--src/app.rs6
-rw-r--r--src/benchmark/executor.rs230
-rw-r--r--src/benchmark/mod.rs183
-rw-r--r--src/benchmark/scheduler.rs17
-rw-r--r--src/options.rs27
-rw-r--r--tests/integration_tests.rs94
6 files changed, 376 insertions, 181 deletions
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()),
+ );
+}