Show phase times separately in progress and results

Rename CargoModel to ScenarioModel (more accurate) and
other functions similarly.

NEWS.md

@@ -4,6 +4,8 @@
 
 - Added: A new `mutants.out/debug.log` with internal debugging information.
 
+- Improved: The time for check, build, and test is now shown separately in progress bars and output, to give a better indication of which is taking more time in the tree under test. Also, times are show in seconds with one decimal place, and they are styled more consistently.
+
 ## 0.2.10
 
 Released 2022-08-07

src/console.rs

@@ -28,14 +28,18 @@ impl Console {
         }
     }
 
+    /// Update that a cargo task is starting.
+    pub fn scenario_started(&self, scenario: &Scenario, log_file: &Utf8Path) {
+        let start = Instant::now();
+        let scenario_model = ScenarioModel::new(scenario, start, log_file.to_owned());
+        self.view.update(|model| {
+            model.i_mutant += scenario.is_mutant() as usize;
+            model.scenario_model = Some(scenario_model);
+        });
+    }
+
     /// Update that cargo finished.
-    pub fn cargo_outcome(
-        &self,
-        scenario: &Scenario,
-        start: Instant,
-        outcome: &Outcome,
-        options: &Options,
-    ) {
+    pub fn scenario_finished(&self, scenario: &Scenario, outcome: &Outcome, options: &Options) {
         self.view.update(|model| match outcome.summary() {
             SummaryOutcome::CaughtMutant => model.mutants_caught += 1,
             SummaryOutcome::MissedMutant => model.mutants_missed += 1,
@@ -62,7 +66,18 @@ impl Console {
         )
         .unwrap();
         if options.show_times {
-            write!(s, " in {}", style_elapsed_secs(start)).unwrap();
+            let prs: Vec<String> = outcome
+                .phase_results()
+                .iter()
+                .map(|pr| {
+                    format!(
+                        "{secs} {phase}",
+                        secs = style_secs(pr.duration),
+                        phase = style(pr.phase.to_string()).dim()
+                    )
+                })
+                .collect();
+            let _ = write!(s, " in {}", prs.join(" + "));
         }
         if outcome.should_show_logs() || options.show_all_logs {
             s.push('\n');
@@ -85,24 +100,24 @@ impl Console {
         })
     }
 
-    /// Update that a cargo task is starting.
-    pub fn start_cargo(&self, scenario: &Scenario, log_file: &Utf8Path) {
-        let start = Instant::now();
-        let cargo_model = CargoModel::new(scenario, start, log_file.to_owned());
+    /// A new phase of this scenario started.
+    pub fn scenario_phase_started(&self, phase: Phase) {
         self.view.update(|model| {
-            model.i_mutant += scenario.is_mutant() as usize;
-            model.cargo_model = Some(cargo_model);
-        });
+            model
+                .scenario_model
+                .as_mut()
+                .expect("scenario_model exists")
+                .phase_started(phase);
+        })
     }
 
-    /// Update the phase of the cargo task.
-    pub fn set_cargo_phase(&self, phase: &Phase) {
+    pub fn scenario_phase_finished(&self, phase: Phase) {
         self.view.update(|model| {
             model
-                .cargo_model
+                .scenario_model
                 .as_mut()
-                .expect("cargo model already started")
-                .phase = Some(phase.name())
+                .expect("scenario_model exists")
+                .phase_finished(phase);
         })
     }
 
@@ -123,7 +138,7 @@ impl Console {
 #[derive(Default)]
 struct LabModel {
     copy_model: Option<CopyModel>,
-    cargo_model: Option<CargoModel>,
+    scenario_model: Option<ScenarioModel>,
     lab_start_time: Option<Instant>,
     i_mutant: usize,
     n_mutants: usize,
@@ -141,7 +156,7 @@ impl nutmeg::Model for LabModel {
         if let Some(copy) = self.copy_model.as_mut() {
             s.push_str(&copy.render(width));
         }
-        if let Some(cargo_model) = self.cargo_model.as_mut() {
+        if let Some(scenario_model) = self.scenario_model.as_mut() {
             if !s.is_empty() {
                 s.push('\n')
             }
@@ -177,55 +192,84 @@ impl nutmeg::Model for LabModel {
                 writeln!(
                     s,
                     ", {} elapsed, about {} remaining",
-                    duration_minutes_seconds(elapsed),
-                    nutmeg::estimate_remaining(&lab_start_time, self.i_mutant, self.n_mutants)
+                    style_minutes_seconds(elapsed),
+                    style(nutmeg::estimate_remaining(
+                        &lab_start_time,
+                        self.i_mutant,
+                        self.n_mutants
+                    ))
+                    .cyan()
                 )
                 .unwrap();
             }
-            s.push_str(&cargo_model.render(width));
+            s.push_str(&scenario_model.render(width));
         }
         s
     }
 }
 
 impl LabModel {}
 
-/// A Nutmeg progress model for running `cargo test` etc.
+/// A Nutmeg progress model for running a single scenario.
 ///
 /// It draws the command and some description of what scenario is being tested.
-struct CargoModel {
+struct ScenarioModel {
     name: Cow<'static, str>,
-    start: Instant,
-    phase: Option<&'static str>,
+    phase_start: Instant,
+    phase: Option<Phase>,
+    /// Previously-executed phases and durations.
+    previous_phase_durations: Vec<(Phase, Duration)>,
     log_file: Utf8PathBuf,
 }
 
-impl nutmeg::Model for CargoModel {
+impl ScenarioModel {
+    fn new(scenario: &Scenario, start: Instant, log_file: Utf8PathBuf) -> ScenarioModel {
+        ScenarioModel {
+            name: style_scenario(scenario),
+            phase: None,
+            phase_start: start,
+            log_file,
+            previous_phase_durations: Vec::new(),
+        }
+    }
+
+    fn phase_started(&mut self, phase: Phase) {
+        self.phase = Some(phase);
+        self.phase_start = Instant::now();
+    }
+
+    fn phase_finished(&mut self, phase: Phase) {
+        debug_assert_eq!(self.phase, Some(phase));
+        self.previous_phase_durations
+            .push((phase, self.phase_start.elapsed()));
+        self.phase = None;
+    }
+}
+
+impl nutmeg::Model for ScenarioModel {
     fn render(&mut self, _width: usize) -> String {
         let mut s = String::with_capacity(100);
-        write!(s, "{} ", self.name).unwrap();
+        write!(s, "{} ... ", self.name).unwrap();
+        let mut prs = self
+            .previous_phase_durations
+            .iter()
+            .map(|(phase, duration)| format!("{} {}", style_secs(*duration), style(phase).dim()))
+            .collect::<Vec<_>>();
         if let Some(phase) = self.phase {
-            write!(s, "({}) ", phase).unwrap();
+            prs.push(format!(
+                "{} {}",
+                style_secs(self.phase_start.elapsed()),
+                style(phase).dim()
+            ));
         }
-        write!(s, "... {}", style_elapsed_secs(self.start)).unwrap();
+        write!(s, "{}", prs.join(" + ")).unwrap();
         if let Ok(last_line) = last_line(&self.log_file) {
             write!(s, "\n    {}", last_line).unwrap();
         }
         s
     }
 }
 
-impl CargoModel {
-    fn new(scenario: &Scenario, start: Instant, log_file: Utf8PathBuf) -> CargoModel {
-        CargoModel {
-            name: style_scenario(scenario),
-            phase: None,
-            start,
-            log_file,
-        }
-    }
-}
-
 /// A Nutmeg model for progress in copying a tree.
 pub struct CopyModel {
     bytes_copied: u64,
@@ -343,11 +387,19 @@ pub fn print_error(msg: &str) {
 }
 
 fn style_elapsed_secs(since: Instant) -> String {
-    style(format!("{:.1}s", since.elapsed().as_secs_f32()))
+    style_secs(since.elapsed())
+}
+
+fn style_secs(duration: Duration) -> String {
+    style(format!("{:.1}s", duration.as_secs_f32()))
         .cyan()
         .to_string()
 }
 
+fn style_minutes_seconds(duration: Duration) -> String {
+    style(duration_minutes_seconds(duration)).cyan().to_string()
+}
+
 pub fn duration_minutes_seconds(duration: Duration) -> String {
     let secs = duration.as_secs();
     format!("{}:{:02}", secs / 60, secs % 60)

src/lab.rs

@@ -197,29 +197,29 @@ fn run_cargo_phases(
     info!("start testing {scenario} in {in_dir}");
     let mut log_file = output_dir.create_log(scenario)?;
     log_file.message(&scenario.to_string());
-    let start_time = Instant::now();
     if let Scenario::Mutant(mutant) = scenario {
         log_file.message(&mutant.diff());
     }
-    console.start_cargo(scenario, log_file.path());
+    console.scenario_started(scenario, log_file.path());
 
     let mut outcome = Outcome::new(&log_file, scenario.clone());
     for &phase in phases {
         let phase_start = Instant::now();
-        console.set_cargo_phase(&phase);
+        console.scenario_phase_started(phase);
         let cargo_args = cargo_args(phase, options);
         let timeout = match phase {
             Phase::Test => options.test_timeout(),
             _ => Duration::MAX,
         };
         let cargo_result = run_cargo(&cargo_args, in_dir, &mut log_file, timeout, console)?;
         outcome.add_phase_result(phase, phase_start.elapsed(), cargo_result);
+        console.scenario_phase_finished(phase);
         if (phase == Phase::Check && options.check_only) || !cargo_result.success() {
             break;
         }
     }
     info!("{scenario} outcome {:?}", outcome.summary());
-    console.cargo_outcome(scenario, start_time, &outcome, options);
+    console.scenario_finished(scenario, &outcome, options);
 
     Ok(outcome)
 }

src/outcome.rs

@@ -160,16 +160,6 @@ impl Serialize for Outcome {
     }
 }
 
-#[derive(Debug, Clone, Eq, PartialEq, Serialize, Hash)]
-pub enum SummaryOutcome {
-    Success,
-    CaughtMutant,
-    MissedMutant,
-    Unviable,
-    Failure,
-    Timeout,
-}
-
 impl Outcome {
     pub fn new(log_file: &LogFile, scenario: Scenario) -> Outcome {
         Outcome {
@@ -204,6 +194,10 @@ impl Outcome {
         self.phase_results.last().unwrap().cargo_result
     }
 
+    pub fn phase_results(&self) -> &[PhaseResult] {
+        &self.phase_results
+    }
+
     /// True if this status indicates the user definitely needs to see the logs, because a task
     /// failed that should not have failed.
     pub fn should_show_logs(&self) -> bool {
@@ -280,11 +274,15 @@ impl Outcome {
     }
 }
 
+/// The result of running one phase of a mutation scenario, i.e. a single cargo check/build/test command.
 #[derive(Debug, Clone, Eq, PartialEq)]
-struct PhaseResult {
-    phase: Phase,
-    duration: Duration,
-    cargo_result: CargoResult,
+pub struct PhaseResult {
+    /// What phase was this?
+    pub phase: Phase,
+    /// How long did it take?
+    pub duration: Duration,
+    /// Did it succeed?
+    pub cargo_result: CargoResult,
 }
 
 impl Serialize for PhaseResult {
@@ -300,3 +298,14 @@ impl Serialize for PhaseResult {
         ss.end()
     }
 }
+
+/// Overall summary outcome for one mutant.
+#[derive(Debug, Clone, Eq, PartialEq, Serialize, Hash)]
+pub enum SummaryOutcome {
+    Success,
+    CaughtMutant,
+    MissedMutant,
+    Unviable,
+    Failure,
+    Timeout,
+}