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

Improve tracing in bootstrap

I was annoyed that bootstrap had like 5 separate ways of debugging/tracing/profiling, and it was hard for me to understand how are individual steps executed. This PR tries to unify severla things behind `BOOTSTRAP_TRACING`, and improve tracing/profiling in general:
- All generated tracing outputs are now stored in a single directory to make it easier to examine them, plus bootstrap prepares a `latest` symlink to the latest generated tracing output directory for convenience.
- All executed spans are now logged automatically (without requiring usage of `#[tracing::instrument]`).
- A custom span/event formatter was implemented, to provide domain-specific output (like location of executed commands or spans) and hopefully also to reduce visual clutter.
  - `tracing_forest` was removed. While it did some useful postprocessing, it didn't expose enough information for making the dynamic step spans work.
- You can now explicitly log steps (`STEP=info`) and/or commands (`COMMAND=info`), to have more granular control over what gets logged.
- `print-step-timings` also show when a step starts its execution (not just when it ends it), so that when some step fails in CI, we can actually see what step it was (before we would only see the end of the previous step).
- The rustc-dev-guide page on debugging/profiling bootstrap was updated.

There are still some things that work outside of tracing (`print-step-timings` and `dump-bootstrap-shims`), but I think that for now this improvement is good enough.

I removed the `> step`, `< step` verbose output, because I found it unusable, as verbose bootstrap output also enables verbose Cargo output, and then you simply drown in too much data, and because I think that the new tracing system makes it obsolete (although it does require recompilation with the `tracing` feature). If you want to keep it, happy to revert 690c781. And the information about cached steps is now also shown in the Graphviz step dependency graph.

We can modify the tracing output however we want, as we now implement it ourselves. Notably, we could also show exit logs for step spans, currently I only show enter spans. Maybe creating indents for each executed nested command is also not needed. Happy to hear feedback!

Some further improvements could be to print step durations, if we decide to also log step exit events. We could also try to enable tracing in CI logs, but it might be too verbose.

Best reviewed commit-by-commit.

r? `@jieyouxu`

CC `@Shourya742`

Author: Zalathar

src/bootstrap/Cargo.lock

@@ -11,21 +11,18 @@ dependencies = [
  "memchr",
 ]
 
-[[package]]
-name = "ansi_term"
-version = "0.12.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2"
-dependencies = [
- "winapi",
-]
-
 [[package]]
 name = "anstyle"
 version = "1.0.10"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "55cc3b69f167a1ef2e161439aa98aed94e6028e5f9a59be9a6ffb47aef1651f9"
 
+[[package]]
+name = "autocfg"
+version = "1.5.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c08606f8c3cbf4ce6ec8e28fb0014a2c086708fe954eaa885384a6165172e7e8"
+
 [[package]]
 name = "bitflags"
 version = "2.6.0"
