From 1b5eb17d61f1651d6b9d412a5be586dfb80fd447 Mon Sep 17 00:00:00 2001 From: Alex Crichton Date: Fri, 16 Mar 2018 12:10:47 -0700 Subject: [PATCH] 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 --- config.toml.example | 4 +++ src/bootstrap/bin/rustc.rs | 65 ++++++++++++++++++++++++++------------ src/bootstrap/builder.rs | 29 +++++++++++++++-- src/bootstrap/config.rs | 3 ++ src/ci/run.sh | 2 ++ 5 files changed, 81 insertions(+), 22 deletions(-) diff --git a/config.toml.example b/config.toml.example index aec5e5a0e2c..e92807d5aaa 100644 --- a/config.toml.example +++ b/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 # ============================================================================= 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::>(); @@ -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 { +fn exec_cmd(cmd: &mut Command) -> io::Result { use std::os::unix::process::CommandExt; Err(cmd.exec()) } #[cfg(not(unix))] -fn exec_cmd(cmd: &mut Command) -> ::std::io::Result { - cmd.status() +fn exec_cmd(cmd: &mut Command) -> io::Result { + 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>>, + time_spent_on_dependencies: Cell, } 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, + pub print_step_timings: bool, // Fallback musl-root for all targets pub musl_root: Option, @@ -204,6 +205,7 @@ struct Build { openssl_static: Option, configure_args: Option>, local_rebuild: Option, + print_step_timings: Option, } /// 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 { diff --git a/src/ci/run.sh b/src/ci/run.sh index e3f38e4834a..9a26043c92c 100755 --- a/src/ci/run.sh +++ b/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"