Add some tracing to core bootstrap logic

src/bootstrap/src/bin/main.rs

@@ -16,11 +16,7 @@ use bootstrap::{
 };
 use build_helper::ci::CiEnv;
 #[cfg(feature = "tracing")]
-use tracing::*;
-#[cfg(feature = "tracing")]
-use tracing_subscriber::EnvFilter;
-#[cfg(feature = "tracing")]
-use tracing_subscriber::prelude::*;
+use tracing::{debug, instrument};
 
 #[cfg_attr(feature = "tracing", instrument(level = "trace", name = "main"))]
 fn main() {
@@ -33,7 +29,11 @@ fn main() {
         return;
     }
 
+    #[cfg(feature = "tracing")]
+    debug!("parsing flags");
     let flags = Flags::parse(&args);
+    #[cfg(feature = "tracing")]
+    debug!("parsing config based on flags");
     let config = Config::parse(flags);
 
     let mut build_lock;
@@ -95,6 +95,8 @@ fn main() {
     let dump_bootstrap_shims = config.dump_bootstrap_shims;
     let out_dir = config.out.clone();
 
+    #[cfg(feature = "tracing")]
+    debug!("creating new build based on config");
     Build::new(config).build();
 
     if suggest_setup {
@@ -211,16 +213,14 @@ fn check_version(config: &Config) -> Option<String> {
 //   "tracing", instrument(..))]`.
 #[cfg(feature = "tracing")]
 fn setup_tracing() {
+    use tracing_subscriber::EnvFilter;
+    use tracing_subscriber::layer::SubscriberExt;
+
     let filter = EnvFilter::from_env("BOOTSTRAP_TRACING");
-    let layer = tracing_tree::HierarchicalLayer::default()
-        .with_writer(std::io::stderr)
-        .with_ansi(true)
-        .with_targets(true)
-        .with_bracketed_fields(true)
-        .with_indent_amount(2)
-        .with_indent_lines(true);
-    let subscriber = tracing_subscriber::registry().with(filter).with(layer);
-
-    tracing::subscriber::set_global_default(subscriber).unwrap();
-    trace!("tracing subscriber setup");
+    // 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);
+
+    tracing::subscriber::set_global_default(registry).unwrap();
 }

src/bootstrap/src/core/config/config.rs

@@ -18,6 +18,8 @@ use build_helper::exit;
 use build_helper::git::{GitConfig, get_closest_merge_commit, output_result};
 use serde::{Deserialize, Deserializer};
 use serde_derive::Deserialize;
+#[cfg(feature = "tracing")]
+use tracing::{instrument, span};
 
 use crate::core::build_steps::compile::CODEGEN_BACKEND_PREFIX;
 use crate::core::build_steps::llvm;
@@ -1227,7 +1229,14 @@ define_config! {
 }
 
 impl Config {
+    #[cfg_attr(
+        feature = "tracing",
+        instrument(target = "CONFIG_HANDLING", level = "trace", name = "Config::default_opts")
+    )]
     pub fn default_opts() -> Config {
+        #[cfg(feature = "tracing")]
+        span!(target: "CONFIG_HANDLING", tracing::Level::TRACE, "constructing default config");
+
         Config {
             bypass_bootstrap_lock: false,
             llvm_optimize: true,
@@ -1311,10 +1320,23 @@ impl Config {
             })
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        instrument(target = "CONFIG_HANDLING", level = "trace", name = "Config::parse", skip_all)
+    )]
     pub fn parse(flags: Flags) -> Config {
         Self::parse_inner(flags, Self::get_toml)
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        instrument(
+            target = "CONFIG_HANDLING",
+            level = "trace",
+            name = "Config::parse_inner",
+            skip_all
+        )
+    )]
     pub(crate) fn parse_inner(
         mut flags: Flags,
         get_toml: impl Fn(&Path) -> Result<TomlConfig, toml::de::Error>,
@@ -1323,6 +1345,17 @@ impl Config {
 
         // Set flags.
         config.paths = std::mem::take(&mut flags.paths);
+
+        #[cfg(feature = "tracing")]
+        span!(
+            target: "CONFIG_HANDLING",
+            tracing::Level::TRACE,
+            "collecting paths and path exclusions",
+            "flags.paths" = ?flags.paths,
+            "flags.skip" = ?flags.skip,
+            "flags.exclude" = ?flags.exclude
+        );
+
         config.skip = flags
             .skip
             .into_iter()
@@ -1339,6 +1372,14 @@ impl Config {
             })
             .collect();
 
+        #[cfg(feature = "tracing")]
+        span!(
+            target: "CONFIG_HANDLING",
+            tracing::Level::TRACE,
+            "normalizing and combining `flag.skip`/`flag.exclude` paths",
+            "config.skip" = ?config.skip,
+        );
+
         config.include_default_paths = flags.include_default_paths;
         config.rustc_error_format = flags.rustc_error_format;
         config.json_output = flags.json_output;
@@ -1418,7 +1459,11 @@ impl Config {
 
         config.stage0_metadata = build_helper::stage0_parser::parse_stage0_file();
 
-        // Read from `--config`, then `RUST_BOOTSTRAP_CONFIG`, then `./config.toml`, then `config.toml` in the root directory.
+        // Find configuration file, with the following cascading fallback (first match wins):
+        // - `--config <path>`
+        // - `RUST_BOOTSTRAP_CONFIG`
+        // - `./config.toml`
+        // - `config.toml` in the root directory.
         let toml_path = flags
             .config
             .clone()

src/bootstrap/src/core/config/flags.rs

@@ -6,6 +6,8 @@
 use std::path::{Path, PathBuf};
 
 use clap::{CommandFactory, Parser, ValueEnum};
+#[cfg(feature = "tracing")]
+use tracing::instrument;
 
 use crate::core::build_steps::setup::Profile;
 use crate::core::builder::{Builder, Kind};
@@ -211,6 +213,10 @@ impl Flags {
         }
     }
 
+    #[cfg_attr(
+        feature = "tracing",
+        instrument(level = "trace", name = "Flags::parse", skip_all, fields(args = ?args))
+    )]
     pub fn parse(args: &[String]) -> Self {
         Flags::parse_from(normalize_args(args))
     }

