Experiment: Create timing report.

Cargo.toml

@@ -37,6 +37,7 @@ git2-curl = "0.11.0"
 glob = "0.3.0"
 hex = "0.3"
 home = "0.5"
+humantime = "1.2.0"
 ignore = "0.4.7"
 lazy_static = "1.2.0"
 jobserver = "0.1.13"

src/bin/cargo/cli.rs

@@ -36,6 +36,7 @@ Available unstable (nightly-only) flags:
  -Z config-profile -- Read profiles from .cargo/config files
  -Z install-upgrade -- `cargo install` will upgrade instead of failing
  -Z cache-messages -- Cache compiler messages
+ -Z timings -- Display concurrency information
 
 Run with 'cargo -Z [FLAG] [SUBCOMMAND]'"
  );

src/cargo/core/compiler/context/mod.rs

@@ -129,7 +129,7 @@ impl<'a, 'cfg> Context<'a, 'cfg> {
  export_dir: Option<PathBuf>,
  exec: &Arc<dyn Executor>,
  ) -> CargoResult<Compilation<'cfg>> {
- let mut queue = JobQueue::new(self.bcx);
+ let mut queue = JobQueue::new(self.bcx, units);
  let mut plan = BuildPlan::new();
  let build_plan = self.bcx.build_config.build_plan;
  self.prepare_units(export_dir, units)?;
@@ -513,6 +513,6 @@ impl<'a, 'cfg> Context<'a, 'cfg> {
  /// Returns whether when `unit` is built whether it should emit metadata as
  /// well because some compilations rely on that.
  pub fn rmeta_required(&self, unit: &Unit<'a>) -> bool {
- self.rmeta_required.contains(unit)
+ self.rmeta_required.contains(unit) || self.bcx.config.cli_unstable().timings.is_some()
  }
 }

src/cargo/core/compiler/job_queue.rs

@@ -14,6 +14,7 @@ use super::job::{
  Freshness::{self, Dirty, Fresh},
  Job,
 };
+use super::timings::Timings;
 use super::{BuildContext, BuildPlan, CompileMode, Context, Unit};
 use crate::core::{PackageId, TargetKind};
 use crate::handle_error;
@@ -39,6 +40,7 @@ pub struct JobQueue<'a, 'cfg> {
  is_release: bool,
  progress: Progress<'cfg>,
  next_id: u32,
+ timings: Timings<'a, 'cfg>,
 }
 
 pub struct JobState<'a> {
