diff --git a/Cargo.lock b/Cargo.lock index 2d04f59..7ea6756 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -82,11 +82,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index" [[package]] name = "hyperfine" -version = "0.2.0" +version = "0.3.0" dependencies = [ "ansi_term 0.10.2 (registry+https://github.com/rust-lang/crates.io-index)", "clap 2.29.2 (registry+https://github.com/rust-lang/crates.io-index)", "indicatif 0.9.0 (registry+https://github.com/rust-lang/crates.io-index)", + "libc 0.2.36 (registry+https://github.com/rust-lang/crates.io-index)", "statistical 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)", ] diff --git a/Cargo.toml b/Cargo.toml index 045f92a..c65dcd1 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -7,12 +7,13 @@ license = "MIT/Apache-2.0" name = "hyperfine" readme = "README.md" repository = "https://github.com/sharkdp/hyperfine" -version = "0.2.0" +version = "0.3.0" [dependencies] ansi_term = "0.10" indicatif = "0.9" statistical = "0.1" +libc = "0.2" [dependencies.clap] version = "2" diff --git a/src/hyperfine/benchmark.rs b/src/hyperfine/benchmark.rs index 652be22..6189744 100644 --- a/src/hyperfine/benchmark.rs +++ b/src/hyperfine/benchmark.rs @@ -2,28 +2,33 @@ use std::io; use std::process::{Command, Stdio}; use std::time::Instant; -use ansi_term::Colour::{Cyan, Green, Purple, White, Yellow}; +use ansi_term::Colour::{Blue, Cyan, Green, Purple, White, Yellow}; use statistical::{mean, standard_deviation}; use hyperfine::internal::{get_progress_bar, max, min, CmdFailureAction, HyperfineOptions, Second, Warnings, MIN_EXECUTION_TIME}; use hyperfine::format::{format_duration, format_duration_unit}; +use hyperfine::cputime::{get_cpu_interval, get_cpu_times}; /// Results from timing a single shell command +#[derive(Debug, Copy, Clone)] pub struct TimingResult { - /// Execution time in seconds - pub execution_time: Second, + /// Wall clock time + pub time_real: Second, - /// True if the command finished with exit code zero - pub success: bool, + /// Time spent in user mode + pub time_user: Second, + + /// Time spent in kernel mode + pub time_system: Second, } -impl TimingResult { - fn new(execution_time: Second, success: bool) -> TimingResult { - TimingResult { - execution_time, - success, - } +/// 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 } } @@ -31,9 +36,10 @@ impl TimingResult { pub fn time_shell_command( shell_cmd: &str, failure_action: CmdFailureAction, - shell_spawning_time: Option, -) -> io::Result { + shell_spawning_time: Option, +) -> io::Result<(TimingResult, bool)> { let start = Instant::now(); + let start_cpu = get_cpu_times(); let status = Command::new("sh") .arg("-c") @@ -43,6 +49,9 @@ pub fn time_shell_command( .stderr(Stdio::null()) .status()?; + let end_cpu = get_cpu_times(); + let duration = start.elapsed(); + if failure_action == CmdFailureAction::RaiseError && !status.success() { return Err(io::Error::new( io::ErrorKind::Other, @@ -51,33 +60,40 @@ pub fn time_shell_command( )); } - let duration = start.elapsed(); + // Real time + let mut time_real = duration.as_secs() as f64 + (duration.subsec_nanos() as f64) * 1e-9; - let execution_time = duration.as_secs() as f64 + (duration.subsec_nanos() as f64) * 1e-9; + // User and system time + let cpu_interval = get_cpu_interval(&start_cpu, &end_cpu); + let mut time_user = cpu_interval.user; + let mut time_system = cpu_interval.system; // Correct for shell spawning time - let execution_time_corrected = if let Some(spawning_time) = shell_spawning_time { - if execution_time < spawning_time { - 0.0 - } else { - execution_time - spawning_time - } - } else { - execution_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(cpu_interval.user, spawning_time.time_user); + time_system = subtract_shell_spawning_time(cpu_interval.system, spawning_time.time_system); + } - Ok(TimingResult::new( - execution_time_corrected, + Ok(( + TimingResult { + time_real, + time_user, + time_system, + }, status.success(), )) } /// Measure the average shell spawning time -pub fn mean_shell_spawning_time() -> io::Result { +pub fn mean_shell_spawning_time() -> io::Result { const COUNT: u64 = 200; let progress_bar = get_progress_bar(COUNT, "Measuring shell spawning time"); - let mut times: Vec = vec![]; + 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("", CmdFailureAction::RaiseError, None); @@ -90,22 +106,28 @@ pub fn mean_shell_spawning_time() -> io::Result { Make sure you can run 'sh -c \"\"'.", )) } - Ok(r) => { - times.push(r.execution_time); + Ok((r, _)) => { + times_real.push(r.time_real); + times_user.push(r.time_user); + times_system.push(r.time_system); } } progress_bar.inc(1); } progress_bar.finish_and_clear(); - Ok(mean(×)) + Ok(TimingResult { + time_real: mean(×_real), + time_user: mean(×_user), + time_system: mean(×_system), + }) } /// Run the benchmark for a single shell command pub fn run_benchmark( num: usize, cmd: &str, - shell_spawning_time: Second, + shell_spawning_time: TimingResult, options: &HyperfineOptions, ) -> io::Result<()> { println!( @@ -116,7 +138,9 @@ pub fn run_benchmark( ); println!(); - let mut execution_times: Vec = vec![]; + let mut times_real: Vec = vec![]; + let mut times_user: Vec = vec![]; + let mut times_system: Vec = vec![]; let mut all_succeeded = true; // Warmup phase @@ -142,11 +166,12 @@ pub fn run_benchmark( run_preparation_command(); // Initial timing run - let res = time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?; + let (res, success) = + time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?; // Determine number of benchmark runs let runs_in_min_time = - (options.min_time_sec / (res.execution_time + shell_spawning_time)) as u64; + (options.min_time_sec / (res.time_real + shell_spawning_time.time_real)) as u64; let count = if runs_in_min_time >= options.min_runs { runs_in_min_time @@ -157,8 +182,11 @@ pub fn run_benchmark( let count_remaining = count - 1; // Save the first result - execution_times.push(res.execution_time); - all_succeeded = all_succeeded && res.success; + times_real.push(res.time_real); + times_user.push(res.time_user); + times_system.push(res.time_system); + + all_succeeded = all_succeeded && success; // Re-configure the progress bar progress_bar.set_length(count_remaining); @@ -168,25 +196,32 @@ pub fn run_benchmark( run_preparation_command(); let msg = { - let mean = format_duration(mean(&execution_times), None); + let mean = format_duration(mean(×_real), None); format!("Current estimate: {}", Green.paint(mean)) }; progress_bar.set_message(&msg); - let res = time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?; + let (res, success) = + time_shell_command(cmd, options.failure_action, Some(shell_spawning_time))?; - execution_times.push(res.execution_time); - all_succeeded = all_succeeded && res.success; + times_real.push(res.time_real); + times_user.push(res.time_user); + times_system.push(res.time_system); + + all_succeeded = all_succeeded && success; progress_bar.inc(1); } progress_bar.finish_and_clear(); // Compute statistical quantities - let t_mean = mean(&execution_times); - let t_stddev = standard_deviation(&execution_times, Some(t_mean)); - let t_min = min(&execution_times); - let t_max = max(&execution_times); + let t_mean = mean(×_real); + let t_stddev = standard_deviation(×_real, Some(t_mean)); + 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, unit_mean) = format_duration_unit(t_mean, None); @@ -194,12 +229,17 @@ pub fn run_benchmark( let min_str = format_duration(t_min, Some(unit_mean)); let max_str = format_duration(t_max, Some(unit_mean)); + let (user_str, user_unit) = format_duration_unit(user_mean, None); + let system_str = format_duration(system_mean, Some(user_unit)); + println!( - " Time ({} ± {}): {} ± {}", + " Time ({} ± {}): {} ± {} [User: {}, System: {}]", Green.bold().paint("mean"), Green.paint("σ"), Green.bold().paint(mean_str), - Green.paint(stddev_str) + Green.paint(stddev_str), + Blue.paint(user_str), + Blue.paint(system_str) ); println!(" "); @@ -215,7 +255,7 @@ pub fn run_benchmark( let mut warnings = vec![]; // Check execution time - if execution_times.iter().any(|&t| t < MIN_EXECUTION_TIME) { + if times_real.iter().any(|&t| t < MIN_EXECUTION_TIME) { warnings.push(Warnings::FastExecutionTime); } diff --git a/src/hyperfine/cputime.rs b/src/hyperfine/cputime.rs new file mode 100644 index 0000000..b5c3d12 --- /dev/null +++ b/src/hyperfine/cputime.rs @@ -0,0 +1,49 @@ +use libc::{getrusage, rusage, RUSAGE_CHILDREN}; +use std::mem; + +use hyperfine::internal::Second; + +#[derive(Debug, Copy, Clone)] +pub struct CPUTimes { + /// Total amount of time spent executing in user mode + user_usec: i64, + + /// Total amount of time spent executing in kernel mode + system_usec: i64, +} + +#[derive(Debug, Copy, Clone)] +pub struct CPUInterval { + /// Total amount of time spent executing in user mode + pub user: Second, + + /// Total amount of time spent executing in kernel mode + pub system: Second, +} + +/// Read CPU execution times (user and system time) from kernel +pub fn get_cpu_times() -> CPUTimes { + let result: rusage = unsafe { + let mut buf = mem::zeroed(); + let success = getrusage(RUSAGE_CHILDREN, &mut buf); + assert_eq!(0, success); + buf + }; + + const USEC_PER_SEC: i64 = 1000 * 1000; + + CPUTimes { + user_usec: i64::from(result.ru_utime.tv_sec) * USEC_PER_SEC + + i64::from(result.ru_utime.tv_usec), + system_usec: i64::from(result.ru_stime.tv_sec) * USEC_PER_SEC + + i64::from(result.ru_stime.tv_usec), + } +} + +/// Compute the time intervals in between two CPUTimes snapshots +pub fn get_cpu_interval(start: &CPUTimes, end: &CPUTimes) -> CPUInterval { + CPUInterval { + user: ((end.user_usec - start.user_usec) as f64) * 1e-6, + system: ((end.system_usec - start.system_usec) as f64) * 1e-6, + } +} diff --git a/src/hyperfine/mod.rs b/src/hyperfine/mod.rs index b9caf45..235a213 100644 --- a/src/hyperfine/mod.rs +++ b/src/hyperfine/mod.rs @@ -1,3 +1,4 @@ pub mod benchmark; pub mod format; pub mod internal; +pub mod cputime; diff --git a/src/main.rs b/src/main.rs index 89a4511..9e9df14 100644 --- a/src/main.rs +++ b/src/main.rs @@ -2,6 +2,7 @@ extern crate ansi_term; #[macro_use] extern crate clap; extern crate indicatif; +extern crate libc; extern crate statistical; use std::cmp;