Merge pull request #581 from devonhollowood/elapsed

Add elapsed time to progress bar

src/benchmark/mod.rs

@@ -6,6 +6,7 @@ pub mod scheduler;
 
 use std::cmp;
 use std::io::{self, Write};
+use std::time::Instant;
 
 use crate::benchmark::executor::BenchmarkIteration;
 use crate::command::Command;
@@ -14,7 +15,9 @@ use crate::options::{
 };
 use crate::outlier_detection::OUTLIER_THRESHOLD;
 use crate::output::console_writeln;
-use crate::output::progress_bar::get_progress_bar;
+use crate::output::progress_bar::{
+    finish_initial_measurement, get_progress_bar, start_initial_measurement,
+};
 use crate::output::warnings::{OutlierWarningOptions, Warnings};
 use crate::parameter::ParameterNameAndValue;
 use crate::quantity::{const_time_from_seconds, ratio, FormatQuantity, Time, Zero};
@@ -244,7 +247,11 @@ impl<'a> Benchmark<'a> {
         let progress_bar = if self.options.output_style != OutputStyleOption::Disabled {
             Some(get_progress_bar(
                 self.options.run_bounds.min,
-                "Initial time measurement",
+                if preparation_command.is_some() {
+                    "Running preparation command"
+                } else {
+                    "Initial run"
+                },
                 self.options.output_style,
             ))
         } else {
@@ -258,6 +265,9 @@ impl<'a> Benchmark<'a> {
         });
 
         // Initial timing run
+        if let Some(bar) = progress_bar.as_ref() {
+            start_initial_measurement(bar, Instant::now());
+        }
         let res = self.executor.run_command_and_measure(
             self.command,
             benchmark_iteration,
@@ -266,6 +276,18 @@ impl<'a> Benchmark<'a> {
         )?;
         let success = res.exit_status.success();
 
+        if let Some(bar) = progress_bar.as_ref() {
+            let time_unit = self
+                .options
+                .time_unit
+                .unwrap_or(res.time_wall_clock.suitable_unit());
+            let estimate = res.time_wall_clock.format(time_unit);
+            finish_initial_measurement(
+                bar,
+                format!("Current estimate: {}", estimate.to_string().green()),
+            );
+        }
+
         let conclusion_result = run_conclusion_command(benchmark_iteration)?;
         let conclusion_overhead = conclusion_result.map_or(Time::zero(), |res| {
             res.time_wall_clock + self.executor.time_overhead()
@@ -299,16 +321,13 @@ impl<'a> Benchmark<'a> {
 
         // 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)
+            bar.set_length(count);
+            bar.inc(1);
         }
 
         // Gather statistics (perform the actual benchmark)
         for i in 0..count_remaining {
             let benchmark_iteration = BenchmarkIteration::Benchmark(i + 1);
-            run_preparation_command(benchmark_iteration)?;
 
             let msg = {
                 let t_wall_clock_mean = measurements.time_wall_clock_mean();
@@ -324,6 +343,8 @@ impl<'a> Benchmark<'a> {
                 bar.set_message(msg.to_owned())
             }
 
+            run_preparation_command(benchmark_iteration)?;
+
             let res = self.executor.run_command_and_measure(
                 self.command,
                 benchmark_iteration,

src/output/progress_bar.rs

@@ -1,5 +1,6 @@
-use indicatif::{ProgressBar, ProgressStyle};
-use std::time::Duration;
+use indicatif::{FormattedDuration, ProgressBar, ProgressState, ProgressStyle};
+use std::fmt;
+use std::time::{Duration, Instant};
 
 use crate::options::OutputStyleOption;
 
@@ -9,13 +10,44 @@ const TICK_SETTINGS: (&str, u64) = ("⠋⠙⠹⠸⠼⠴⠦⠧⠇⠏ ", 80);
 #[cfg(windows)]
 const TICK_SETTINGS: (&str, u64) = (r"+-x| ", 200);
 
+// Keep the message area 30 columns wide across preparation, the initial run,
+// and estimates so that switching between them does not move the bar.
+const DEFAULT_TEMPLATE: &str = " {spinner} {msg:<30} {wide_bar} ETA {eta_precise} ";
+const INITIAL_TEMPLATE: &str =
+    " {spinner} Initial run: {initial_elapsed:<17} {wide_bar} ETA {eta_precise} ";
+
+/// Show the time elapsed since the initial benchmark command started.
+pub fn start_initial_measurement(bar: &ProgressBar, started: Instant) {
+    let style = bar
+        .style()
+        .template(INITIAL_TEMPLATE)
+        .expect("no template error")
+        .with_key(
+            "initial_elapsed",
+            move |_: &ProgressState, w: &mut dyn fmt::Write| {
+                write!(w, "{}", FormattedDuration(started.elapsed())).unwrap();
+            },
+        );
+    bar.set_style(style);
+}
+
+/// Stop showing the initial timer and display the next phase's message.
+pub fn finish_initial_measurement(bar: &ProgressBar, message: String) {
+    bar.set_message(message);
+    bar.set_style(
+        bar.style()
+            .template(DEFAULT_TEMPLATE)
+            .expect("no template error"),
+    );
+}
+
 /// Return a pre-configured progress bar
 pub fn get_progress_bar(length: u64, msg: &str, option: OutputStyleOption) -> ProgressBar {
     let progressbar_style = match option {
         OutputStyleOption::Basic | OutputStyleOption::Color => ProgressStyle::default_bar(),
         _ => ProgressStyle::default_spinner()
             .tick_chars(TICK_SETTINGS.0)
-            .template(" {spinner} {msg:<30} {wide_bar} ETA {eta_precise} ")
+            .template(DEFAULT_TEMPLATE)
             .expect("no template error"),
     };