ci: Print out how long each step takes on CI

This commit updates CI configuration to inform rustbuild that it should print
out how long each step takes on CI. This'll hopefully allow us to track the
duration of steps over time and follow regressions a bit more closesly (as well
as have closer analysis of differences between two builds).

cc #48829

Author: alexcrichton

config.toml.example

@@ -186,6 +186,10 @@
 # essentially skipping stage0 as the local compiler is recompiling itself again.
 #local-rebuild = false
 
+# Print out how long each rustbuild step took (mostly intended for CI and
+# tracking over time)
+#print-step-timings = false
+
 # =============================================================================
 # General install configuration options
 # =============================================================================

src/bootstrap/bin/rustc.rs

@@ -31,9 +31,11 @@ extern crate bootstrap;
 
 use std::env;
 use std::ffi::OsString;
-use std::str::FromStr;
+use std::io;
 use std::path::PathBuf;
-use std::process::{Command, ExitStatus};
+use std::process::Command;
+use std::str::FromStr;
+use std::time::Instant;
 
 fn main() {
     let mut args = env::args_os().skip(1).collect::<Vec<_>>();
@@ -90,7 +92,7 @@ fn main() {
     };
     let stage = env::var("RUSTC_STAGE").expect("RUSTC_STAGE was not set");
     let sysroot = env::var_os("RUSTC_SYSROOT").expect("RUSTC_SYSROOT was not set");
-    let mut on_fail = env::var_os("RUSTC_ON_FAIL").map(|of| Command::new(of));
+    let on_fail = env::var_os("RUSTC_ON_FAIL").map(|of| Command::new(of));
 
     let rustc = env::var_os(rustc).unwrap_or_else(|| panic!("{:?} was not set", rustc));
     let libdir = env::var_os(libdir).unwrap_or_else(|| panic!("{:?} was not set", libdir));
@@ -103,6 +105,7 @@ fn main() {
         .arg(format!("stage{}", stage))
         .env(bootstrap::util::dylib_path_var(),
              env::join_paths(&dylib_path).unwrap());
+    let mut maybe_crate = None;
 
     if let Some(target) = target {
         // The stage0 compiler has a special sysroot distinct from what we
@@ -134,6 +137,7 @@ fn main() {
             .find(|a| &*a[0] == "--crate-name")
             .unwrap();
         let crate_name = &*crate_name[1];
+        maybe_crate = Some(crate_name);
 
         // If we're compiling specifically the `panic_abort` crate then we pass
         // the `-C panic=abort` option. Note that we do not do this for any
@@ -281,31 +285,52 @@ fn main() {
         eprintln!("libdir: {:?}", libdir);
     }
 
-    // Actually run the compiler!
-    std::process::exit(if let Some(ref mut on_fail) = on_fail {
-        match cmd.status() {
-            Ok(s) if s.success() => 0,
-            _ => {
-                println!("\nDid not run successfully:\n{:?}\n-------------", cmd);
-                exec_cmd(on_fail).expect("could not run the backup command");
-                1
+    if let Some(mut on_fail) = on_fail {
+        let e = match cmd.status() {
+            Ok(s) if s.success() => std::process::exit(0),
+            e => e,
+        };
+        println!("\nDid not run successfully: {:?}\n{:?}\n-------------", e, cmd);
+        exec_cmd(&mut on_fail).expect("could not run the backup command");
+        std::process::exit(1);
+    }
+
+    if env::var_os("RUSTC_PRINT_STEP_TIMINGS").is_some() {
+        if let Some(krate) = maybe_crate {
+            let start = Instant::now();
+            let status = cmd
+                .status()
+                .expect(&format!("\n\n failed to run {:?}", cmd));
+            let dur = start.elapsed();
+
+            let is_test = args.iter().any(|a| a == "--test");
+            eprintln!("[RUSTC-TIMING] {} test:{} {}.{:03}",
+                      krate.to_string_lossy(),
+                      is_test,
+                      dur.as_secs(),
+                      dur.subsec_nanos() / 1_000_000);
+
+            match status.code() {
+                Some(i) => std::process::exit(i),
+                None => {
+                    eprintln!("rustc exited with {}", status);
+                    std::process::exit(0xfe);
+                }
             }
         }
-    } else {
-        std::process::exit(match exec_cmd(&mut cmd) {
-            Ok(s) => s.code().unwrap_or(0xfe),
-            Err(e) => panic!("\n\nfailed to run {:?}: {}\n\n", cmd, e),
-        })
-    })
+    }
+
+    let code = exec_cmd(&mut cmd).expect(&format!("\n\n failed to run {:?}", cmd));
+    std::process::exit(code);
 }
 
 #[cfg(unix)]
-fn exec_cmd(cmd: &mut Command) -> ::std::io::Result<ExitStatus> {
+fn exec_cmd(cmd: &mut Command) -> io::Result<i32> {
     use std::os::unix::process::CommandExt;
     Err(cmd.exec())
 }
 
 #[cfg(not(unix))]
-fn exec_cmd(cmd: &mut Command) -> ::std::io::Result<ExitStatus> {
-    cmd.status()
+fn exec_cmd(cmd: &mut Command) -> io::Result<i32> {
+    cmd.status().map(|status| status.code().unwrap())
 }

src/bootstrap/builder.rs

@@ -9,7 +9,7 @@
 // except according to those terms.
 
 use std::any::Any;
-use std::cell::RefCell;
+use std::cell::{Cell, RefCell};
 use std::collections::BTreeSet;
 use std::env;
 use std::fmt::Debug;
@@ -18,6 +18,7 @@ use std::hash::Hash;
 use std::ops::Deref;
 use std::path::{Path, PathBuf};
 use std::process::Command;
+use std::time::{Instant, Duration};
 
 use compile;
 use install;
@@ -40,6 +41,7 @@ pub struct Builder<'a> {
     pub kind: Kind,
     cache: Cache,
     stack: RefCell<Vec<Box<Any>>>,
+    time_spent_on_dependencies: Cell<Duration>,
 }
 
 impl<'a> Deref for Builder<'a> {
@@ -343,6 +345,7 @@ impl<'a> Builder<'a> {
             kind,
             cache: Cache::new(),
             stack: RefCell::new(Vec::new()),
+            time_spent_on_dependencies: Cell::new(Duration::new(0, 0)),
         };
 
         let builder = &builder;
@@ -383,6 +386,7 @@ impl<'a> Builder<'a> {
             kind,
             cache: Cache::new(),
             stack: RefCell::new(Vec::new()),
+            time_spent_on_dependencies: Cell::new(Duration::new(0, 0)),
         };
 
         if kind == Kind::Dist {
@@ -662,6 +666,10 @@ impl<'a> Builder<'a> {
             cargo.env("RUSTC_ON_FAIL", on_fail);
         }
 
+        if self.config.print_step_timings {
+            cargo.env("RUSTC_PRINT_STEP_TIMINGS", "1");
+        }
+
         cargo.env("RUSTC_VERBOSE", format!("{}", self.verbosity));
 
         // Throughout the build Cargo can execute a number of build scripts
@@ -818,7 +826,24 @@ impl<'a> Builder<'a> {
             self.build.verbose(&format!("{}> {:?}", "  ".repeat(stack.len()), step));
             stack.push(Box::new(step.clone()));
         }
-        let out = step.clone().run(self);
+
+        let (out, dur) = {
+            let start = Instant::now();
+            let zero = Duration::new(0, 0);
+            let parent = self.time_spent_on_dependencies.replace(zero);
+            let out = step.clone().run(self);
+            let dur = start.elapsed();
+            let deps = self.time_spent_on_dependencies.replace(parent + dur);
+            (out, dur - deps)
+        };
+
+        if self.build.config.print_step_timings && dur > Duration::from_millis(100) {
+            println!("[TIMING] {:?} -- {}.{:03}",
+                     step,
+                     dur.as_secs(),
+                     dur.subsec_nanos() / 1_000_000);
+        }
+
         {
             let mut stack = self.stack.borrow_mut();
             let cur_step = stack.pop().expect("step stack empty");

src/bootstrap/config.rs

@@ -121,6 +121,7 @@ pub struct Config {
     pub quiet_tests: bool,
     pub test_miri: bool,
     pub save_toolstates: Option<PathBuf>,
+    pub print_step_timings: bool,
 
     // Fallback musl-root for all targets
     pub musl_root: Option<PathBuf>,
@@ -204,6 +205,7 @@ struct Build {
     openssl_static: Option<bool>,
     configure_args: Option<Vec<String>>,
     local_rebuild: Option<bool>,
+    print_step_timings: Option<bool>,
 }
 
 /// TOML representation of various global install decisions.
@@ -413,6 +415,7 @@ impl Config {
         set(&mut config.openssl_static, build.openssl_static);
         set(&mut config.configure_args, build.configure_args);
         set(&mut config.local_rebuild, build.local_rebuild);
+        set(&mut config.print_step_timings, build.print_step_timings);
         config.verbose = cmp::max(config.verbose, flags.verbose);
 
         if let Some(ref install) = toml.install {

src/ci/run.sh

@@ -25,6 +25,8 @@ source "$ci_dir/shared.sh"
 
 if [ "$TRAVIS" == "true" ] && [ "$TRAVIS_BRANCH" != "auto" ]; then
     RUST_CONFIGURE_ARGS="$RUST_CONFIGURE_ARGS --enable-quiet-tests"
+else
+    RUST_CONFIGURE_ARGS="$RUST_CONFIGURE_ARGS --set build.print-step-timings"
 fi
 
 RUST_CONFIGURE_ARGS="$RUST_CONFIGURE_ARGS --enable-sccache"