Rollup merge of #136924 - Kobzol:bootstrap-tracing, r=jieyouxu

Add profiling of bootstrap commands using Chrome events

Since we now have support for tracing in bootstrap, and the execution of most commands is centralized within a few functions, it's quite trivial to also trace command execution, and visualize it using the Chrome profiler. This can be helpful both to profile what takes time in bootstrap and also to get a visual idea of what happens in a given bootstrap invocation (since the execution of external commands is usually the most interesting thing).

This is how it looks:
![image](https://github.com/user-attachments/assets/3351489e-3a0f-4729-9082-5bf40c586d4b)

I first tried to use [tracing-flame](https://github.com/tokio-rs/tracing/tree/master/tracing-flame), but the output wasn't very useful, because the event/stackframe names were bootstrap code locations, instead of the command contents.

r? ``@jieyouxu``

9 files changed, 84 insertions, 4 deletions

diff --git a/src/bootstrap/Cargo.lock b/src/bootstrap/Cargo.lock
index d2f3c7f36ca..a47f3af60cb 100644
--- a/src/bootstrap/Cargo.lock
+++ b/src/bootstrap/Cargo.lock
@@ -59,6 +59,7 @@ dependencies = [
  "termcolor",
  "toml",
  "tracing",
+ "tracing-chrome",
  "tracing-subscriber",
  "tracing-tree",
  "walkdir",
@@ -728,6 +729,17 @@ dependencies = [
 ]
 
 [[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"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/src/bootstrap/Cargo.toml b/src/bootstrap/Cargo.toml
index d7afcc7f27d..ed51862390d 100644
--- a/src/bootstrap/Cargo.toml
+++ b/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 }
 
diff --git a/src/bootstrap/src/bin/main.rs b/src/bootstrap/src/bin/main.rs
index 441674936c6..38b380e3db8 100644
--- a/src/bootstrap/src/bin/main.rs
+++ b/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,7 +210,7 @@ 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;
 
@@ -218,7 +218,17 @@ fn setup_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
 }
diff --git a/src/bootstrap/src/core/build_steps/compile.rs b/src/bootstrap/src/core/build_steps/compile.rs
index a2375842bdd..8e5a8b7e254 100644
--- a/src/bootstrap/src/core/build_steps/compile.rs
+++ b/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.
diff --git a/src/bootstrap/src/lib.rs b/src/bootstrap/src/lib.rs
index 665ab117002..7cd8aacf0d6 100644
--- a/src/bootstrap/src/lib.rs
+++ b/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();
 
diff --git a/src/bootstrap/src/utils/exec.rs b/src/bootstrap/src/utils/exec.rs
index 1902dcd3962..7eb9ab96c8a 100644
--- a/src/bootstrap/src/utils/exec.rs
+++ b/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(" ")
+    }
+}
diff --git a/src/bootstrap/src/utils/helpers.rs b/src/bootstrap/src/utils/helpers.rs
index a1b1748c85b..3fee397da09 100644
--- a/src/bootstrap/src/utils/helpers.rs
+++ b/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}")),
diff --git a/src/bootstrap/src/utils/tracing.rs b/src/bootstrap/src/utils/tracing.rs
index e89decf9e55..99849341dc3 100644
--- a/src/bootstrap/src/utils/tracing.rs
+++ b/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()
+        }
+    };
+}
diff --git a/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md b/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md
index 3f907e85dd6..04fa5b204dd 100644
--- a/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap.md
+++ b/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>.