ci: Print out how long each step takes on CI

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"