From dcfeede18e587c0f327532df04ec06d3edcf1bd2 Mon Sep 17 00:00:00 2001 From: David Peter Date: Sun, 20 Feb 2022 13:44:34 +0100 Subject: [PATCH] Move functionality to scheduler --- .../{result.rs => benchmark_result.rs} | 0 src/benchmark/mod.rs | 505 +----------------- src/benchmark/relative_speed.rs | 2 +- src/benchmark/scheduler.rs | 497 ++++++++++++++++- src/benchmark/timing_result.rs | 14 + src/export/asciidoc.rs | 2 +- src/export/csv.rs | 2 +- src/export/json.rs | 2 +- src/export/markdown.rs | 2 +- src/export/mod.rs | 2 +- 10 files changed, 514 insertions(+), 514 deletions(-) rename src/benchmark/{result.rs => benchmark_result.rs} (100%) create mode 100644 src/benchmark/timing_result.rs diff --git a/src/benchmark/result.rs b/src/benchmark/benchmark_result.rs similarity index 100% rename from src/benchmark/result.rs rename to src/benchmark/benchmark_result.rs diff --git a/src/benchmark/mod.rs b/src/benchmark/mod.rs index 3d4bd14..2e6c265 100644 --- a/src/benchmark/mod.rs +++ b/src/benchmark/mod.rs @@ -1,510 +1,9 @@ +pub mod benchmark_result; pub mod relative_speed; -pub mod result; pub mod scheduler; +pub mod timing_result; -use std::cmp; -use std::process::{ExitStatus, Stdio}; - -use colored::*; -use statistical::{mean, median, standard_deviation}; - -use crate::benchmark::result::BenchmarkResult; -use crate::command::Command; -use crate::options::{CmdFailureAction, CommandOutputPolicy, Options, OutputStyleOption, Shell}; -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::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 anyhow::{bail, Result}; - /// Threshold for warning about fast execution time pub const MIN_EXECUTION_TIME: Second = 5e-3; - -/// Results from timing a single command -#[derive(Debug, Default, Copy, Clone)] -pub struct TimingResult { - /// Wall clock time - pub time_real: Second, - - /// Time spent in user mode - pub time_user: Second, - - /// Time spent in kernel mode - pub time_system: Second, -} - -/// 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, -) -> 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 { - 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 = vec![]; - let mut times_user: Vec = vec![]; - let mut times_system: Vec = 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), - }) -} - -fn run_intermediate_command( - shell: &Shell, - command: &Option>, - command_output_policy: CommandOutputPolicy, - error_output: &'static str, -) -> Result { - if let Some(ref cmd) = command { - let res = time_shell_command( - shell, - cmd, - command_output_policy, - CmdFailureAction::RaiseError, - None, - ); - if res.is_err() { - bail!(error_output); - } - return res.map(|r| r.0); - } - Ok(TimingResult { - ..Default::default() - }) -} - -/// Run the command specified by `--setup`. -fn run_setup_command( - shell: &Shell, - command: &Option>, - output_policy: CommandOutputPolicy, -) -> Result { - let error_output = "The setup command terminated with a non-zero exit code. \ - Append ' || true' to the command if you are sure that this can be ignored."; - - run_intermediate_command(shell, command, output_policy, error_output) -} - -/// Run the command specified by `--prepare`. -fn run_preparation_command( - shell: &Shell, - command: &Option>, - output_policy: CommandOutputPolicy, -) -> Result { - let error_output = "The preparation command terminated with a non-zero exit code. \ - Append ' || true' to the command if you are sure that this can be ignored."; - - run_intermediate_command(shell, command, output_policy, error_output) -} - -/// Run the command specified by `--cleanup`. -fn run_cleanup_command( - shell: &Shell, - command: &Option>, - output_policy: CommandOutputPolicy, -) -> Result { - let error_output = "The cleanup command terminated with a non-zero exit code. \ - Append ' || true' to the command if you are sure that this can be ignored."; - - run_intermediate_command(shell, command, output_policy, error_output) -} - -/// Run the benchmark for a single shell command -pub fn run_benchmark( - num: usize, - cmd: &Command<'_>, - shell_spawning_time: TimingResult, - options: &Options, -) -> Result { - let command_name = cmd.get_name(); - if options.output_style != OutputStyleOption::Disabled { - println!( - "{}{}: {}", - "Benchmark ".bold(), - (num + 1).to_string().bold(), - command_name, - ); - } - - let mut times_real: Vec = vec![]; - let mut times_user: Vec = vec![]; - let mut times_system: Vec = vec![]; - let mut exit_codes: Vec> = vec![]; - let mut all_succeeded = true; - - // Run init command - let prepare_cmd = options.preparation_command.as_ref().map(|values| { - let preparation_command = if values.len() == 1 { - &values[0] - } else { - &values[num] - }; - Command::new_parametrized(None, preparation_command, cmd.get_parameters().clone()) - }); - - // Run setup command - let setup_cmd = options.setup_command.as_ref().map(|setup_command| { - Command::new_parametrized(None, setup_command, cmd.get_parameters().clone()) - }); - run_setup_command(&options.shell, &setup_cmd, options.command_output_policy)?; - - // Warmup phase - if options.warmup_count > 0 { - let progress_bar = if options.output_style != OutputStyleOption::Disabled { - Some(get_progress_bar( - options.warmup_count, - "Performing warmup runs", - options.output_style, - )) - } else { - None - }; - - for _ in 0..options.warmup_count { - let _ = run_preparation_command( - &options.shell, - &prepare_cmd, - options.command_output_policy, - )?; - let _ = time_shell_command( - &options.shell, - cmd, - options.command_output_policy, - options.command_failure_action, - None, - )?; - if let Some(bar) = progress_bar.as_ref() { - bar.inc(1) - } - } - if let Some(bar) = progress_bar.as_ref() { - bar.finish_and_clear() - } - } - - // Set up progress bar (and spinner for initial measurement) - let progress_bar = if options.output_style != OutputStyleOption::Disabled { - Some(get_progress_bar( - options.run_bounds.min, - "Initial time measurement", - options.output_style, - )) - } else { - None - }; - - let prepare_result = - run_preparation_command(&options.shell, &prepare_cmd, options.command_output_policy)?; - - // Initial timing run - let (res, status) = time_shell_command( - &options.shell, - cmd, - options.command_output_policy, - options.command_failure_action, - Some(shell_spawning_time), - )?; - let success = status.success(); - - // Determine number of benchmark runs - let runs_in_min_time = (options.min_benchmarking_time - / (res.time_real + prepare_result.time_real + shell_spawning_time.time_real)) - as u64; - - let count = { - let min = cmp::max(runs_in_min_time, options.run_bounds.min); - - options - .run_bounds - .max - .as_ref() - .map(|max| cmp::min(min, *max)) - .unwrap_or(min) - }; - - let count_remaining = count - 1; - - // Save the first result - times_real.push(res.time_real); - times_user.push(res.time_user); - times_system.push(res.time_system); - exit_codes.push(extract_exit_code(status)); - - all_succeeded = all_succeeded && success; - - // Re-configure the progress bar - if let Some(bar) = progress_bar.as_ref() { - bar.set_length(count) - } - if let Some(bar) = progress_bar.as_ref() { - bar.inc(1) - } - - // Gather statistics - for _ in 0..count_remaining { - run_preparation_command(&options.shell, &prepare_cmd, options.command_output_policy)?; - - let msg = { - let mean = format_duration(mean(×_real), options.time_unit); - format!("Current estimate: {}", mean.to_string().green()) - }; - - if let Some(bar) = progress_bar.as_ref() { - bar.set_message(msg.to_owned()) - } - - let (res, status) = time_shell_command( - &options.shell, - cmd, - options.command_output_policy, - options.command_failure_action, - Some(shell_spawning_time), - )?; - let success = status.success(); - - times_real.push(res.time_real); - times_user.push(res.time_user); - times_system.push(res.time_system); - exit_codes.push(extract_exit_code(status)); - - all_succeeded = all_succeeded && success; - - if let Some(bar) = progress_bar.as_ref() { - bar.inc(1) - } - } - - if let Some(bar) = progress_bar.as_ref() { - bar.finish_and_clear() - } - - // Compute statistical quantities - let t_num = times_real.len(); - let t_mean = mean(×_real); - let t_stddev = if times_real.len() > 1 { - Some(standard_deviation(×_real, Some(t_mean))) - } else { - None - }; - let t_median = median(×_real); - let t_min = min(×_real); - let t_max = max(×_real); - - let user_mean = mean(×_user); - let system_mean = mean(×_system); - - // Formatting and console output - let (mean_str, time_unit) = format_duration_unit(t_mean, options.time_unit); - let min_str = format_duration(t_min, Some(time_unit)); - let max_str = format_duration(t_max, Some(time_unit)); - let num_str = format!("{} runs", t_num); - - let user_str = format_duration(user_mean, Some(time_unit)); - let system_str = format_duration(system_mean, Some(time_unit)); - - if options.output_style != OutputStyleOption::Disabled { - if times_real.len() == 1 { - println!( - " Time ({} ≡): {:>8} {:>8} [User: {}, System: {}]", - "abs".green().bold(), - mean_str.green().bold(), - " ".to_string(), // alignment - user_str.blue(), - system_str.blue() - ); - } else { - let stddev_str = format_duration(t_stddev.unwrap(), Some(time_unit)); - - println!( - " Time ({} ± {}): {:>8} ± {:>8} [User: {}, System: {}]", - "mean".green().bold(), - "σ".green(), - mean_str.green().bold(), - stddev_str.green(), - user_str.blue(), - system_str.blue() - ); - - println!( - " Range ({} … {}): {:>8} … {:>8} {}", - "min".cyan(), - "max".purple(), - min_str.cyan(), - max_str.purple(), - num_str.dimmed() - ); - } - } - - // Warnings - let mut warnings = vec![]; - - // Check execution time - if times_real.iter().any(|&t| t < MIN_EXECUTION_TIME) { - warnings.push(Warnings::FastExecutionTime); - } - - // Check programm exit codes - if !all_succeeded { - warnings.push(Warnings::NonZeroExitCode); - } - - // Run outlier detection - let scores = modified_zscores(×_real); - if scores[0] > OUTLIER_THRESHOLD { - warnings.push(Warnings::SlowInitialRun(times_real[0])); - } else if scores.iter().any(|&s| s.abs() > OUTLIER_THRESHOLD) { - warnings.push(Warnings::OutliersDetected); - } - - if !warnings.is_empty() { - eprintln!(" "); - - for warning in &warnings { - eprintln!(" {}: {}", "Warning".yellow(), warning); - } - } - - if options.output_style != OutputStyleOption::Disabled { - println!(" "); - } - - // Run cleanup command - let cleanup_cmd = options.cleanup_command.as_ref().map(|cleanup_command| { - Command::new_parametrized(None, cleanup_command, cmd.get_parameters().clone()) - }); - run_cleanup_command(&options.shell, &cleanup_cmd, options.command_output_policy)?; - - Ok(BenchmarkResult { - command: command_name, - mean: t_mean, - stddev: t_stddev, - median: t_median, - user: user_mean, - system: system_mean, - min: t_min, - max: t_max, - times: Some(times_real), - exit_codes, - parameters: cmd - .get_parameters() - .iter() - .map(|(name, value)| ((*name).to_string(), value.to_string())) - .collect(), - }) -} diff --git a/src/benchmark/relative_speed.rs b/src/benchmark/relative_speed.rs index 56067d2..02de11b 100644 --- a/src/benchmark/relative_speed.rs +++ b/src/benchmark/relative_speed.rs @@ -1,6 +1,6 @@ use std::cmp::Ordering; -use super::result::BenchmarkResult; +use super::benchmark_result::BenchmarkResult; use crate::util::units::Scalar; #[derive(Debug)] diff --git a/src/benchmark/scheduler.rs b/src/benchmark/scheduler.rs index 6e92ce1..d6364dd 100644 --- a/src/benchmark/scheduler.rs +++ b/src/benchmark/scheduler.rs @@ -1,11 +1,29 @@ +use std::cmp; +use std::process::{ExitStatus, Stdio}; + +use colored::*; +use statistical::{mean, median, standard_deviation}; + +use super::benchmark_result::BenchmarkResult; +use super::timing_result::TimingResult; +use super::{relative_speed, MIN_EXECUTION_TIME}; + +use crate::command::Command; use crate::command::Commands; use crate::export::ExportManager; -use crate::options::{Options, OutputStyleOption}; +use crate::options::{CmdFailureAction, CommandOutputPolicy, Options, OutputStyleOption, Shell}; +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::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 super::{mean_shell_spawning_time, relative_speed, result::BenchmarkResult, run_benchmark}; - -use anyhow::Result; -use colored::*; +use anyhow::{bail, Result}; pub struct Scheduler<'a> { commands: &'a Commands<'a>, @@ -90,3 +108,472 @@ impl<'a> Scheduler<'a> { } } } + +/// 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, +) -> 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 { + 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 = vec![]; + let mut times_user: Vec = vec![]; + let mut times_system: Vec = 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), + }) +} + +fn run_intermediate_command( + shell: &Shell, + command: &Option>, + command_output_policy: CommandOutputPolicy, + error_output: &'static str, +) -> Result { + if let Some(ref cmd) = command { + let res = time_shell_command( + shell, + cmd, + command_output_policy, + CmdFailureAction::RaiseError, + None, + ); + if res.is_err() { + bail!(error_output); + } + return res.map(|r| r.0); + } + Ok(TimingResult { + ..Default::default() + }) +} + +/// Run the command specified by `--setup`. +fn run_setup_command( + shell: &Shell, + command: &Option>, + output_policy: CommandOutputPolicy, +) -> Result { + let error_output = "The setup command terminated with a non-zero exit code. \ + Append ' || true' to the command if you are sure that this can be ignored."; + + run_intermediate_command(shell, command, output_policy, error_output) +} + +/// Run the command specified by `--prepare`. +fn run_preparation_command( + shell: &Shell, + command: &Option>, + output_policy: CommandOutputPolicy, +) -> Result { + let error_output = "The preparation command terminated with a non-zero exit code. \ + Append ' || true' to the command if you are sure that this can be ignored."; + + run_intermediate_command(shell, command, output_policy, error_output) +} + +/// Run the command specified by `--cleanup`. +fn run_cleanup_command( + shell: &Shell, + command: &Option>, + output_policy: CommandOutputPolicy, +) -> Result { + let error_output = "The cleanup command terminated with a non-zero exit code. \ + Append ' || true' to the command if you are sure that this can be ignored."; + + run_intermediate_command(shell, command, output_policy, error_output) +} + +/// Run the benchmark for a single shell command +pub fn run_benchmark( + num: usize, + cmd: &Command<'_>, + shell_spawning_time: TimingResult, + options: &Options, +) -> Result { + let command_name = cmd.get_name(); + if options.output_style != OutputStyleOption::Disabled { + println!( + "{}{}: {}", + "Benchmark ".bold(), + (num + 1).to_string().bold(), + command_name, + ); + } + + let mut times_real: Vec = vec![]; + let mut times_user: Vec = vec![]; + let mut times_system: Vec = vec![]; + let mut exit_codes: Vec> = vec![]; + let mut all_succeeded = true; + + // Run init command + let prepare_cmd = options.preparation_command.as_ref().map(|values| { + let preparation_command = if values.len() == 1 { + &values[0] + } else { + &values[num] + }; + Command::new_parametrized(None, preparation_command, cmd.get_parameters().clone()) + }); + + // Run setup command + let setup_cmd = options.setup_command.as_ref().map(|setup_command| { + Command::new_parametrized(None, setup_command, cmd.get_parameters().clone()) + }); + run_setup_command(&options.shell, &setup_cmd, options.command_output_policy)?; + + // Warmup phase + if options.warmup_count > 0 { + let progress_bar = if options.output_style != OutputStyleOption::Disabled { + Some(get_progress_bar( + options.warmup_count, + "Performing warmup runs", + options.output_style, + )) + } else { + None + }; + + for _ in 0..options.warmup_count { + let _ = run_preparation_command( + &options.shell, + &prepare_cmd, + options.command_output_policy, + )?; + let _ = time_shell_command( + &options.shell, + cmd, + options.command_output_policy, + options.command_failure_action, + None, + )?; + if let Some(bar) = progress_bar.as_ref() { + bar.inc(1) + } + } + if let Some(bar) = progress_bar.as_ref() { + bar.finish_and_clear() + } + } + + // Set up progress bar (and spinner for initial measurement) + let progress_bar = if options.output_style != OutputStyleOption::Disabled { + Some(get_progress_bar( + options.run_bounds.min, + "Initial time measurement", + options.output_style, + )) + } else { + None + }; + + let prepare_result = + run_preparation_command(&options.shell, &prepare_cmd, options.command_output_policy)?; + + // Initial timing run + let (res, status) = time_shell_command( + &options.shell, + cmd, + options.command_output_policy, + options.command_failure_action, + Some(shell_spawning_time), + )?; + let success = status.success(); + + // Determine number of benchmark runs + let runs_in_min_time = (options.min_benchmarking_time + / (res.time_real + prepare_result.time_real + shell_spawning_time.time_real)) + as u64; + + let count = { + let min = cmp::max(runs_in_min_time, options.run_bounds.min); + + options + .run_bounds + .max + .as_ref() + .map(|max| cmp::min(min, *max)) + .unwrap_or(min) + }; + + let count_remaining = count - 1; + + // Save the first result + times_real.push(res.time_real); + times_user.push(res.time_user); + times_system.push(res.time_system); + exit_codes.push(extract_exit_code(status)); + + all_succeeded = all_succeeded && success; + + // Re-configure the progress bar + if let Some(bar) = progress_bar.as_ref() { + bar.set_length(count) + } + if let Some(bar) = progress_bar.as_ref() { + bar.inc(1) + } + + // Gather statistics + for _ in 0..count_remaining { + run_preparation_command(&options.shell, &prepare_cmd, options.command_output_policy)?; + + let msg = { + let mean = format_duration(mean(×_real), options.time_unit); + format!("Current estimate: {}", mean.to_string().green()) + }; + + if let Some(bar) = progress_bar.as_ref() { + bar.set_message(msg.to_owned()) + } + + let (res, status) = time_shell_command( + &options.shell, + cmd, + options.command_output_policy, + options.command_failure_action, + Some(shell_spawning_time), + )?; + let success = status.success(); + + times_real.push(res.time_real); + times_user.push(res.time_user); + times_system.push(res.time_system); + exit_codes.push(extract_exit_code(status)); + + all_succeeded = all_succeeded && success; + + if let Some(bar) = progress_bar.as_ref() { + bar.inc(1) + } + } + + if let Some(bar) = progress_bar.as_ref() { + bar.finish_and_clear() + } + + // Compute statistical quantities + let t_num = times_real.len(); + let t_mean = mean(×_real); + let t_stddev = if times_real.len() > 1 { + Some(standard_deviation(×_real, Some(t_mean))) + } else { + None + }; + let t_median = median(×_real); + let t_min = min(×_real); + let t_max = max(×_real); + + let user_mean = mean(×_user); + let system_mean = mean(×_system); + + // Formatting and console output + let (mean_str, time_unit) = format_duration_unit(t_mean, options.time_unit); + let min_str = format_duration(t_min, Some(time_unit)); + let max_str = format_duration(t_max, Some(time_unit)); + let num_str = format!("{} runs", t_num); + + let user_str = format_duration(user_mean, Some(time_unit)); + let system_str = format_duration(system_mean, Some(time_unit)); + + if options.output_style != OutputStyleOption::Disabled { + if times_real.len() == 1 { + println!( + " Time ({} ≡): {:>8} {:>8} [User: {}, System: {}]", + "abs".green().bold(), + mean_str.green().bold(), + " ".to_string(), // alignment + user_str.blue(), + system_str.blue() + ); + } else { + let stddev_str = format_duration(t_stddev.unwrap(), Some(time_unit)); + + println!( + " Time ({} ± {}): {:>8} ± {:>8} [User: {}, System: {}]", + "mean".green().bold(), + "σ".green(), + mean_str.green().bold(), + stddev_str.green(), + user_str.blue(), + system_str.blue() + ); + + println!( + " Range ({} … {}): {:>8} … {:>8} {}", + "min".cyan(), + "max".purple(), + min_str.cyan(), + max_str.purple(), + num_str.dimmed() + ); + } + } + + // Warnings + let mut warnings = vec![]; + + // Check execution time + if times_real.iter().any(|&t| t < MIN_EXECUTION_TIME) { + warnings.push(Warnings::FastExecutionTime); + } + + // Check programm exit codes + if !all_succeeded { + warnings.push(Warnings::NonZeroExitCode); + } + + // Run outlier detection + let scores = modified_zscores(×_real); + if scores[0] > OUTLIER_THRESHOLD { + warnings.push(Warnings::SlowInitialRun(times_real[0])); + } else if scores.iter().any(|&s| s.abs() > OUTLIER_THRESHOLD) { + warnings.push(Warnings::OutliersDetected); + } + + if !warnings.is_empty() { + eprintln!(" "); + + for warning in &warnings { + eprintln!(" {}: {}", "Warning".yellow(), warning); + } + } + + if options.output_style != OutputStyleOption::Disabled { + println!(" "); + } + + // Run cleanup command + let cleanup_cmd = options.cleanup_command.as_ref().map(|cleanup_command| { + Command::new_parametrized(None, cleanup_command, cmd.get_parameters().clone()) + }); + run_cleanup_command(&options.shell, &cleanup_cmd, options.command_output_policy)?; + + Ok(BenchmarkResult { + command: command_name, + mean: t_mean, + stddev: t_stddev, + median: t_median, + user: user_mean, + system: system_mean, + min: t_min, + max: t_max, + times: Some(times_real), + exit_codes, + parameters: cmd + .get_parameters() + .iter() + .map(|(name, value)| ((*name).to_string(), value.to_string())) + .collect(), + }) +} diff --git a/src/benchmark/timing_result.rs b/src/benchmark/timing_result.rs new file mode 100644 index 0000000..d4b8490 --- /dev/null +++ b/src/benchmark/timing_result.rs @@ -0,0 +1,14 @@ +use crate::util::units::Second; + +/// Results from timing a single command +#[derive(Debug, Default, Copy, Clone)] +pub struct TimingResult { + /// Wall clock time + pub time_real: Second, + + /// Time spent in user mode + pub time_user: Second, + + /// Time spent in kernel mode + pub time_system: Second, +} diff --git a/src/export/asciidoc.rs b/src/export/asciidoc.rs index 5d315ee..077f795 100644 --- a/src/export/asciidoc.rs +++ b/src/export/asciidoc.rs @@ -1,5 +1,5 @@ +use crate::benchmark::benchmark_result::BenchmarkResult; use crate::benchmark::relative_speed::{self, BenchmarkResultWithRelativeSpeed}; -use crate::benchmark::result::BenchmarkResult; use crate::output::format::format_duration_value; use crate::util::units::Unit; diff --git a/src/export/csv.rs b/src/export/csv.rs index 6f3532d..f550f5f 100644 --- a/src/export/csv.rs +++ b/src/export/csv.rs @@ -3,7 +3,7 @@ use std::borrow::Cow; use csv::WriterBuilder; use super::Exporter; -use crate::benchmark::result::BenchmarkResult; +use crate::benchmark::benchmark_result::BenchmarkResult; use crate::util::units::Unit; use anyhow::Result; diff --git a/src/export/json.rs b/src/export/json.rs index b5eef4d..903264e 100644 --- a/src/export/json.rs +++ b/src/export/json.rs @@ -2,7 +2,7 @@ use serde::*; use serde_json::to_vec_pretty; use super::Exporter; -use crate::benchmark::result::BenchmarkResult; +use crate::benchmark::benchmark_result::BenchmarkResult; use crate::util::units::Unit; use anyhow::Result; diff --git a/src/export/markdown.rs b/src/export/markdown.rs index 4be44fc..d89aca3 100644 --- a/src/export/markdown.rs +++ b/src/export/markdown.rs @@ -1,6 +1,6 @@ use super::Exporter; +use crate::benchmark::benchmark_result::BenchmarkResult; use crate::benchmark::relative_speed::{self, BenchmarkResultWithRelativeSpeed}; -use crate::benchmark::result::BenchmarkResult; use crate::output::format::format_duration_value; use crate::util::units::Unit; diff --git a/src/export/mod.rs b/src/export/mod.rs index c5bca01..aa5f0a2 100644 --- a/src/export/mod.rs +++ b/src/export/mod.rs @@ -11,7 +11,7 @@ use self::csv::CsvExporter; use self::json::JsonExporter; use self::markdown::MarkdownExporter; -use crate::benchmark::result::BenchmarkResult; +use crate::benchmark::benchmark_result::BenchmarkResult; use crate::util::units::Unit; use anyhow::{Context, Result};