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

3 files changed, 75 insertions, 22 deletions

diff --git a/src/bootstrap/bin/rustc.rs b/src/bootstrap/bin/rustc.rs
index 4be16475590..6701f58ba8e 100644
--- a/src/bootstrap/bin/rustc.rs
+++ b/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())
 }
diff --git a/src/bootstrap/builder.rs b/src/bootstrap/builder.rs
index 675d3dd437e..3fd50f17ef3 100644
--- a/src/bootstrap/builder.rs
+++ b/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");
diff --git a/src/bootstrap/config.rs b/src/bootstrap/config.rs
index 920a8ffc2fc..3ef4b0f8ae7 100644
--- a/src/bootstrap/config.rs
+++ b/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 {