src/bootstrap/src/lib.rs

@@ -28,6 +28,8 @@ use std::{env, fs, io, str};
 use build_helper::ci::gha;
 use build_helper::exit;
 use termcolor::{ColorChoice, StandardStream, WriteColor};
+#[cfg(feature = "tracing")]
+use tracing::{debug, instrument, span, trace};
 use utils::build_stamp::BuildStamp;
 use utils::channel::GitInfo;
 
@@ -537,14 +539,25 @@ impl Build {
     }
 
     /// Executes the entire build, as configured by the flags and configuration.
+    #[cfg_attr(feature = "tracing", instrument(level = "debug", name = "Build::build", skip_all))]
     pub fn build(&mut self) {
+        #[cfg(feature = "tracing")]
+        trace!("setting up job management");
         unsafe {
             crate::utils::job::setup(self);
         }
 
+        #[cfg(feature = "tracing")]
+        trace!("downloading rustfmt early");
+
         // Download rustfmt early so that it can be used in rust-analyzer configs.
         let _ = &builder::Builder::new(self).initial_rustfmt();
 
+        #[cfg(feature = "tracing")]
+        let hardcoded_span =
+            span!(tracing::Level::DEBUG, "handling hardcoded subcommands (Format, Suggest, Perf)")
+                .entered();
+
         // hardcoded subcommands
         match &self.config.cmd {
             Subcommand::Format { check, all } => {
@@ -561,25 +574,50 @@ impl Build {
             Subcommand::Perf { .. } => {
                 return core::build_steps::perf::perf(&builder::Builder::new(self));
             }
-            _ => (),
+            _cmd => {
+                #[cfg(feature = "tracing")]
+                debug!(cmd = ?_cmd, "not a hardcoded subcommand; returning to normal handling");
+            }
         }
 
+        #[cfg(feature = "tracing")]
+        drop(hardcoded_span);
+        #[cfg(feature = "tracing")]
+        debug!("handling subcommand normally");
+
         if !self.config.dry_run() {
+            #[cfg(feature = "tracing")]
+            let _real_run_span = span!(tracing::Level::DEBUG, "executing real run").entered();
+
             {
+                #[cfg(feature = "tracing")]
+                let _sanity_check_span =
+                    span!(tracing::Level::DEBUG, "(1) executing dry-run sanity-check").entered();
+
                 // We first do a dry-run. This is a sanity-check to ensure that
                 // steps don't do anything expensive in the dry-run.
                 self.config.dry_run = DryRun::SelfCheck;
                 let builder = builder::Builder::new(self);
                 builder.execute_cli();
             }
+
+            #[cfg(feature = "tracing")]
+            let _actual_run_span =
+                span!(tracing::Level::DEBUG, "(2) executing actual run").entered();
             self.config.dry_run = DryRun::Disabled;
             let builder = builder::Builder::new(self);
             builder.execute_cli();
         } else {
+            #[cfg(feature = "tracing")]
+            let _dry_run_span = span!(tracing::Level::DEBUG, "executing dry run").entered();
+
             let builder = builder::Builder::new(self);
             builder.execute_cli();
         }
 
+        #[cfg(feature = "tracing")]
+        debug!("checking for postponed test failures from `test  --no-fail-fast`");
+
         // Check for postponed failures from `test --no-fail-fast`.
         let failures = self.delayed_failures.borrow();
         if failures.len() > 0 {

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

@@ -1,6 +1,6 @@
 # Debugging bootstrap
 
-> FIXME: this page could be expanded 
+> FIXME: this section should be expanded
 
 ## `tracing` in bootstrap
 
@@ -10,21 +10,69 @@ Bootstrap has conditional [`tracing`][tracing] setup to provide structured loggi
 
 ### Enabling `tracing` output
 
-Bootstrap will conditionally enable `tracing` output if the `BOOTSTRAP_TRACING` env var is set.
+Bootstrap will conditionally build `tracing` support and enable `tracing` output if the `BOOTSTRAP_TRACING` env var is set.
 
-Example usage:
+#### Basic usage
+
+Example basic usage[^just-trace]:
+
+[^just-trace]: It is not recommend to use *just* `BOOTSTRAP_TRACING=TRACE` because that will dump *everything* at `TRACE` level, including logs intentionally gated behind custom targets as they are too verbose even for `TRACE` level by default.
 
 ```bash
-$ BOOTSTRAP_TRACING=TRACE ./x build library --stage 1
+$ BOOTSTRAP_TRACING=bootstrap=TRACE ./x build library --stage 1
+```
+
+Example output[^unstable]:
+
+```
+$ BOOTSTRAP_TRACING=bootstrap=TRACE ./x check src/bootstrap/
+Building bootstrap
+   Compiling bootstrap v0.0.0 (/home/joe/repos/rust/src/bootstrap)
+    Finished `dev` profile [unoptimized] target(s) in 2.74s
+ DEBUG bootstrap parsing flags
+ bootstrap::core::config::flags::Flags::parse args=["check", "src/bootstrap/"]
+ DEBUG bootstrap parsing config based on flags
+ DEBUG bootstrap creating new build based on config
+ bootstrap::Build::build
+  TRACE bootstrap setting up job management
+  TRACE bootstrap downloading rustfmt early
+   bootstrap::handling hardcoded subcommands (Format, Suggest, Perf)
+    DEBUG bootstrap not a hardcoded subcommand; returning to normal handling, cmd=Check { all_targets: false }
+  DEBUG bootstrap handling subcommand normally
+   bootstrap::executing real run
+     bootstrap::(1) executing dry-run sanity-check
+     bootstrap::(2) executing actual run
+Checking stage0 library artifacts (x86_64-unknown-linux-gnu)
+    Finished `release` profile [optimized + debuginfo] target(s) in 0.04s
+Checking stage0 compiler artifacts {rustc-main, rustc_abi, rustc_arena, rustc_ast, rustc_ast_ir, rustc_ast_lowering, rustc_ast_passes, rustc_ast_pretty, rustc_attr_data_structures, rustc_attr_parsing, rustc_baked_icu_data, rustc_borrowck, rustc_builtin_macros, rustc_codegen_llvm, rustc_codegen_ssa, rustc_const_eval, rustc_data_structures, rustc_driver, rustc_driver_impl, rustc_error_codes, rustc_error_messages, rustc_errors, rustc_expand, rustc_feature, rustc_fluent_macro, rustc_fs_util, rustc_graphviz, rustc_hir, rustc_hir_analysis, rustc_hir_pretty, rustc_hir_typeck, rustc_incremental, rustc_index, rustc_index_macros, rustc_infer, rustc_interface, rustc_lexer, rustc_lint, rustc_lint_defs, rustc_llvm, rustc_log, rustc_macros, rustc_metadata, rustc_middle, rustc_mir_build, rustc_mir_dataflow, rustc_mir_transform, rustc_monomorphize, rustc_next_trait_solver, rustc_parse, rustc_parse_format, rustc_passes, rustc_pattern_analysis, rustc_privacy, rustc_query_impl, rustc_query_system, rustc_resolve, rustc_sanitizers, rustc_serialize, rustc_session, rustc_smir, rustc_span, rustc_symbol_mangling, rustc_target, rustc_trait_selection, rustc_traits, rustc_transmute, rustc_ty_utils, rustc_type_ir, rustc_type_ir_macros, stable_mir} (x86_64-unknown-linux-gnu)
+    Finished `release` profile [optimized + debuginfo] target(s) in 0.23s
+Checking stage0 bootstrap artifacts (x86_64-unknown-linux-gnu)
+    Checking bootstrap v0.0.0 (/home/joe/repos/rust/src/bootstrap)
+    Finished `release` profile [optimized + debuginfo] target(s) in 0.64s
+  DEBUG bootstrap checking for postponed test failures from `test  --no-fail-fast`
+Build completed successfully in 0:00:08
 ```
 
-Example output[^experimental]:
+#### Controlling log output
+
+The env var `BOOTSTRAP_TRACING` accepts a [`tracing` env-filter][tracing-env-filter].
+
+There are two orthogonal ways to control which kind of logs you want:
 
-![Example bootstrap tracing output](./debugging-bootstrap/tracing-output-example.png)
+1. You can specify the log **level**, e.g. `DEBUG` or `TRACE`.
+2. You can also control the log **target**, e.g. `bootstrap` or `bootstrap::core::config` vs custom targets like `CONFIG_HANDLING`.
+    - Custom targets are used to limit what is output when `BOOTSTRAP_TRACING=bootstrap=TRACE` is used, as they can be too verbose even for `TRACE` level by default. Currently used custom targets:
+        - `CONFIG_HANDLING`
 
-[^experimental]: This shows what's *possible* with the infra in an experimental implementation.
+The `TRACE` filter will enable *all* `trace` level or less verbose level tracing output.
 
-The env var `BOOTSTRAP_TRACING` accepts a [`tracing` env-filter][tracing-env-filter]. The `TRACE` filter will enable *all* `trace` level or less verbose level tracing output.
+You can of course combine them (custom target logs are typically gated behind `TRACE` log level additionally):
+
+```bash
+$ BOOTSTRAP_TRACING=CONFIG_HANDLING=TRACE ./x build library --stage 1
+```
+
+[^unstable]: This output is always subject to further changes.
 
 [tracing-env-filter]: https://docs.rs/tracing-subscriber/0.3.19/tracing_subscriber/filter/struct.EnvFilter.html
 
@@ -73,28 +121,6 @@ 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.
 
-### Enabling `tracing` bootstrap feature in rust-analyzer
+### rust-analyzer integration?
 
-You can adjust your `settings.json`'s `rust-analyzer.check.overrideCommand` and `rust-analyzer.cargo.buildScripts.overrideCommand` if you want to also enable `logging` cargo feature by default in your editor. This is mostly useful if you want proper r-a completions and such when working on bootstrap itself.
-
-```json
-"rust-analyzer.check.overrideCommand": [
-    "BOOTSTRAP_TRACING=1", // <- BOOTSTRAP_TRACING=1 won't enable tracing filter, but it will activate bootstrap's `tracing` feature
-    "python3",
-    "x.py",
-    "check",
-    "--json-output",
-    "--build-dir=build-rust-analyzer"
-],
-```
-
-```json
-"rust-analyzer.cargo.buildScripts.overrideCommand": [
-    "BOOTSTRAP_TRACING=1", // <- note this
-    "python3",
-    "x.py",
-    "check",
-    "--json-output",
-    "--build-dir=build-rust-analyzer"
-],
-```
+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>.