diff --git a/src/bootstrap/src/bin/main.rs b/src/bootstrap/src/bin/main.rs index 8ebd6b8aa54cd..5fcf7eda8df79 100644 --- a/src/bootstrap/src/bin/main.rs +++ b/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 { // "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. . + 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(); } diff --git a/src/bootstrap/src/core/config/config.rs b/src/bootstrap/src/core/config/config.rs index 910550b0a7d39..98490118f7d62 100644 --- a/src/bootstrap/src/core/config/config.rs +++ b/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, @@ -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 ` + // - `RUST_BOOTSTRAP_CONFIG` + // - `./config.toml` + // - `config.toml` in the root directory. let toml_path = flags .config .clone() diff --git a/src/bootstrap/src/core/config/flags.rs b/src/bootstrap/src/core/config/flags.rs index f17103f97dc40..27fb00cb06e05 100644 --- a/src/bootstrap/src/core/config/flags.rs +++ b/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)) } diff --git a/src/bootstrap/src/lib.rs b/src/bootstrap/src/lib.rs index 482e23cd04c31..d56f35f866cb8 100644 --- a/src/bootstrap/src/lib.rs +++ b/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 { 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 972b4a8fb0e62..3f907e85dd6cc 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 @@ -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 . diff --git a/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap/tracing-output-example.png b/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap/tracing-output-example.png deleted file mode 100644 index 745aec50d4a36..0000000000000 Binary files a/src/doc/rustc-dev-guide/src/building/bootstrapping/debugging-bootstrap/tracing-output-example.png and /dev/null differ