Rollup merge of rust-lang#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`

Author: workingjubilee

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>.