Auto merge of #7311 - ehuss:pipeline-timing, r=alexcrichton

Experiment: Create timing report.

This is just an experiment, so I'm not sure if we'll want to merge it.

This adds an HTML report which gets saved to disk when the build is finished.  It is primarily geared for identifying slow dependencies, and for visualizing how pipelining affects the build.

Here's an example: https://ehuss.github.io/cargo-timing.html
You can mouse over the blocks to highlight the reverse-dependencies that are released when a unit finishes.  `syn` is a really good example.

It does a few other things, like displaying a message after each unit is finished.  See the docs for more information.

Author: bors

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)?;
@@ -523,6 +523,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

@@ -16,6 +16,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;
@@ -41,6 +42,7 @@ pub struct JobQueue<'a, 'cfg> {
     is_release: bool,
     progress: Progress<'cfg>,
     next_id: u32,
+    timings: Timings<'a, 'cfg>,
 }
 
 pub struct JobState<'a> {
@@ -82,7 +84,7 @@ enum Artifact {
 }
 
 enum Message {
-    Run(String),
+    Run(u32, String),
     BuildPlanMsg(String, ProcessBuilder, Arc<Vec<OutputFile>>),
     Stdout(String),
     Stderr(String),
@@ -93,7 +95,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(
@@ -121,7 +123,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
@@ -130,9 +131,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,
@@ -144,6 +146,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
             is_release: bcx.build_config.release,
             progress,
             next_id: 0,
+            timings,
         }
     }
 
@@ -318,6 +321,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();
@@ -330,18 +336,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();
@@ -369,7 +375,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)?;
@@ -427,6 +433,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);
@@ -542,8 +549,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());
             }
         }
@@ -581,14 +592,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.