@@ -47,6 +44,7 @@ version = "0.0.0"
 dependencies = [
  "build_helper",
  "cc",
+ "chrono",
  "clap",
  "clap_complete",
  "cmake",
@@ -71,7 +69,6 @@ dependencies = [
  "toml",
  "tracing",
  "tracing-chrome",
- "tracing-forest",
  "tracing-subscriber",
  "walkdir",
  "windows",
@@ -112,6 +109,15 @@ version = "1.0.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
 
+[[package]]
+name = "chrono"
+version = "0.4.41"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c469d952047f47f91b68d1cba3f10d63c11d73e4636f24f08daf0278abf01c4d"
+dependencies = [
+ "num-traits",
+]
+
 [[package]]
 name = "clap"
 version = "4.5.20"
@@ -458,6 +464,15 @@ dependencies = [
  "winapi",
 ]
 
+[[package]]
+name = "num-traits"
+version = "0.2.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "071dfc062690e90b734c0b2273ce72ad0ffa95f0c74596bc250dcfd960262841"
+dependencies = [
+ "autocfg",
+]
+
 [[package]]
 name = "objc2-core-foundation"
 version = "0.3.1"
@@ -775,26 +790,6 @@ dependencies = [
  "winapi-util",
 ]
 
-[[package]]
-name = "thiserror"
-version = "1.0.69"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "b6aaf5339b578ea85b50e080feb250a3e8ae8cfcdff9a461c9ec2904bc923f52"
-dependencies = [
- "thiserror-impl",
-]
-
-[[package]]
-name = "thiserror-impl"
-version = "1.0.69"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "4fee6c4efc90059e10f81e6d42c60a18f76588c3d74cb83a0b242a2b6c7504c1"
-dependencies = [
- "proc-macro2",
- "quote",
- "syn",
-]
-
 [[package]]
 name = "thread_local"
 version = "1.1.8"
@@ -857,19 +852,6 @@ dependencies = [
  "valuable",
 ]
 
-[[package]]
-name = "tracing-forest"
-version = "0.1.6"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "ee40835db14ddd1e3ba414292272eddde9dad04d3d4b65509656414d1c42592f"
-dependencies = [
- "ansi_term",
- "smallvec",
- "thiserror",
- "tracing",
- "tracing-subscriber",
-]
-
 [[package]]
 name = "tracing-log"
 version = "0.2.0"

src/bootstrap/Cargo.toml

@@ -7,7 +7,7 @@ default-run = "bootstrap"
 
 [features]
 build-metrics = ["sysinfo"]
-tracing = ["dep:tracing", "dep:tracing-chrome", "dep:tracing-subscriber", "dep:tracing-forest"]
+tracing = ["dep:tracing", "dep:tracing-chrome", "dep:tracing-subscriber", "dep:chrono", "dep:tempfile"]
 
 [lib]
 path = "src/lib.rs"
@@ -61,10 +61,11 @@ xz2 = "0.1"
 sysinfo = { version = "0.37.0", default-features = false, optional = true, features = ["system"] }
 
 # Dependencies needed by the `tracing` feature
+chrono = { version = "0.4", default-features = false, optional = true, features = ["now", "std"] }
 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-forest = { version = "0.1.6", optional = true, default-features =  false, features = ["smallvec", "ansi", "env-filter"] }
+tempfile = { version = "3.15.0", optional = true }
 
 [target.'cfg(windows)'.dependencies.junction]
 version = "1.0.0"

src/bootstrap/src/bin/main.rs

@@ -7,6 +7,7 @@
 
 use std::fs::{self, OpenOptions};
 use std::io::{self, BufRead, BufReader, IsTerminal, Write};
+use std::path::Path;
 use std::str::FromStr;
 use std::time::Instant;
 use std::{env, process};
@@ -15,19 +16,16 @@ use bootstrap::{
     Build, CONFIG_CHANGE_HISTORY, ChangeId, Config, Flags, Subcommand, debug,
     find_recent_config_change_ids, human_readable_changes, t,
 };
-#[cfg(feature = "tracing")]
-use tracing::instrument;
 
-fn is_bootstrap_profiling_enabled() -> bool {
-    env::var("BOOTSTRAP_PROFILE").is_ok_and(|v| v == "1")
+fn is_tracing_enabled() -> bool {
+    cfg!(feature = "tracing")
 }
 
-#[cfg_attr(feature = "tracing", instrument(level = "trace", name = "main"))]
 fn main() {
     #[cfg(feature = "tracing")]
-    let _guard = setup_tracing();
+    let guard = bootstrap::setup_tracing("BOOTSTRAP_TRACING");
 
-    let start_time = Instant::now();
+    let _start_time = Instant::now();
 
     let args = env::args().skip(1).collect::<Vec<_>>();
 
@@ -102,6 +100,35 @@ fn main() {
     let dump_bootstrap_shims = config.dump_bootstrap_shims;
     let out_dir = config.out.clone();
 
+    let tracing_enabled = is_tracing_enabled();
+
+    // Prepare a directory for tracing output
+    // Also store a symlink named "latest" to point to the latest tracing directory.
+    let tracing_dir = out_dir.join("bootstrap-trace").join(std::process::id().to_string());
+    let latest_trace_dir = tracing_dir.parent().unwrap().join("latest");
+    if tracing_enabled {
+        let _ = std::fs::remove_dir_all(&tracing_dir);
+        std::fs::create_dir_all(&tracing_dir).unwrap();
+
+        #[cfg(windows)]
+        let _ = std::fs::remove_dir(&latest_trace_dir);
+        #[cfg(not(windows))]
+        let _ = std::fs::remove_file(&latest_trace_dir);
+
+        #[cfg(not(windows))]
+        fn symlink_dir_inner(original: &Path, link: &Path) -> io::Result<()> {
+            use std::os::unix::fs;
+            fs::symlink(original, link)
+        }
+
+        #[cfg(windows)]
+        fn symlink_dir_inner(target: &Path, junction: &Path) -> io::Result<()> {
+            junction::create(target, junction)
+        }
+
+        t!(symlink_dir_inner(&tracing_dir, &latest_trace_dir));
+    }
+
     debug!("creating new build based on config");
     let mut build = Build::new(config);
     build.build();
@@ -156,12 +183,13 @@ fn main() {
         }
     }
 
-    if is_bootstrap_profiling_enabled() {
-        build.report_summary(start_time);
-    }
-
     #[cfg(feature = "tracing")]
-    build.report_step_graph();
+    {
+        build.report_summary(&tracing_dir.join("command-stats.txt"), _start_time);
+        build.report_step_graph(&tracing_dir);
+        guard.copy_to_dir(&tracing_dir);
+        eprintln!("Tracing/profiling output has been written to {}", latest_trace_dir.display());
+    }
 }
 
 fn check_version(config: &Config) -> Option<String> {
@@ -219,37 +247,3 @@ fn check_version(config: &Config) -> Option<String> {
 
     Some(msg)
 }
-
-// # Note on `tracing` usage in bootstrap
-//
-// Due to the conditional compilation via the `tracing` cargo feature, this means that `tracing`
-// usages in bootstrap need to be also gated behind the `tracing` feature:
-//
-// - `tracing` macros with log levels (`trace!`, `debug!`, `warn!`, `info`, `error`) should not be
-//   used *directly*. You should use the wrapped `tracing` macros which gate the actual invocations
-//   behind `feature = "tracing"`.
-// - `tracing`'s `#[instrument(..)]` macro will need to be gated like `#![cfg_attr(feature =
-//   "tracing", instrument(..))]`.
-#[cfg(feature = "tracing")]
-fn setup_tracing() -> impl Drop {
-    use tracing_forest::ForestLayer;
-    use tracing_subscriber::EnvFilter;
-    use tracing_subscriber::layer::SubscriberExt;
-
-    let filter = EnvFilter::from_env("BOOTSTRAP_TRACING");
-
-    let mut chrome_layer = tracing_chrome::ChromeLayerBuilder::new().include_args(true);
-
-    // Writes the Chrome profile to trace-<unix-timestamp>.json if enabled
-    if !is_bootstrap_profiling_enabled() {
-        chrome_layer = chrome_layer.writer(io::sink());
-    }
-
-    let (chrome_layer, _guard) = chrome_layer.build();
-
-    let registry =
-        tracing_subscriber::registry().with(filter).with(ForestLayer::default()).with(chrome_layer);
-
-    tracing::subscriber::set_global_default(registry).unwrap();
-    _guard
-}