[nextest-runner] use indicatif's println to print statuses (#2740)

The `println` function causes notably less flicker than `suspend` -- we
arrange things such that message updates and newlines are part of the
same terminal flush. (Spent some time in gdb walking over this code.)

Also bump up the default tick rate to 20/sec, which feels much nicer
than 10/sec. Make this configurable via a semi-hidden environment
variable.

Author: sunshowers

nextest-runner/src/reporter/displayer/imp.rs

@@ -46,12 +46,6 @@ use std::{
     time::Duration,
 };
 
-/// The duration after which ticks are generated.
-pub const TICK_INTERVAL: Duration = Duration::from_millis(100);
-
-/// The refresh rate for the progress bar, set to match the tick interval in hz.
-pub const PROGRESS_REFRESH_RATE_HZ: u8 = 10;
-
 pub(crate) struct DisplayReporterBuilder {
     pub(crate) default_filter: CompiledDefaultFilter,
     pub(crate) status_levels: StatusLevels,
@@ -224,6 +218,10 @@ impl<'a> DisplayReporter<'a> {
                 progress_bar,
                 term_progress,
             } => {
+                if let Some(term_progress) = term_progress {
+                    term_progress.update_progress(event);
+                }
+
                 if let Some(state) = progress_bar {
                     // Write to a string that will be printed as a log line.
                     let mut buf = String::new();
@@ -232,11 +230,6 @@ impl<'a> DisplayReporter<'a> {
                         .map_err(WriteEventError::Io)?;
 
                     state.update_progress_bar(event, &self.inner.styles);
-                    if let Some(term_progress) = term_progress {
-                        term_progress
-                            .update_progress(event, &mut buf)
-                            .map_err(WriteEventError::Io)?;
-                    }
                     state.write_buf(&buf);
                     Ok(())
                 } else {
@@ -245,11 +238,6 @@ impl<'a> DisplayReporter<'a> {
                     self.inner
                         .write_event_impl(event, &mut writer)
                         .map_err(WriteEventError::Io)?;
-                    if let Some(state) = term_progress {
-                        state
-                            .update_progress(event, &mut writer)
-                            .map_err(WriteEventError::Io)?;
-                    }
                     writer.flush().map_err(WriteEventError::Io)
                 }
             }
@@ -280,24 +268,41 @@ impl ReporterStderrImpl<'_> {
     fn tick(&mut self, styles: &Styles) {
         match self {
             ReporterStderrImpl::Terminal {
-                progress_bar: Some(state),
-                ..
+                progress_bar,
+                term_progress,
             } => {
-                state.tick(styles);
+                if let Some(state) = progress_bar {
+                    state.tick(styles);
+                }
+                if let Some(term_progress) = term_progress {
+                    // In this case, write the last value directly to stderr.
+                    // This is a very small amount of data so buffering is not
+                    // required. It also doesn't have newlines or any visible
+                    // text, so it can be directly written out to stderr without
+                    // going through the progress bar (which screws up
+                    // indicatif's calculations).
+                    eprint!("{}", term_progress.last_value())
+                }
             }
-            ReporterStderrImpl::Terminal { .. } | ReporterStderrImpl::Buffer(_) => {}
+            ReporterStderrImpl::Buffer(_) => {}
         }
     }
 
     fn finish_and_clear_bar(&self) {
         match self {
             ReporterStderrImpl::Terminal {
-                progress_bar: Some(state),
-                ..
+                progress_bar,
+                term_progress,
             } => {
-                state.finish_and_clear();
+                if let Some(state) = progress_bar {
+                    state.finish_and_clear();
+                }
+                if let Some(term_progress) = term_progress {
+                    // The last value is expected to be Remove.
+                    eprint!("{}", term_progress.last_value())
+                }
             }
-            ReporterStderrImpl::Terminal { .. } | ReporterStderrImpl::Buffer(_) => {}
+            ReporterStderrImpl::Buffer(_) => {}
         }
     }
 

nextest-runner/src/reporter/displayer/mod.rs

@@ -9,7 +9,7 @@ mod progress;
 mod status_level;
 mod unit_output;
 
-pub use imp::*;
+pub(crate) use imp::*;
 pub use progress::{MaxProgressRunning, ShowProgress};
 pub use status_level::*;
 pub use unit_output::*;

nextest-runner/src/reporter/displayer/progress.rs

@@ -6,25 +6,38 @@ use crate::{
     helpers::{DisplayTestInstance, plural},
     list::TestInstanceId,
     reporter::{
-        PROGRESS_REFRESH_RATE_HZ, displayer::formatters::DisplayBracketedHhMmSs, events::*,
-        helpers::Styles,
+        displayer::formatters::DisplayBracketedHhMmSs,
+        events::*,
+        helpers::{Styles, print_lines_in_chunks},
     },
-    write_str::WriteStr,
 };
 use indicatif::{ProgressBar, ProgressDrawTarget, ProgressStyle};
 use nextest_metadata::RustBinaryId;
 use owo_colors::OwoColorize;
 use std::{
     cmp::{max, min},
     env, fmt,
-    io::{self, IsTerminal, Write},
+    io::IsTerminal,
     num::NonZero,
     str::FromStr,
     time::{Duration, Instant},
 };
 use swrite::{SWrite, swrite};
 use tracing::debug;
 
+/// The refresh rate for the progress bar, set to a minimal value.
+///
+/// For progress, during each tick, two things happen:
+///
+/// - We update the message, calling self.bar.set_message.
+/// - We print any buffered output.
+///
+/// We want both of these updates to be combined into one terminal flush, so we
+/// set *this* to a minimal value (so self.bar.set_message doesn't do a redraw),
+/// and rely on ProgressBar::print_and_flush_buffer to always flush the
+/// terminal.
+const PROGRESS_REFRESH_RATE_HZ: u8 = 1;
+
 /// The maximum number of running tests to display with
 /// `--show-progress=running` or `only`.
 #[derive(Clone, Copy, Debug, Eq, PartialEq)]
@@ -159,7 +172,10 @@ pub(super) struct ProgressBarState {
     max_running_displayed: usize,
     // None when the running tests are not displayed
     running_tests: Option<Vec<RunningTest>>,
-    buffer: Vec<u8>,
+    buffer: String,
+    // Size in bytes for chunking println calls. Configurable via the
+    // undocumented __NEXTEST_PROGRESS_PRINTLN_CHUNK_SIZE env var.
+    println_chunk_size: usize,
     // Reasons for hiding the progress bar. We show the progress bar if none of
     // these are set and hide it if any of them are set.
     //
@@ -201,14 +217,23 @@ impl ProgressBarState {
 
         let running_tests = show_running.then(Vec::new);
 
+        // The println chunk size defaults to a value chosen by experimentation,
+        // locally and over SSH. This controls how often the progress bar
+        // refreshes during large output bursts.
+        let println_chunk_size = env::var("__NEXTEST_PROGRESS_PRINTLN_CHUNK_SIZE")
+            .ok()
+            .and_then(|s| s.parse::<usize>().ok())
+            .unwrap_or(4096);
+
         Self {
             bar,
             stats: RunStats::default(),
             running: 0,
             max_progress_running,
             max_running_displayed: 0,
             running_tests,
-            buffer: Vec::new(),
+            buffer: String::new(),
+            println_chunk_size,
             hidden_no_capture: false,
             hidden_run_paused: false,
             hidden_info_response: false,
@@ -222,25 +247,38 @@ impl ProgressBarState {
     }
 
     fn print_and_clear_buffer(&mut self) {
-        self.print_buffer();
+        self.print_and_force_redraw();
         self.buffer.clear();
     }
 
-    fn print_buffer(&self) {
-        // ProgressBar::println doesn't print status lines if the bar is
-        // hidden. The suspend method prints it in all cases.
-        // suspend forces a full redraw, so we call it only if there is
-        // something in the buffer
-        if !self.buffer.is_empty() {
-            self.bar.suspend(|| {
-                std::io::stderr()
-                    .write_all(&self.buffer)
-                    .expect("write to succeed")
-            });
+    /// Prints the contents of the buffer, and always forces a redraw.
+    fn print_and_force_redraw(&self) {
+        if self.buffer.is_empty() {
+            // Force a redraw as part of our contract. See the documentation for
+            // `PROGRESS_REFRESH_RATE_HZ`.
+            self.bar.force_draw();
+            return;
         }
+
+        // println below also forces a redraw, so we don't need to call
+        // force_draw in this case.
+
+        // ProgressBar::println is only called if there's something in the
+        // buffer, for two reasons:
+        //
+        // 1. If passed in nothing at all, it prints an empty line.
+        // 2. It forces a full redraw.
+        //
+        // But if self.buffer is too large, we can overwhelm the terminal with
+        // large amounts of non-progress-bar output, causing the progress bar to
+        // flicker in and out. To avoid those issues, we chunk the output to
+        // maintain progress bar visibility by redrawing it regularly.
+        print_lines_in_chunks(&self.buffer, self.println_chunk_size, |chunk| {
+            self.bar.println(chunk);
+        });
     }
 
-    pub(super) fn update_message(&mut self, styles: &Styles) {
+    fn update_message(&mut self, styles: &Styles) {
         let mut msg = progress_bar_msg(&self.stats, self.running, styles);
         msg += "     ";
 
@@ -457,12 +495,12 @@ impl ProgressBarState {
     }
 
     pub(super) fn write_buf(&mut self, buf: &str) {
-        self.buffer.extend_from_slice(buf.as_bytes());
+        self.buffer.push_str(buf);
     }
 
     #[inline]
     pub(super) fn finish_and_clear(&self) {
-        self.print_buffer();
+        self.print_and_force_redraw();
         self.bar.finish_and_clear();
     }
 
@@ -487,7 +525,10 @@ impl ProgressBarState {
 }
 
 /// OSC 9 terminal progress reporting.
-pub(super) struct TerminalProgress {}
+#[derive(Default)]
+pub(super) struct TerminalProgress {
+    last_value: TerminalProgressValue,
+}
 
 impl TerminalProgress {
     const ENV: &str = "CARGO_TERM_PROGRESS_TERM_INTEGRATION";
@@ -500,7 +541,7 @@ impl TerminalProgress {
                     if let Some(v) = config.term.progress.term_integration {
                         if v {
                             debug!("enabling terminal progress reporting based on {source:?}");
-                            return Some(Self {});
+                            return Some(Self::default());
                         } else {
                             debug!("disabling terminal progress reporting based on {source:?}");
                             return None;
@@ -514,7 +555,7 @@ impl TerminalProgress {
                                 "enabling terminal progress reporting based on \
                                  CARGO_TERM_PROGRESS_TERM_INTEGRATION environment variable"
                             );
-                            return Some(Self {});
+                            return Some(Self::default());
                         } else if v == "false" {
                             debug!(
                                 "disabling terminal progress reporting based on \
@@ -533,7 +574,7 @@ impl TerminalProgress {
                     if let Some(v) = config.term.progress.term_integration {
                         if v {
                             debug!("enabling terminal progress reporting based on {source:?}");
-                            return Some(Self {});
+                            return Some(Self::default());
                         } else {
                             debug!("disabling terminal progress reporting based on {source:?}");
                             return None;
@@ -543,14 +584,10 @@ impl TerminalProgress {
             }
         }
 
-        supports_osc_9_4(stream).then_some(TerminalProgress {})
+        supports_osc_9_4(stream).then(Self::default)
     }
 
-    pub(super) fn update_progress(
-        &self,
-        event: &TestEvent<'_>,
-        writer: &mut dyn WriteStr,
-    ) -> Result<(), io::Error> {
+    pub(super) fn update_progress(&mut self, event: &TestEvent<'_>) {
         let value = match &event.kind {
             TestEventKind::RunStarted { .. }
             | TestEventKind::StressSubRunStarted { .. }
@@ -594,7 +631,11 @@ impl TerminalProgress {
             }
         };
 
-        write!(writer, "{value}")
+        self.last_value = value;
+    }
+
+    pub(super) fn last_value(&self) -> &TerminalProgressValue {
+        &self.last_value
     }
 }
 
@@ -628,9 +669,10 @@ fn supports_osc_9_4(stream: &dyn IsTerminal) -> bool {
 /// A progress status value printable as an ANSI OSC 9;4 escape code.
 ///
 /// Adapted from Cargo 1.87.
-#[derive(PartialEq, Debug)]
-enum TerminalProgressValue {
+#[derive(PartialEq, Debug, Default)]
+pub(super) enum TerminalProgressValue {
     /// No output.
+    #[default]
     None,
     /// Remove progress.
     Remove,