sharkdp/hyperfine
1
1
Fork 0
mirror of https://github.com/sharkdp/hyperfine.git synced 2024-08-17 18:00:31 +03:00
Code Issues Projects Releases Wiki Activity

Add debug/mock mode

Browse Source
This commit is contained in:
David Peter 2022-02-22 08:36:56 +01:00
parent 319cfac4ab
commit a1885ac746
6 changed files with 376 additions and 181 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
src/app.rs
View File

@ -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]

230
src/benchmark/executor.rs Normal file
View File

@ -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);
}

183
src/benchmark/mod.rs
View File

@ -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);

17
src/benchmark/scheduler.rs
View File

@ -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.

27
src/options.rs
View File

@ -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;

94
tests/integration_tests.rs
View File

@ -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()),
);
}