Update the progress bar for parallel downloads

This is actually a super tricky problem. We don't really have the capacity for
more than one line of update-able information in Cargo right now, so we need to
squeeze a lot of information into one line of output for Cargo. The main
constraints this tries to satisfy are:

* At all times it should be clear what's happening. Cargo shouldn't just hang
  with no output when downloading a crate for a long time, a counter ideally
  needs to be decreasing while the download progresses.

* If a progress bar is shown, it shouldn't jump around. This ends up just being
  a surprising user experience for most. Progress bars should only ever
  increase, but they may increase at different speeds.

* Cargo has, currently, at most one line of output (as mentioned above) to pack
  information into. We haven't delved into fancier terminal features that
  involve multiple lines of update-able output.

* When downloading crates as part of `cargo build` (the norm) we don't actually
  know ahead of time how many crates are being downloaded. We rely on the
  calculation of unit dependencies to naturally feed into downloading more
  crates.

* Furthermore, once we decide to download a crate, we don't actually know how
  big it is! We have to wait for the server to tell us how big it is.

There doesn't really seem to be a great solution that satisfies all of these
constraints unfortunately. As a result this commit implements a relatively
conservative solution which should hopefully get us most of the way there. There
isn't actually a progress bar but rather Cargo prints that it's got N crates
left to download, and if it takes awhile it prints out that there are M bytes
remaining.

Unfortunately the progress is pretty choppy and jerky, not providing a smooth
UI. This appears to largely be because Cargo will synchronously extract
tarballs, which for large crates can cause a noticeable pause. Cargo's not
really prepared internally to perform this work on helper threads, but ideally
if it could do so it would improve the output quite a bit! (making it much
smoother and also able to account for the time tarball extraction takes).
This commit is contained in:
Alex Crichton 2018-09-12 20:57:01 -07:00
parent 775b4ebca1
commit a46df8fe7d
6 changed files with 237 additions and 96 deletions

View file

@ -18,6 +18,7 @@ path = "src/cargo/lib.rs"
[dependencies]
atty = "0.2"
bytesize = "1.0"
crates-io = { path = "src/crates-io", version = "0.20" }
crossbeam-utils = "0.5"
crypto-hash = "0.3.1"

View file

