Auto merge of #6615 - ehuss:progress-updates, r=alexcrichton

Improve progress bar flickering.

This attempts to reduce the amount of flickering primarily by reducing the number of times the progress bar is updated. The outline of changes:

- Don't display the progress bar for all the initial "Fresh" messages (if -v is not given).
- Don't redisplay the progress bar if it hasn't changed.
- Don't clear the progress bar if it is not displayed.
- Don't clear the progress bar for `Message` events that don't print anything.
- Drain messages in batches to avoid frequently updating the progress bar.
- Only display progress bar if the queue is blocked.

This significantly improves the initial "fresh" updates, but I still see some flickering during normal updates. I wasn't able to figure out why. Logging to a file and doing screen captures I see cargo is printing the progress bar <1ms after it is cleared. I'm guessing that it's just bad timing where the terminal renders just before the progress bar is displayed, and it has to wait an entire rendering cycle until it gets displayed.

I tested on a variety of different terminals and OS's, but the more testing this can get the better.

This unfortunately adds some brittleness of carefully clearing the progress bar before printing new messages. I don't really see an easy way to make that better since there is such a wide variety of ways a `Message` can be printed.

Fixes #6574

src/cargo/core/compiler/job_queue.rs

@@ -29,7 +29,7 @@ use super::{BuildContext, BuildPlan, CompileMode, Context, Kind, Unit};
 /// This structure is backed by the `DependencyQueue` type and manages the
 /// actual compilation step of each package. Packages enqueue units of work and
 /// then later on the entire graph is processed and compiled.
-pub struct JobQueue<'a> {
+pub struct JobQueue<'a, 'cfg> {
     queue: DependencyQueue<Key<'a>, Vec<(Job, Freshness)>>,
     tx: Sender<Message<'a>>,
     rx: Receiver<Message<'a>>,
@@ -39,6 +39,7 @@ pub struct JobQueue<'a> {
     documented: HashSet<PackageId>,
     counts: HashMap<PackageId, usize>,
     is_release: bool,
+    progress: Progress<'cfg>,
 }
 
 /// A helper structure for metadata about the state of a building package.
@@ -131,9 +132,10 @@ impl<'a> JobState<'a> {
     }
 }
 
