diff --git a/src/benchmark/executor.rs b/src/benchmark/executor.rs index 915b735b6..dd52fe623 100644 --- a/src/benchmark/executor.rs +++ b/src/benchmark/executor.rs @@ -146,15 +146,7 @@ impl Executor for RawExecutor<'_> { &command.get_command_line(), )?; - Ok(( - TimingResult { - time_real: result.time_real, - time_user: result.time_user, - time_system: result.time_system, - memory_usage_byte: result.memory_usage_byte, - }, - result.status, - )) + Ok((result.timing, result.status)) } fn calibrate(&mut self) -> Result<()> { @@ -213,20 +205,13 @@ impl Executor for ShellExecutor<'_> { // Subtract shell spawning time if let Some(spawning_time) = self.shell_spawning_time { - result.time_real = (result.time_real - spawning_time.time_real).max(0.0); - result.time_user = (result.time_user - spawning_time.time_user).max(0.0); - result.time_system = (result.time_system - spawning_time.time_system).max(0.0); + result.timing.time_real = (result.timing.time_real - spawning_time.time_real).max(0.0); + result.timing.time_user = (result.timing.time_user - spawning_time.time_user).max(0.0); + result.timing.time_system = + (result.timing.time_system - spawning_time.time_system).max(0.0); } - Ok(( - TimingResult { - time_real: result.time_real, - time_user: result.time_user, - time_system: result.time_system, - memory_usage_byte: result.memory_usage_byte, - }, - result.status, - )) + Ok((result.timing, result.status)) } /// Measure the average shell spawning time @@ -289,6 +274,12 @@ impl Executor for ShellExecutor<'_> { time_user: mean(×_user), time_system: mean(×_system), memory_usage_byte: 0, + voluntary_context_switches: 0, + context_switches: 0, + filesystem_input: 0, + filesystem_output: 0, + minor_page_faults: 0, + major_page_faults: 0, }); Ok(()) @@ -345,6 +336,12 @@ impl Executor for MockExecutor { time_user: 0.0, time_system: 0.0, memory_usage_byte: 0, + voluntary_context_switches: 0, + context_switches: 0, + filesystem_input: 0, + filesystem_output: 0, + minor_page_faults: 0, + major_page_faults: 0, }, status, )) diff --git a/src/benchmark/mod.rs b/src/benchmark/mod.rs index e3534a7bc..b62acd94b 100644 --- a/src/benchmark/mod.rs +++ b/src/benchmark/mod.rs @@ -12,12 +12,12 @@ use crate::options::{ CmdFailureAction, CommandOutputPolicy, ExecutorKind, Options, OutputStyleOption, }; use crate::outlier_detection::{modified_zscores, OUTLIER_THRESHOLD}; -use crate::output::format::{format_duration, format_duration_unit}; +use crate::output::format::{format_duration, format_duration_unit, BytesFormat}; use crate::output::progress_bar::get_progress_bar; use crate::output::warnings::{OutlierWarningOptions, Warnings}; use crate::parameter::ParameterNameAndValue; use crate::util::exit_code::extract_exit_code; -use crate::util::min_max::{max, min}; +use crate::util::min_max::{max, min, statistics}; use crate::util::units::Second; use benchmark_result::BenchmarkResult; use timing_result::TimingResult; @@ -154,6 +154,12 @@ impl<'a> Benchmark<'a> { let mut memory_usage_byte: Vec = vec![]; let mut exit_codes: Vec> = vec![]; let mut all_succeeded = true; + let mut voluntary_context_switches = Vec::new(); + let mut context_switches = Vec::new(); + let mut filesystem_input = Vec::new(); + let mut filesystem_output = Vec::new(); + let mut minor_page_faults = Vec::new(); + let mut major_page_faults = Vec::new(); let output_policy = &self.options.command_output_policies[self.number]; @@ -282,6 +288,14 @@ impl<'a> Benchmark<'a> { times_system.push(res.time_system); memory_usage_byte.push(res.memory_usage_byte); exit_codes.push(extract_exit_code(status)); + if self.options.resource_usage { + voluntary_context_switches.push(res.voluntary_context_switches); + context_switches.push(res.context_switches); + filesystem_input.push(res.filesystem_input); + filesystem_output.push(res.filesystem_output); + minor_page_faults.push(res.minor_page_faults); + major_page_faults.push(res.major_page_faults); + } all_succeeded = all_succeeded && success; @@ -319,6 +333,14 @@ impl<'a> Benchmark<'a> { times_system.push(res.time_system); memory_usage_byte.push(res.memory_usage_byte); exit_codes.push(extract_exit_code(status)); + if self.options.resource_usage { + voluntary_context_switches.push(res.voluntary_context_switches); + context_switches.push(res.context_switches); + filesystem_input.push(res.filesystem_input); + filesystem_output.push(res.filesystem_output); + minor_page_faults.push(res.minor_page_faults); + major_page_faults.push(res.major_page_faults); + } all_succeeded = all_succeeded && success; @@ -389,6 +411,56 @@ impl<'a> Benchmark<'a> { num_str.dimmed() ); } + + if self.options.resource_usage { + println!(); + + macro_rules! print_bytes_stats { + ($stats: expr, $title: literal) => {{ + let stats = statistics(&$stats); + println!( + " {:<7} ({} … {}|{} … {}): {:>8} … {:>8}{}{:<8} … {:>8}", + $title, + "min".cyan(), + "mean".green().bold(), + "med".blue().bold(), + "max".purple(), + format!("{}", BytesFormat(stats.min)).cyan(), + format!("{}", BytesFormat(stats.mean)).green().bold(), + "|".dimmed(), + format!("{}", BytesFormat(stats.median)).blue().bold(), + format!("{}", BytesFormat(stats.max)).purple() + ); + }}; + } + + macro_rules! print_stats { + ($stats: expr, $title: literal) => {{ + let stats = statistics(&$stats); + println!( + " {:<7} ({} … {}|{} … {}): {:>8} … {:>8}{}{:<8} … {:>8}", + $title, + "min".cyan(), + "mean".green().bold(), + "med".blue().bold(), + "max".purple(), + format!("{}", stats.min).cyan(), + format!("{}", stats.mean).green().bold(), + "|".dimmed(), + format!("{}", stats.median).blue().bold(), + format!("{}", stats.max).purple() + ); + }}; + } + + print_bytes_stats!(memory_usage_byte, "maxrss"); + print_stats!(voluntary_context_switches, "nvcsw"); + print_stats!(context_switches, "nivcsw"); + print_stats!(filesystem_input, "inblock"); + print_stats!(filesystem_output, "oublock"); + print_stats!(minor_page_faults, "minflt"); + print_stats!(major_page_faults, "majflt"); + } } // Warnings @@ -430,7 +502,7 @@ impl<'a> Benchmark<'a> { } if !warnings.is_empty() { - eprintln!(" "); + eprintln!(); for warning in &warnings { eprintln!(" {}: {}", "Warning".yellow(), warning); @@ -438,7 +510,7 @@ impl<'a> Benchmark<'a> { } if self.options.output_style != OutputStyleOption::Disabled { - println!(" "); + println!(); } self.run_cleanup_command(self.command.get_parameters().iter().cloned(), output_policy)?; diff --git a/src/benchmark/timing_result.rs b/src/benchmark/timing_result.rs index f7aac92bb..063016d4d 100644 --- a/src/benchmark/timing_result.rs +++ b/src/benchmark/timing_result.rs @@ -14,4 +14,22 @@ pub struct TimingResult { /// Maximum amount of memory used, in bytes pub memory_usage_byte: u64, + + /// Number of voluntary context switches + pub voluntary_context_switches: u64, + + /// Number of involuntary context switches + pub context_switches: u64, + + /// Number of times the filesystem had to perform input. + pub filesystem_input: u64, + + /// Number of times the filesystem had to perform output. + pub filesystem_output: u64, + + /// Number of minor page faults + pub minor_page_faults: u64, + + /// Number of major page faults + pub major_page_faults: u64, } diff --git a/src/cli.rs b/src/cli.rs index b12f6d34c..98843458e 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -251,6 +251,12 @@ fn build_command() -> Command { the output of the tool.", ), ) + .arg( + Arg::new("resource-usage") + .long("resource-usage") + .action(ArgAction::SetTrue) + .help("Show resource usage of the command.") + ) .arg( Arg::new("sort") .long("sort") diff --git a/src/options.rs b/src/options.rs index 7c83da1c5..f84bac473 100644 --- a/src/options.rs +++ b/src/options.rs @@ -229,6 +229,9 @@ pub struct Options { /// What color mode to use for the terminal output pub output_style: OutputStyleOption, + /// Display resource usage of commands + pub resource_usage: bool, + /// How to order benchmarks in the relative speed comparison pub sort_order_speed_comparison: SortOrder, @@ -262,6 +265,7 @@ impl Default for Options { setup_command: None, cleanup_command: None, output_style: OutputStyleOption::Full, + resource_usage: false, sort_order_speed_comparison: SortOrder::MeanTime, sort_order_exports: SortOrder::Command, executor_kind: ExecutorKind::default(), @@ -382,6 +386,8 @@ impl Options { } }; + options.resource_usage = *matches.get_one::("resource-usage").unwrap_or(&false); + match options.output_style { OutputStyleOption::Basic | OutputStyleOption::NoColor => { colored::control::set_override(false) diff --git a/src/output/format.rs b/src/output/format.rs index f1aa0d059..eb405f8f2 100644 --- a/src/output/format.rs +++ b/src/output/format.rs @@ -1,3 +1,5 @@ +use std::fmt::Display; + use crate::util::units::{Second, Unit}; /// Format the given duration as a string. The output-unit can be enforced by setting `unit` to @@ -25,6 +27,51 @@ pub fn format_duration_value(duration: Second, unit: Option) -> (String, U } } +/// Wrapper to format memory sizes as a string. +pub struct BytesFormat(pub u64); + +impl Display for BytesFormat { + #[expect(clippy::cast_precision_loss)] + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let bytes = self.0; + if bytes < 100_000 { + return write!(f, "{bytes} b"); + } + let bytes = bytes as f64 / 1000.0; + if bytes < 10.0 { + return write!(f, "{bytes:.3} kb"); + } + if bytes < 100.0 { + return write!(f, "{bytes:.2} kb"); + } + if bytes < 1000.0 { + return write!(f, "{bytes:.1} kb"); + } + let bytes = bytes / 1000.0; + if bytes < 10.0 { + return write!(f, "{bytes:.3} MB"); + } + if bytes < 100.0 { + return write!(f, "{bytes:.2} MB"); + } + if bytes < 1000.0 { + return write!(f, "{bytes:.1} MB"); + } + let bytes = bytes / 1000.0; + if bytes < 10.0 { + return write!(f, "{bytes:.3} GB"); + } + if bytes < 100.0 { + return write!(f, "{bytes:.2} GB"); + } + if bytes < 1000.0 { + return write!(f, "{bytes:.1} GB"); + } + let bytes = bytes / 1000.0; + write!(f, "{bytes:.0} TB") + } +} + #[test] fn test_format_duration_unit_basic() { let (out_str, out_unit) = format_duration_unit(1.3, None); @@ -75,3 +122,14 @@ fn test_format_duration_unit_with_unit() { assert_eq!("1300000.0 µs", out_str); assert_eq!(Unit::MicroSecond, out_unit); } + +#[test] +fn test_format_bytes() { + assert_eq!("0 b", format!("{}", BytesFormat(0))); + assert_eq!("42 b", format!("{}", BytesFormat(42))); + assert_eq!("10240 b", format!("{}", BytesFormat(10240))); + assert_eq!("102.4 kb", format!("{}", BytesFormat(102400))); + assert_eq!("102.4 MB", format!("{}", BytesFormat(102400000))); + assert_eq!("1.024 GB", format!("{}", BytesFormat(1024000000))); + assert_eq!("18446744 TB", format!("{}", BytesFormat(u64::MAX))); +} diff --git a/src/timer/mod.rs b/src/timer/mod.rs index b2cd2654c..066b68bbc 100644 --- a/src/timer/mod.rs +++ b/src/timer/mod.rs @@ -8,6 +8,10 @@ mod unix_timer; #[cfg(target_os = "linux")] use nix::fcntl::{splice, SpliceFFlags}; +#[cfg(not(windows))] +use std::convert::TryFrom; +#[cfg(not(windows))] +use std::convert::TryInto; #[cfg(target_os = "linux")] use std::fs::File; #[cfg(target_os = "linux")] @@ -16,7 +20,7 @@ use std::os::fd::AsFd; #[cfg(target_os = "windows")] use windows_sys::Win32::System::Threading::CREATE_SUSPENDED; -use crate::util::units::Second; +use crate::benchmark::timing_result::TimingResult; use wall_clock_timer::WallClockTimer; use std::io::Read; @@ -33,17 +37,29 @@ struct CPUTimes { /// Total amount of time spent executing in kernel mode pub system_usec: i64, - /// Maximum amount of memory used by the process, in bytes - pub memory_usage_byte: u64, + /// Number of voluntary context switches + pub voluntary_context_switches: u64, + + /// Number of involuntary context switches + pub context_switches: u64, + + /// Number of times the filesystem had to perform input. + pub filesystem_input: u64, + + /// Number of times the filesystem had to perform output. + pub filesystem_output: u64, + + /// Number of minor page faults + pub minor_page_faults: u64, + + /// Number of major page faults + pub major_page_faults: u64, } /// Used to indicate the result of running a command #[derive(Debug, Copy, Clone)] pub struct TimerResult { - pub time_real: Second, - pub time_user: Second, - pub time_system: Second, - pub memory_usage_byte: u64, + pub timing: TimingResult, /// The exit status of the process pub status: ExitStatus, } @@ -106,16 +122,75 @@ pub fn execute_and_measure(mut command: Command) -> Result { discard(output); } - let status = child.wait()?; + #[cfg(not(windows))] + let (status, memory_usage_byte) = { + use std::io::Error; + use std::os::unix::process::ExitStatusExt; + + let mut raw_status = 0; + let pid = child.id().try_into().expect("should convert to pid_t"); + // SAFETY: libc::rusage is Plain Old Data + let mut rusage = unsafe { std::mem::zeroed() }; + // SAFETY: all syscall arguments are valid + let result = unsafe { libc::wait4(pid, &raw mut raw_status, 0, &raw mut rusage) }; + if result != pid { + return Err(Error::last_os_error().into()); + } + + // Linux and *BSD return the value in KibiBytes, Darwin flavors in bytes + let max_rss_byte = if cfg!(target_os = "macos") || cfg!(target_os = "ios") { + rusage.ru_maxrss + } else { + rusage.ru_maxrss * 1024 + }; + let memory_usage_byte = u64::try_from(max_rss_byte).expect("should not be negative"); + + let status = ExitStatus::from_raw(raw_status); + + (status, memory_usage_byte) + }; + + #[cfg(windows)] + let (status, memory_usage_byte) = (child.wait()?, 0); let time_real = wallclock_timer.stop(); - let (time_user, time_system, memory_usage_byte) = cpu_timer.stop(); - Ok(TimerResult { + #[cfg(not(windows))] + let ( + time_user, + time_system, + voluntary_context_switches, + context_switches, + filesystem_input, + filesystem_output, + minor_page_faults, + major_page_faults, + ) = cpu_timer.stop(); + + #[cfg(windows)] + let (time_user, time_system, memory_usage_byte) = cpu_timer.stop(); + #[cfg(windows)] + let ( + voluntary_context_switches, + context_switches, + filesystem_input, + filesystem_output, + minor_page_faults, + major_page_faults, + ) = (0, 0, 0, 0, 0, 0); + + let timing = TimingResult { time_real, time_user, time_system, memory_usage_byte, - status, - }) + voluntary_context_switches, + context_switches, + filesystem_input, + filesystem_output, + minor_page_faults, + major_page_faults, + }; + + Ok(TimerResult { timing, status }) } diff --git a/src/timer/unix_timer.rs b/src/timer/unix_timer.rs index 34e5325cb..18ca55307 100644 --- a/src/timer/unix_timer.rs +++ b/src/timer/unix_timer.rs @@ -26,13 +26,19 @@ impl CPUTimer { } } - pub fn stop(&self) -> (Second, Second, u64) { + pub fn stop(&self) -> (Second, Second, u64, u64, u64, u64, u64, u64) { let end_cpu = get_cpu_times(); let cpu_interval = cpu_time_interval(&self.start_cpu, &end_cpu); + ( cpu_interval.user, cpu_interval.system, - end_cpu.memory_usage_byte, + end_cpu.voluntary_context_switches - self.start_cpu.voluntary_context_switches, + end_cpu.context_switches - self.start_cpu.context_switches, + end_cpu.filesystem_input - self.start_cpu.filesystem_input, + end_cpu.filesystem_output - self.start_cpu.filesystem_output, + end_cpu.minor_page_faults - self.start_cpu.minor_page_faults, + end_cpu.major_page_faults - self.start_cpu.major_page_faults, ) } } @@ -50,12 +56,13 @@ fn get_cpu_times() -> CPUTimes { const MICROSEC_PER_SEC: i64 = 1000 * 1000; - // Linux and *BSD return the value in KibiBytes, Darwin flavors in bytes - let max_rss_byte = if cfg!(target_os = "macos") || cfg!(target_os = "ios") { - result.ru_maxrss - } else { - result.ru_maxrss * 1024 - }; + let voluntary_context_switches = + u64::try_from(result.ru_nvcsw).expect("should never be negative"); + let context_switches = u64::try_from(result.ru_nivcsw).expect("should never be negative"); + let filesystem_input = u64::try_from(result.ru_inblock).expect("should never be negative"); + let filesystem_output = u64::try_from(result.ru_oublock).expect("should never be negative"); + let minor_page_faults = u64::try_from(result.ru_minflt).expect("should never be negative"); + let major_page_faults = u64::try_from(result.ru_majflt).expect("should never be negative"); #[allow(clippy::useless_conversion)] CPUTimes { @@ -63,7 +70,12 @@ fn get_cpu_times() -> CPUTimes { + i64::from(result.ru_utime.tv_usec), system_usec: i64::from(result.ru_stime.tv_sec) * MICROSEC_PER_SEC + i64::from(result.ru_stime.tv_usec), - memory_usage_byte: u64::try_from(max_rss_byte).unwrap_or(0), + voluntary_context_switches, + context_switches, + filesystem_input, + filesystem_output, + minor_page_faults, + major_page_faults, } } @@ -83,13 +95,23 @@ fn test_cpu_time_interval() { let t_a = CPUTimes { user_usec: 12345, system_usec: 54321, - memory_usage_byte: 0, + voluntary_context_switches: 0, + context_switches: 0, + filesystem_input: 0, + filesystem_output: 0, + minor_page_faults: 0, + major_page_faults: 0, }; let t_b = CPUTimes { user_usec: 20000, system_usec: 70000, - memory_usage_byte: 0, + voluntary_context_switches: 0, + context_switches: 0, + filesystem_input: 0, + filesystem_output: 0, + minor_page_faults: 0, + major_page_faults: 0, }; let t_zero = cpu_time_interval(&t_a, &t_a); diff --git a/src/util/min_max.rs b/src/util/min_max.rs index d4ee07ec6..028ded8db 100644 --- a/src/util/min_max.rs +++ b/src/util/min_max.rs @@ -14,6 +14,40 @@ pub fn min(vals: &[f64]) -> f64 { .unwrap() } +pub struct Statistics { + pub min: u64, + pub max: u64, + pub mean: u64, + pub median: u64, +} + +/// A function to comupute statistics for u64's +#[must_use] +pub fn statistics(vals: &[u64]) -> Statistics { + assert!(!vals.is_empty()); + + let mut copy = vals.to_vec(); + assert!(!copy.is_empty()); + copy.sort_unstable(); + + let len = copy.len(); + // For an even set use the upper middle value, since it is higher than the + // lower middle value, and higher most of the time means worse, to get an + // actual data sample as result and not an computed average. + let median_idx = if len.is_multiple_of(2) { + len / 2 + 1 + } else { + len / 2 + }; + + Statistics { + min: *copy.first().expect("non-empty"), + max: *copy.last().expect("non-empty"), + mean: copy.iter().sum::() / len as u64, + median: copy[median_idx], + } +} + #[test] fn test_max() { let assert_float_eq = |a: f64, b: f64| {