@ -14,6 +14,7 @@ use jobserver::{Acquired, HelperThread};
use core::profiles::Profile;
use core::{PackageId, Target, TargetKind};
use handle_error;
use util;
use util::{internal, profile, CargoResult, CargoResultExt, ProcessBuilder};
use util::{Config, DependencyQueue, Dirty, Fresh, Freshness};
use util::{Progress, ProgressStyle};
@ -368,16 +369,7 @@ impl<'a> JobQueue<'a> {
opt_type += " + debuginfo";
}
let time_elapsed = {
let duration = cx.bcx.config.creation_time().elapsed();
let secs = duration.as_secs();
if secs >= 60 {
format!("{}m {:02}s", secs / 60, secs % 60)
} else {
format!("{}.{:02}s", secs, duration.subsec_nanos() / 10_000_000)
}
};
let time_elapsed = util::elapsed(cx.bcx.config.creation_time().elapsed());
if self.queue.is_empty() {
let message = format!(

View file

@ -4,21 +4,22 @@ use std::fmt;
use std::hash;
use std::mem;
use std::path::{Path, PathBuf};
use std::time::Duration;
use std::time::{Instant, Duration};
use bytesize::ByteSize;
use curl::easy::{Easy, HttpVersion};
use curl::multi::{Multi, EasyHandle};
use lazycell::LazyCell;
use semver::Version;
use serde::ser;
use toml;
use lazycell::LazyCell;
use curl::easy::{Easy, HttpVersion};
use curl::multi::{Multi, EasyHandle};
use core::{Dependency, Manifest, PackageId, SourceId, Target};
use core::{FeatureMap, SourceMap, Summary};
use core::source::MaybePackage;
use core::interning::InternedString;
use ops;
use util::{internal, lev_distance, Config, Progress, ProgressStyle};
use util::{self, internal, lev_distance, Config, Progress, ProgressStyle};
use util::errors::{CargoResult, CargoResultExt, HttpNot200};
use util::network::Retry;
@ -258,9 +259,11 @@ pub struct Downloads<'a, 'cfg: 'a> {
results: Vec<(usize, CargoResult<()>)>,
next: usize,
retry: Retry<'cfg>,
progress: RefCell<Progress<'cfg>>,
progress: RefCell<Option<Progress<'cfg>>>,
downloads_finished: usize,
downloaded_bytes: usize,
downloaded_bytes: u64,
largest: (u64, String),
start: Instant,
}
struct Download {
@ -269,8 +272,9 @@ struct Download {
data: RefCell<Vec<u8>>,
url: String,
descriptor: String,
total: Cell<usize>,
current: Cell<usize>,
total: Cell<u64>,
current: Cell<u64>,
start: Instant,
}
impl<'cfg> PackageSet<'cfg> {
@ -304,19 +308,21 @@ impl<'cfg> PackageSet<'cfg> {
pub fn enable_download<'a>(&'a self) -> CargoResult<Downloads<'a, 'cfg>> {
assert!(!self.downloading.replace(true));
Ok(Downloads {
start: Instant::now(),
set: self,
next: 0,
pending: HashMap::new(),
pending_ids: HashSet::new(),
results: Vec::new(),
retry: Retry::new(self.config)?,
progress: RefCell::new(Progress::with_style(
progress: RefCell::new(Some(Progress::with_style(
"Downloading",
ProgressStyle::Ratio,
self.config,
)),
))),
downloads_finished: 0,
downloaded_bytes: 0,
largest: (0, String::new()),
})
}
pub fn get_one(&self, id: &PackageId) -> CargoResult<&Package> {
@ -409,9 +415,9 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
handle.progress_function(move |dl_total, dl_cur, _, _| {
tls::with(|downloads| {
let dl = &downloads.pending[&token].0;
dl.total.set(dl_total as usize);
dl.current.set(dl_cur as usize);
downloads.tick(false).is_ok()
dl.total.set(dl_total as u64);
dl.current.set(dl_cur as u64);
downloads.tick(WhyTick::DownloadUpdate).is_ok()
})
})?;
@ -423,8 +429,10 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
descriptor,
total: Cell::new(0),
current: Cell::new(0),
start: Instant::now(),
};
self.enqueue(dl, handle)?;
self.tick(WhyTick::DownloadStarted)?;
Ok(None)
}
@ -443,8 +451,6 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
///
/// This function will panic if there are no remaining downloads.
pub fn wait(&mut self) -> CargoResult<&'a Package> {
self.tick(true)?;
let (dl, data) = loop {
assert_eq!(self.pending.len(), self.pending_ids.len());
let (token, result) = self.wait_for_curl()?;
@ -496,13 +502,26 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
//
// We can continue to iterate on this, but this is hopefully good enough
// for now.
if !self.progress.borrow().is_enabled() {
if !self.progress.borrow().as_ref().unwrap().is_enabled() {
self.set.config.shell().status("Downloading", &dl.descriptor)?;
}
self.downloads_finished += 1;
self.downloaded_bytes += dl.total.get();
self.tick(true)?;
if dl.total.get() > self.largest.0 {
self.largest = (dl.total.get(), dl.id.name().to_string());
}
// We're about to synchronously extract the crate below. While we're
// doing that our download progress won't actually be updated, nor do we
// have a great view into the progress of the extraction. Let's prepare
// the user for this CPU-heavy step if it looks like it'll take some
// time to do so.
if dl.total.get() < ByteSize::kb(400).0 {
self.tick(WhyTick::DownloadFinished)?;
} else {
self.tick(WhyTick::Extracting(&dl.id.name()))?;
}
// Inform the original source that the download is finished which
// should allow us to actually get the package and fill it in now.
@ -564,17 +583,67 @@ impl<'a, 'cfg> Downloads<'a, 'cfg> {
}
}
fn tick(&self, now: bool) -> CargoResult<()> {
self.progress.borrow_mut().tick(
self.downloads_finished,
self.downloads_finished + self.pending.len(),
)
fn tick(&self, why: WhyTick) -> CargoResult<()> {
let mut progress = self.progress.borrow_mut();
let progress = progress.as_mut().unwrap();
if let WhyTick::DownloadUpdate = why {
if !progress.update_allowed() {
return Ok(())
}
}
let mut msg = format!("{} crates", self.pending.len());
match why {
WhyTick::Extracting(krate) => {
msg.push_str(&format!(", extracting {} ...", krate));
}
_ => {
let mut dur = Duration::new(0, 0);
let mut remaining = 0;
for (dl, _) in self.pending.values() {
dur += dl.start.elapsed();
remaining += dl.total.get() - dl.current.get();
}
if remaining > 0 && dur > Duration::from_millis(500) {
msg.push_str(&format!(", remaining bytes: {}", ByteSize(remaining)));
}
}
}
progress.print_now(&msg)
}
}
enum WhyTick<'a> {
DownloadStarted,
DownloadUpdate,
DownloadFinished,
Extracting(&'a str),
}
impl<'a, 'cfg> Drop for Downloads<'a, 'cfg> {
fn drop(&mut self) {
self.set.downloading.set(false);
let progress = self.progress.get_mut().take().unwrap();
// Don't print a download summary if we're not using a progress bar,
// we've already printed lots of `Downloading...` items.
if !progress.is_enabled() {
return
}
if self.downloads_finished == 0 {
return
}
let mut status = format!("{} crates ({}) in {}",
self.downloads_finished,
ByteSize(self.downloaded_bytes),
util::elapsed(self.start.elapsed()));
if self.largest.0 > ByteSize::mb(1).0 {
status.push_str(&format!(
" (largest was `{}` at {})",
self.largest.1,
ByteSize(self.largest.0),
));
}
drop(self.set.config.shell().status("Downloaded", status));
}
}

View file

@ -15,6 +15,7 @@
#![cfg_attr(feature = "cargo-clippy", allow(wrong_self_convention))] // perhaps Rc should be special cased in Clippy?
extern crate atty;
extern crate bytesize;
extern crate clap;
#[cfg(target_os = "macos")]
extern crate core_foundation;

View file

@ -1,3 +1,5 @@
use std::time::Duration;
pub use self::cfg::{Cfg, CfgExpr};
pub use self::config::{homedir, Config, ConfigValue};
pub use self::dependency_queue::{DependencyQueue, Dirty, Fresh, Freshness};
@ -46,3 +48,13 @@ mod read2;
mod progress;
mod lockserver;
pub mod diagnostic_server;
pub fn elapsed(duration: Duration) -> String {
let secs = duration.as_secs();
if secs >= 60 {
format!("{}m {:02}s", secs / 60, secs % 60)
} else {
format!("{}.{:02}s", secs, duration.subsec_nanos() / 10_000_000)
}
}

View file

@ -16,13 +16,17 @@ pub enum ProgressStyle {
Ratio,
}
struct Throttle {
first: bool,
last_update: Instant,
}
struct State<'cfg> {
config: &'cfg Config,
format: Format,
first: bool,
last_update: Instant,
name: String,
done: bool,
throttle: Throttle,
}
struct Format {
@ -50,10 +54,9 @@ impl<'cfg> Progress<'cfg> {
max_width: n,
max_print: 80,
},
first: true,
last_update: Instant::now(),
name: name.to_string(),
done: false,
throttle: Throttle::new(),
}),
}
}
@ -71,31 +74,10 @@ impl<'cfg> Progress<'cfg> {
}
pub fn tick(&mut self, cur: usize, max: usize) -> CargoResult<()> {
match self.state {
Some(ref mut s) => s.tick(cur, max, "", true),
None => Ok(()),
}
}
pub fn clear(&mut self) {
if let Some(ref mut s) = self.state {
s.clear();
}
}
pub fn tick_now(&mut self, cur: usize, max: usize, msg: &str) -> CargoResult<()> {
match self.state {
Some(ref mut s) => s.tick(cur, max, msg, false),
None => Ok(()),
}
}
}
impl<'cfg> State<'cfg> {
fn tick(&mut self, cur: usize, max: usize, msg: &str, throttle: bool) -> CargoResult<()> {
if self.done {
return Ok(());
}
let s = match &mut self.state {
Some(s) => s,
None => return Ok(()),
};
// Don't update too often as it can cause excessive performance loss
// just putting stuff onto the terminal. We also want to avoid
@ -109,36 +91,110 @@ impl<'cfg> State<'cfg> {
// 2. If we've drawn something, then we rate limit ourselves to only
// draw to the console every so often. Currently there's a 100ms
// delay between updates.
if throttle {
if self.first {
let delay = Duration::from_millis(500);
if self.last_update.elapsed() < delay {
return Ok(());
}
self.first = false;
} else {
let interval = Duration::from_millis(100);
if self.last_update.elapsed() < interval {
return Ok(());
}
}
self.last_update = Instant::now();
if !s.throttle.allowed() {
return Ok(())
}
if cur == max {
s.tick(cur, max, "")
}
pub fn tick_now(&mut self, cur: usize, max: usize, msg: &str) -> CargoResult<()> {
match self.state {
Some(ref mut s) => s.tick(cur, max, msg),
None => Ok(()),
}
}
pub fn update_allowed(&mut self) -> bool {
match &mut self.state {
Some(s) => s.throttle.allowed(),
None => false,
}
}
pub fn print_now(&mut self, msg: &str) -> CargoResult<()> {
match &mut self.state {
Some(s) => s.print("", msg),
None => Ok(()),
}
}
pub fn clear(&mut self) {
if let Some(ref mut s) = self.state {
s.clear();
}
}
}
impl Throttle {
fn new() -> Throttle {
Throttle {
first: true,
last_update: Instant::now(),
}
}
fn allowed(&mut self) -> bool {
if self.first {
let delay = Duration::from_millis(500);
if self.last_update.elapsed() < delay {
return false
}
} else {
let interval = Duration::from_millis(100);
if self.last_update.elapsed() < interval {
return false
}
}
self.update();
true
}
fn update(&mut self) {
self.first = false;
self.last_update = Instant::now();
}
}
impl<'cfg> State<'cfg> {
fn tick(&mut self, cur: usize, max: usize, msg: &str) -> CargoResult<()> {
if self.done {
return Ok(());
}
if max > 0 && cur == max {
self.done = true;
}
// Write out a pretty header, then the progress bar itself, and then
// return back to the beginning of the line for the next print.
self.try_update_max_width();
if let Some(string) = self.format.progress_status(cur, max, msg) {
self.config.shell().status_header(&self.name)?;
write!(self.config.shell().err(), "{}\r", string)?;
if let Some(pbar) = self.format.progress(cur, max) {
self.print(&pbar, msg)?;
}
Ok(())
}
fn print(&mut self, prefix: &str, msg: &str) -> CargoResult<()> {
self.throttle.update();
self.try_update_max_width();
// make sure we have enough room for the header
if self.format.max_width < 15 {
return Ok(())
}
self.config.shell().status_header(&self.name)?;
let mut line = prefix.to_string();
self.format.render(&mut line, msg);
while line.len() < self.format.max_width - 15 {
line.push(' ');
}
write!(self.config.shell().err(), "{}\r", line)?;
Ok(())
}
fn clear(&mut self) {
self.try_update_max_width();
let blank = " ".repeat(self.format.max_width);
@ -153,7 +209,7 @@ impl<'cfg> State<'cfg> {
}
impl Format {
fn progress_status(&self, cur: usize, max: usize, msg: &str) -> Option<String> {
fn progress(&self, cur: usize, max: usize) -> Option<String> {
// Render the percentage at the far right and then figure how long the
// progress bar is
let pct = (cur as f64) / (max as f64);
@ -192,26 +248,36 @@ impl Format {
string.push_str("]");
string.push_str(&stats);
let mut avail_msg_len = self.max_width - self.width();
Some(string)
}
fn render(&self, string: &mut String, msg: &str) {
let mut avail_msg_len = self.max_width - string.len() - 15;
let mut ellipsis_pos = 0;
if avail_msg_len > 3 {
for c in msg.chars() {
let display_width = c.width().unwrap_or(0);
if avail_msg_len >= display_width {
avail_msg_len -= display_width;
string.push(c);
if avail_msg_len >= 3 {
ellipsis_pos = string.len();
}
} else {
string.truncate(ellipsis_pos);
string.push_str("...");
break;
if avail_msg_len <= 3 {
return
}
for c in msg.chars() {
let display_width = c.width().unwrap_or(0);
if avail_msg_len >= display_width {
avail_msg_len -= display_width;
string.push(c);
if avail_msg_len >= 3 {
ellipsis_pos = string.len();
}
} else {
string.truncate(ellipsis_pos);
string.push_str("...");
break;
}
}
}
Some(string)
#[cfg(test)]
fn progress_status(&self, cur: usize, max: usize, msg: &str) -> Option<String> {
let mut ret = self.progress(cur, max)?;
self.render(&mut ret, msg);
Some(ret)
}
fn width(&self) -> usize {