-impl<'a> JobQueue<'a> {
-    pub fn new<'cfg>(bcx: &BuildContext<'a, 'cfg>) -> JobQueue<'a> {
+impl<'a, 'cfg> JobQueue<'a, 'cfg> {
+    pub fn new(bcx: &BuildContext<'a, 'cfg>) -> JobQueue<'a, 'cfg> {
         let (tx, rx) = channel();
+        let progress = Progress::with_style("Building", ProgressStyle::Ratio, bcx.config);
         JobQueue {
             queue: DependencyQueue::new(),
             tx,
@@ -144,10 +146,11 @@ impl<'a> JobQueue<'a> {
             documented: HashSet::new(),
             counts: HashMap::new(),
             is_release: bcx.build_config.release,
+            progress,
         }
     }
 
-    pub fn enqueue<'cfg>(
+    pub fn enqueue(
         &mut self,
         cx: &Context<'a, 'cfg>,
         unit: &Unit<'a>,
@@ -231,7 +234,6 @@ impl<'a> JobQueue<'a> {
         // successful and otherwise wait for pending work to finish if it failed
         // and then immediately return.
         let mut error = None;
-        let mut progress = Progress::with_style("Building", ProgressStyle::Ratio, cx.bcx.config);
         let total = self.queue.len();
         loop {
             // Dequeue as much work as we can, learning about everything
@@ -276,76 +278,80 @@ impl<'a> JobQueue<'a> {
             // to the jobserver itself.
             tokens.truncate(self.active.len() - 1);
 
-            let count = total - self.queue.len();
-            let active_names = self
-                .active
-                .iter()
-                .map(Key::name_for_progress)
-                .collect::<Vec<_>>();
-            drop(progress.tick_now(count, total, &format!(": {}", active_names.join(", "))));
-            let event = self.rx.recv().unwrap();
-            progress.clear();
-
-            match event {
-                Message::Run(cmd) => {
-                    cx.bcx
-                        .config
-                        .shell()
-                        .verbose(|c| c.status("Running", &cmd))?;
-                }
-                Message::BuildPlanMsg(module_name, cmd, filenames) => {
-                    plan.update(&module_name, &cmd, &filenames)?;
-                }
-                Message::Stdout(out) => {
-                    println!("{}", out);
-                }
-                Message::Stderr(err) => {
-                    let mut shell = cx.bcx.config.shell();
-                    shell.print_ansi(err.as_bytes())?;
-                    shell.err().write_all(b"\n")?;
-                }
-                Message::FixDiagnostic(msg) => {
-                    print.print(&msg)?;
-                }
-                Message::Finish(key, result) => {
-                    info!("end: {:?}", key);
-
-                    // self.active.remove_item(&key); // <- switch to this when stabilized.
-                    let pos = self
-                        .active
-                        .iter()
-                        .position(|k| *k == key)
-                        .expect("an unrecorded package has finished compiling");
-                    self.active.remove(pos);
-                    if !self.active.is_empty() {
-                        assert!(!tokens.is_empty());
-                        drop(tokens.pop());
+            // Drain all events at once to avoid displaying the progress bar
+            // unnecessarily.
+            let events: Vec<_> = self.rx.try_iter().collect();
+            let events = if events.is_empty() {
+                self.show_progress(total);
+                vec![self.rx.recv().unwrap()]
+            } else {
+                events
+            };
+
+            for event in events {
+                match event {
+                    Message::Run(cmd) => {
+                        cx.bcx
+                            .config
+                            .shell()
+                            .verbose(|c| c.status("Running", &cmd))?;
+                    }
+                    Message::BuildPlanMsg(module_name, cmd, filenames) => {
+                        plan.update(&module_name, &cmd, &filenames)?;
                     }
-                    match result {
-                        Ok(()) => self.finish(key, cx)?,
-                        Err(e) => {
-                            let msg = "The following warnings were emitted during compilation:";
-                            self.emit_warnings(Some(msg), &key, cx)?;
-
-                            if !self.active.is_empty() {
-                                error = Some(failure::format_err!("build failed"));
-                                handle_error(&e, &mut *cx.bcx.config.shell());
-                                cx.bcx.config.shell().warn(
-                                    "build failed, waiting for other \
-                                     jobs to finish...",
-                                )?;
-                            } else {
-                                error = Some(e);
+                    Message::Stdout(out) => {
+                        println!("{}", out);
+                    }
+                    Message::Stderr(err) => {
+                        let mut shell = cx.bcx.config.shell();
+                        shell.print_ansi(err.as_bytes())?;
+                        shell.err().write_all(b"\n")?;
+                    }
+                    Message::FixDiagnostic(msg) => {
+                        print.print(&msg)?;
+                    }
+                    Message::Finish(key, result) => {
+                        info!("end: {:?}", key);
+
+                        // self.active.remove_item(&key); // <- switch to this when stabilized.
+                        let pos = self
+                            .active
+                            .iter()
+                            .position(|k| *k == key)
+                            .expect("an unrecorded package has finished compiling");
+                        self.active.remove(pos);
+                        if !self.active.is_empty() {
+                            assert!(!tokens.is_empty());
+                            drop(tokens.pop());
+                        }
+                        match result {
+                            Ok(()) => self.finish(key, cx)?,
+                            Err(e) => {
+                                let msg = "The following warnings were emitted during compilation:";
+                                self.emit_warnings(Some(msg), &key, cx)?;
+
+                                if !self.active.is_empty() {
+                                    error = Some(failure::format_err!("build failed"));
+                                    handle_error(&e, &mut *cx.bcx.config.shell());
+                                    cx.bcx.config.shell().warn(
+                                        "build failed, waiting for other \
+                                         jobs to finish...",
+                                    )?;
+                                } else {
+                                    error = Some(e);
+                                }
                             }
                         }
                     }
-                }
-                Message::Token(acquired_token) => {
-                    tokens.push(acquired_token.chain_err(|| "failed to acquire jobserver token")?);
+                    Message::Token(acquired_token) => {
+                        tokens.push(
+                            acquired_token.chain_err(|| "failed to acquire jobserver token")?,
+                        );
+                    }
                 }
             }
         }
-        drop(progress);
+        self.progress.clear();
 
         let build_type = if self.is_release { "release" } else { "dev" };
         // NOTE: This may be a bit inaccurate, since this may not display the
@@ -384,6 +390,19 @@ impl<'a> JobQueue<'a> {
         }
     }
 
+    fn show_progress(&mut self, total: usize) {
+        let count = total - self.queue.len();
+        let active_names = self
+            .active
+            .iter()
+            .map(Key::name_for_progress)
+            .collect::<Vec<_>>();
+        drop(
+            self.progress
+                .tick_now(count, total, &format!(": {}", active_names.join(", "))),
+        );
+    }
+
     /// Executes a job in the `scope` given, pushing the spawned thread's
     /// handled onto `threads`.
     fn run(
@@ -422,27 +441,27 @@ impl<'a> JobQueue<'a> {
     }
 
     fn emit_warnings(
-        &self,
+        &mut self,
         msg: Option<&str>,
         key: &Key<'a>,
         cx: &mut Context<'_, '_>,
     ) -> CargoResult<()> {
         let output = cx.build_state.outputs.lock().unwrap();
         let bcx = &mut cx.bcx;
         if let Some(output) = output.get(&(key.pkg, key.kind)) {
-            if let Some(msg) = msg {
-                if !output.warnings.is_empty() {
+            if !output.warnings.is_empty() {
+                if let Some(msg) = msg {
                     writeln!(bcx.config.shell().err(), "{}\n", msg)?;
                 }
-            }
 
-            for warning in output.warnings.iter() {
-                bcx.config.shell().warn(warning)?;
-            }
+                for warning in output.warnings.iter() {
+                    bcx.config.shell().warn(warning)?;
+                }
 
-            if !output.warnings.is_empty() && msg.is_some() {
-                // Output an empty line.
-                writeln!(bcx.config.shell().err())?;
+                if msg.is_some() {
+                    // Output an empty line.
+                    writeln!(bcx.config.shell().err())?;
+                }
             }
         }
 

src/cargo/core/compiler/mod.rs

@@ -126,7 +126,7 @@ impl Executor for DefaultExecutor {
 
 fn compile<'a, 'cfg: 'a>(
     cx: &mut Context<'a, 'cfg>,
-    jobs: &mut JobQueue<'a>,
+    jobs: &mut JobQueue<'a, 'cfg>,
     plan: &mut BuildPlan,
     unit: &Unit<'a>,
     exec: &Arc<dyn Executor>,

src/cargo/core/shell.rs

@@ -23,6 +23,9 @@ pub struct Shell {
     err: ShellOut,
     /// How verbose messages should be
     verbosity: Verbosity,
+    /// Flag that indicates the current line needs to be cleared before
+    /// printing. Used when a progress bar is currently displayed.
+    needs_clear: bool,
 }
 
 impl fmt::Debug for Shell {
@@ -75,6 +78,7 @@ impl Shell {
                 tty: atty::is(atty::Stream::Stderr),
             },
             verbosity: Verbosity::Verbose,
+            needs_clear: false,
         }
     }
 
@@ -83,6 +87,7 @@ impl Shell {
         Shell {
             err: ShellOut::Write(out),
             verbosity: Verbosity::Verbose,
+            needs_clear: false,
         }
     }
 
@@ -97,10 +102,25 @@ impl Shell {
     ) -> CargoResult<()> {
         match self.verbosity {
             Verbosity::Quiet => Ok(()),
-            _ => self.err.print(status, message, color, justified),
+            _ => {
+                if self.needs_clear {
+                    self.err_erase_line();
+                }
+                self.err.print(status, message, color, justified)
+            }
         }
     }
 
+    /// Set whether or not the next print should clear the current line.
+    pub fn set_needs_clear(&mut self, needs_clear: bool) {
+        self.needs_clear = needs_clear;
+    }
+
+    /// True if the `needs_clear` flag is not set.
+    pub fn is_cleared(&self) -> bool {
+        !self.needs_clear
+    }
+
     /// Returns the width of the terminal in spaces, if any
     pub fn err_width(&self) -> Option<usize> {
         match self.err {
@@ -119,13 +139,17 @@ impl Shell {
 
     /// Get a reference to the underlying writer
     pub fn err(&mut self) -> &mut dyn Write {
+        if self.needs_clear {
+            self.err_erase_line();
+        }
         self.err.as_write()
     }
 
     /// Erase from cursor to end of line.
     pub fn err_erase_line(&mut self) {
         if let ShellOut::Stream { tty: true, .. } = self.err {
             imp::err_erase_line(self);
+            self.needs_clear = false;
         }
     }
 
@@ -251,6 +275,9 @@ impl Shell {
 
     /// Prints a message and translates ANSI escape code into console colors.
     pub fn print_ansi(&mut self, message: &[u8]) -> CargoResult<()> {
+        if self.needs_clear {
+            self.err_erase_line();
+        }
         #[cfg(windows)]
         {
             if let ShellOut::Stream { stream, .. } = &mut self.err {
@@ -361,7 +388,7 @@ mod imp {
         // This is the "EL - Erase in Line" sequence. It clears from the cursor
         // to the end of line.
         // https://en.wikipedia.org/wiki/ANSI_escape_code#CSI_sequences
-        let _ = shell.err().write_all(b"\x1B[K");
+        let _ = shell.err.as_write().write_all(b"\x1B[K");
     }
 }
 
@@ -434,6 +461,6 @@ mod imp {
 fn default_err_erase_line(shell: &mut Shell) {
     if let Some(max_width) = imp::stderr_width() {
         let blank = " ".repeat(max_width);
-        drop(write!(shell.err(), "{}\r", blank));
+        drop(write!(shell.err.as_write(), "{}\r", blank));
     }
 }