@@ -80,7 +82,7 @@ enum Artifact {
 }
 
 enum Message {
- Run(String),
+ Run(u32, String),
  BuildPlanMsg(String, ProcessBuilder, Arc<Vec<OutputFile>>),
  Stdout(String),
  Stderr(String),
@@ -91,7 +93,7 @@ enum Message {
 
 impl<'a> JobState<'a> {
  pub fn running(&self, cmd: &ProcessBuilder) {
- let _ = self.tx.send(Message::Run(cmd.to_string()));
+ let _ = self.tx.send(Message::Run(self.id, cmd.to_string()));
  }
 
  pub fn build_plan(
@@ -119,7 +121,6 @@ impl<'a> JobState<'a> {
  /// This should only be called once because a metadata file can only be
  /// produced once!
  pub fn rmeta_produced(&self) {
- assert!(self.rmeta_required.get());
  self.rmeta_required.set(false);
  let _ = self
  .tx
@@ -128,9 +129,10 @@ impl<'a> JobState<'a> {
 }
 
 impl<'a, 'cfg> JobQueue<'a, 'cfg> {
- pub fn new(bcx: &BuildContext<'a, 'cfg>) -> JobQueue<'a, 'cfg> {
+ pub fn new(bcx: &BuildContext<'a, 'cfg>, root_units: &[Unit<'a>]) -> JobQueue<'a, 'cfg> {
  let (tx, rx) = channel();
  let progress = Progress::with_style("Building", ProgressStyle::Ratio, bcx.config);
+ let timings = Timings::new(bcx, root_units);
  JobQueue {
  queue: DependencyQueue::new(),
  tx,
@@ -142,6 +144,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
  is_release: bcx.build_config.release,
  progress,
  next_id: 0,
+ timings,
  }
  }
 
@@ -316,6 +319,9 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
  // to the jobserver itself.
  tokens.truncate(self.active.len() - 1);
 
+ self.timings
+ .mark_concurrency(self.active.len(), queue.len(), self.queue.len());
+
  // Drain all events at once to avoid displaying the progress bar
  // unnecessarily.
  let events: Vec<_> = self.rx.try_iter().collect();
@@ -328,18 +334,18 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
 
  for event in events {
  match event {
- Message::Run(cmd) => {
+ Message::Run(id, cmd) => {
  cx.bcx
  .config
  .shell()
  .verbose(|c| c.status("Running", &cmd))?;
+ self.timings.unit_start(id, self.active[&id]);
  }
  Message::BuildPlanMsg(module_name, cmd, filenames) => {
  plan.update(&module_name, &cmd, &filenames)?;
  }
  Message::Stdout(out) => {
- self.progress.clear();
- println!("{}", out);
+ cx.bcx.config.shell().stdout_println(out);
  }
  Message::Stderr(err) => {
  let mut shell = cx.bcx.config.shell();
@@ -367,7 +373,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
  };
  info!("end ({:?}): {:?}", unit, result);
  match result {
- Ok(()) => self.finish(&unit, artifact, cx)?,
+ Ok(()) => self.finish(id, &unit, artifact, cx)?,
  Err(e) => {
  let msg = "The following warnings were emitted during compilation:";
  self.emit_warnings(Some(msg), &unit, cx)?;
@@ -425,6 +431,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
  if !cx.bcx.build_config.build_plan {
  cx.bcx.config.shell().status("Finished", message)?;
  }
+ self.timings.finished()?;
  Ok(())
  } else {
  debug!("queue: {:#?}", self.queue);
@@ -519,8 +526,12 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
  }
 
  match fresh {
- Freshness::Fresh => doit(),
+ Freshness::Fresh => {
+ self.timings.add_fresh();
+ doit()
+ }
  Freshness::Dirty => {
+ self.timings.add_dirty();
  scope.spawn(move |_| doit());
  }
  }
@@ -558,14 +569,19 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
 
  fn finish(
  &mut self,
+ id: u32,
  unit: &Unit<'a>,
  artifact: Artifact,
  cx: &mut Context<'_, '_>,
  ) -> CargoResult<()> {
  if unit.mode.is_run_custom_build() && cx.bcx.show_warnings(unit.pkg.package_id()) {
  self.emit_warnings(None, unit, cx)?;
  }
- self.queue.finish(unit, &artifact);
+ let unlocked = self.queue.finish(unit, &artifact);
+ match artifact {
+ Artifact::All => self.timings.unit_finished(id, unlocked),
+ Artifact::Metadata => self.timings.unit_rmeta_finished(id, unlocked),
+ }
  Ok(())
  }
 

src/cargo/core/compiler/mod.rs

@@ -11,20 +11,20 @@ mod layout;
 mod links;
 mod output_depinfo;
 pub mod standard_lib;
+mod timings;
 mod unit;
 pub mod unit_dependencies;
 
 use std::env;
 use std::ffi::{OsStr, OsString};
 use std::fs::{self, File};
 use std::io::Write;
-use std::path::{Path, PathBuf};
+use std::path::PathBuf;
 use std::sync::Arc;
 
 use failure::Error;
 use lazycell::LazyCell;
 use log::debug;
-use same_file::is_same_file;
 use serde::Serialize;
 
 pub use self::build_config::{BuildConfig, CompileMode, MessageFormat};
@@ -442,12 +442,12 @@ fn link_targets<'a, 'cfg>(
  }
  };
  destinations.push(dst.clone());
- hardlink_or_copy(src, dst)?;
+ paths::link_or_copy(src, dst)?;
  if let Some(ref path) = output.export_path {
  let export_dir = export_dir.as_ref().unwrap();
  paths::create_dir_all(export_dir)?;
 
- hardlink_or_copy(src, path)?;
+ paths::link_or_copy(src, path)?;
  }
  }
 
@@ -476,54 +476,6 @@ fn link_targets<'a, 'cfg>(
  }))
 }
 
-/// Hardlink (file) or symlink (dir) src to dst if possible, otherwise copy it.
-fn hardlink_or_copy(src: &Path, dst: &Path) -> CargoResult<()> {
- debug!("linking {} to {}", src.display(), dst.display());
- if is_same_file(src, dst).unwrap_or(false) {
- return Ok(());
- }
-
- // NB: we can't use dst.exists(), as if dst is a broken symlink,
- // dst.exists() will return false. This is problematic, as we still need to
- // unlink dst in this case. symlink_metadata(dst).is_ok() will tell us
- // whether dst exists *without* following symlinks, which is what we want.
- if fs::symlink_metadata(dst).is_ok() {
- paths::remove_file(&dst)?;
- }
-
- let link_result = if src.is_dir() {
- #[cfg(target_os = "redox")]
- use std::os::redox::fs::symlink;
- #[cfg(unix)]
- use std::os::unix::fs::symlink;
- #[cfg(windows)]
- use std::os::windows::fs::symlink_dir as symlink;
-
- let dst_dir = dst.parent().unwrap();
- let src = if src.starts_with(dst_dir) {
- src.strip_prefix(dst_dir).unwrap()
- } else {
- src
- };
- symlink(src, dst)
- } else {
- fs::hard_link(src, dst)
- };
- link_result
- .or_else(|err| {
- debug!("link failed {}. falling back to fs::copy", err);
- fs::copy(src, dst).map(|_| ())
- })
- .chain_err(|| {
- format!(
- "failed to link or copy `{}` to `{}`",
- src.display(),
- dst.display()
- )
- })?;
- Ok(())
-}
-
 // For all plugin dependencies, add their -L paths (now calculated and present
 // in `build_script_outputs`) to the dynamic library load path for the command
 // to execute.