bootstrap: add more logging

Author: jieyouxu

src/bootstrap/src/bin/main.rs

@@ -16,7 +16,7 @@ use bootstrap::{
 };
 use build_helper::ci::CiEnv;
 #[cfg(feature = "tracing")]
-use tracing::{instrument, trace};
+use tracing::{debug, instrument};
 
 #[cfg_attr(feature = "tracing", instrument(level = "trace", name = "main"))]
 fn main() {
@@ -29,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;
@@ -91,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 {

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;

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 {