[WIP] Add timing messages

Author: bjorn3

build_system/build_backend.rs

@@ -38,6 +38,8 @@ pub(crate) fn build_backend(
     eprintln!("[BUILD] rustc_codegen_cranelift");
     crate::utils::spawn_and_wait(cmd);
 
+    super::time("Built backend");
+
     CG_CLIF
         .target_dir(dirs)
         .join(&bootstrap_host_compiler.triple)

build_system/build_sysroot.rs

@@ -29,6 +29,8 @@ pub(crate) fn build_sysroot(
     BIN_DIR.ensure_exists(dirs);
     LIB_DIR.ensure_exists(dirs);
 
+    super::time("  Ensured clean sysroot");
+
     let is_native = bootstrap_host_compiler.triple == target_triple;
 
     let cg_clif_dylib_path = match cg_clif_dylib_src {
@@ -49,6 +51,8 @@ pub(crate) fn build_sysroot(
         CodegenBackend::Builtin(name) => CodegenBackend::Builtin(name.clone()),
     };
 
+    super::time("  Copied backend");
+
     // Build and copy rustc and cargo wrappers
     let wrapper_base_name = get_file_name(&bootstrap_host_compiler.rustc, "____", "bin");
     for wrapper in ["rustc-clif", "rustdoc-clif", "cargo-clif"] {
@@ -79,8 +83,12 @@ pub(crate) fn build_sysroot(
         }
         spawn_and_wait(build_cargo_wrapper_cmd);
         try_hard_link(wrapper_path, BIN_DIR.to_path(dirs).join(wrapper_name));
+
+        super::time(&format!("    Built wrapper {wrapper}"));
     }
 
+    super::time("  Built wrappers");
+
     let host = build_sysroot_for_triple(
         dirs,
         bootstrap_host_compiler.clone(),
@@ -133,6 +141,9 @@ pub(crate) fn build_sysroot(
     if !is_native {
         target_compiler.set_cross_linker_and_runner();
     }
+
+    super::time("Built sysroot");
+
     target_compiler
 }
 

build_system/main.rs

@@ -1,8 +1,9 @@
 #![warn(rust_2018_idioms)]
 #![warn(unused_lifetimes)]
 #![warn(unreachable_pub)]
-
 use std::path::PathBuf;
+use std::sync::{Mutex, OnceLock};
+use std::time::{Duration, Instant};
 use std::{env, process};
 
 use self::utils::Compiler;
@@ -19,6 +20,18 @@ mod shared_utils;
 mod tests;
 mod utils;
 
+static STARTUP_TIME: OnceLock<Instant> = OnceLock::new();
+static PREVIOUS_STEP: Mutex<Option<Instant>> = Mutex::new(None);
+
+fn time(step: &str) {
+    let now = Instant::now();
+    let mut previous_step = PREVIOUS_STEP.lock().unwrap();
+    let delta =
+        previous_step.map(|previous_step| now - previous_step).unwrap_or(Duration::from_secs(0));
+    *previous_step = Some(now);
+    println!("{step:<30} @ {:?} (+ {:?})", now - *STARTUP_TIME.get().unwrap(), delta);
+}
+
 fn usage() {
     eprintln!("{}", include_str!("usage.txt"));
 }
@@ -54,6 +67,8 @@ enum CodegenBackend {
 }
 
 fn main() {
+    STARTUP_TIME.set(Instant::now()).unwrap();
+
     if env::var_os("RUST_BACKTRACE").is_none() {
         env::set_var("RUST_BACKTRACE", "1");
     }
@@ -199,6 +214,8 @@ fn main() {
     env::set_var("RUSTC", "rustc_should_be_set_explicitly");
     env::set_var("RUSTDOC", "rustdoc_should_be_set_explicitly");
 
+    time("Inited");
+
     let cg_clif_dylib = if let Some(name) = use_backend {
         CodegenBackend::Builtin(name)
     } else {

build_system/tests.rs

@@ -270,6 +270,7 @@ pub(crate) fn run_tests(
 
         BUILD_EXAMPLE_OUT_DIR.ensure_fresh(dirs);
         runner.run_testsuite(NO_SYSROOT_SUITE);
+        super::time("Ran testsuite no_sysroot");
     } else {
         eprintln!("[SKIP] no_sysroot tests");
     }
@@ -300,6 +301,7 @@ pub(crate) fn run_tests(
 
         if run_base_sysroot {
             runner.run_testsuite(BASE_SYSROOT_SUITE);
+            super::time("Ran testsuite base_sysroot");
         } else {
             eprintln!("[SKIP] base_sysroot tests");
         }
@@ -309,6 +311,7 @@ pub(crate) fn run_tests(
             // projects. Changing the code to fix them is not worth it, so just silence all lints.
             runner.target_compiler.rustflags.push("--cap-lints=allow".to_owned());
             runner.run_testsuite(EXTENDED_SYSROOT_SUITE);
+            super::time("Ran testsuite extended_sysroot");
         } else {
             eprintln!("[SKIP] extended_sysroot tests");
         }
@@ -415,6 +418,8 @@ impl<'a> TestRunner<'a> {
                     spawn_and_wait(jit_cmd);
                 }
             }
+
+            super::time(&format!("  Ran test {config}"));
         }
     }