Add profiling of bootstrap commands using Chrome events

src/bootstrap/Cargo.lock

@@ -59,6 +59,7 @@ dependencies = [
  "termcolor",
  "toml",
  "tracing",
+ "tracing-chrome",
  "tracing-subscriber",
  "tracing-tree",
  "walkdir",
@@ -727,6 +728,17 @@ dependencies = [
  "syn",
 ]
 
+[[package]]
+name = "tracing-chrome"
+version = "0.7.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bf0a738ed5d6450a9fb96e86a23ad808de2b727fd1394585da5cdd6788ffe724"
+dependencies = [
+ "serde_json",
+ "tracing-core",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.33"

src/bootstrap/Cargo.toml

@@ -7,7 +7,7 @@ default-run = "bootstrap"
 
 [features]
 build-metrics = ["sysinfo"]
-tracing = ["dep:tracing", "dep:tracing-subscriber", "dep:tracing-tree"]
+tracing = ["dep:tracing", "dep:tracing-chrome", "dep:tracing-subscriber", "dep:tracing-tree"]
 
 [lib]
 path = "src/lib.rs"
@@ -67,6 +67,7 @@ sysinfo = { version = "0.33.0", default-features = false, optional = true, featu
 
 # Dependencies needed by the `tracing` feature
 tracing = { version = "0.1", optional = true, features = ["attributes"] }
+tracing-chrome = { version = "0.7", optional = true }
 tracing-subscriber = { version = "0.3", optional = true, features = ["env-filter", "fmt", "registry", "std"] }
 tracing-tree = { version = "0.4.0", optional = true }
 

src/bootstrap/src/bin/main.rs

@@ -21,7 +21,7 @@ use tracing::instrument;
 #[cfg_attr(feature = "tracing", instrument(level = "trace", name = "main"))]
 fn main() {
     #[cfg(feature = "tracing")]
-    setup_tracing();
+    let _guard = setup_tracing();
 
     let args = env::args().skip(1).collect::<Vec<_>>();
 
@@ -210,15 +210,25 @@ fn check_version(config: &Config) -> Option<String> {
 // - `tracing`'s `#[instrument(..)]` macro will need to be gated like `#![cfg_attr(feature =
 //   "tracing", instrument(..))]`.
 #[cfg(feature = "tracing")]
-fn setup_tracing() {
+fn setup_tracing() -> impl Drop {
     use tracing_subscriber::EnvFilter;
     use tracing_subscriber::layer::SubscriberExt;
 
     let filter = EnvFilter::from_env("BOOTSTRAP_TRACING");
     // cf. <https://docs.rs/tracing-tree/latest/tracing_tree/struct.HierarchicalLayer.html>.
     let layer = tracing_tree::HierarchicalLayer::default().with_targets(true).with_indent_amount(2);
 
-    let registry = tracing_subscriber::registry().with(filter).with(layer);
+    let mut chrome_layer = tracing_chrome::ChromeLayerBuilder::new().include_args(true);
+
+    // Writes the Chrome profile to trace-<unix-timestamp>.json if enabled
+    if !env::var("BOOTSTRAP_PROFILE").is_ok_and(|v| v == "1") {
+        chrome_layer = chrome_layer.writer(io::sink());
+    }
+
+    let (chrome_layer, _guard) = chrome_layer.build();
+
+    let registry = tracing_subscriber::registry().with(filter).with(layer).with(chrome_layer);
 
     tracing::subscriber::set_global_default(registry).unwrap();
+    _guard
 }

src/bootstrap/src/core/build_steps/compile.rs

@@ -2234,6 +2234,10 @@ pub fn stream_cargo(
     cb: &mut dyn FnMut(CargoMessage<'_>),
 ) -> bool {
     let mut cmd = cargo.into_cmd();
+
+    #[cfg(feature = "tracing")]
+    let _run_span = crate::trace_cmd!(cmd);
+
     let cargo = cmd.as_command_mut();
     // Instruct Cargo to give us json messages on stdout, critically leaving
     // stderr as piped so we can get those pretty colors.

src/bootstrap/src/lib.rs

@@ -905,6 +905,9 @@ impl Build {
             return CommandOutput::default();
         }
 
+        #[cfg(feature = "tracing")]
+        let _run_span = trace_cmd!(command);
+
         let created_at = command.get_created_location();
         let executed_at = std::panic::Location::caller();
 

src/bootstrap/src/utils/exec.rs

@@ -329,3 +329,25 @@ impl Default for CommandOutput {
         }
     }
 }
+
+/// Helper trait to format both Command and BootstrapCommand as a short execution line,
+/// without all the other details (e.g. environment variables).
+#[allow(unused)]
+pub trait FormatShortCmd {
+    fn format_short_cmd(&self) -> String;
+}
+
+impl FormatShortCmd for BootstrapCommand {
+    fn format_short_cmd(&self) -> String {
+        self.command.format_short_cmd()
+    }
+}
+
+impl FormatShortCmd for Command {
+    fn format_short_cmd(&self) -> String {
+        let program = Path::new(self.get_program());
+        let mut line = vec![program.file_name().unwrap().to_str().unwrap()];
+        line.extend(self.get_args().map(|arg| arg.to_str().unwrap()));
+        line.join(" ")
+    }
+}

src/bootstrap/src/utils/helpers.rs

@@ -265,6 +265,9 @@ pub fn make(host: &str) -> PathBuf {
 
 #[track_caller]
 pub fn output(cmd: &mut Command) -> String {
+    #[cfg(feature = "tracing")]
+    let _run_span = crate::trace_cmd!(cmd);
+
     let output = match cmd.stderr(Stdio::inherit()).output() {
         Ok(status) => status,
         Err(e) => fail(&format!("failed to execute command: {cmd:?}\nERROR: {e}")),

src/bootstrap/src/utils/tracing.rs

@@ -47,3 +47,20 @@ macro_rules! error {
         ::tracing::error!($($tokens)*)
     }
 }
+
+#[macro_export]
+macro_rules! trace_cmd {
+    ($cmd:expr) => {
+        {
+            use $crate::utils::exec::FormatShortCmd;
+
+            ::tracing::span!(
+                target: "COMMAND",
+                ::tracing::Level::TRACE,
+                "executing command",
+                cmd = $cmd.format_short_cmd(),
+                full_cmd = ?$cmd
+            ).entered()
+        }
+    };
+}

src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md

@@ -121,6 +121,14 @@ For `#[instrument]`, it's recommended to:
 - Explicitly pick an instrumentation name via `name = ".."` to distinguish between e.g. `run` of different steps.
 - Take care to not cause diverging behavior via tracing, e.g. building extra things only when tracing infra is enabled.
 
+### Profiling bootstrap
+
+You can use the `COMMAND` tracing target to trace execution of most commands spawned by bootstrap. If you also use the `BOOTSTRAP_PROFILE=1` environment variable, bootstrap will generate a Chrome JSON trace file, which can be visualized in Chrome's `chrome://tracing` page or on https://ui.perfetto.dev.
+
+```bash
+$ BOOTSTRAP_TRACING=COMMAND=trace BOOTSTRAP_PROFILE=1 ./x build library
+```
+
 ### rust-analyzer integration?
 
 Unfortunately, because bootstrap is a `rust-analyzer.linkedProjects`, you can't ask r-a to check/build bootstrap itself with `tracing` feature enabled to get relevant completions, due to lack of support as described in <https://github.com/rust-lang/rust-analyzer/issues/8521>.