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 9c5ebbd36c46..fb90c0fdb435 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,120 +1,100 @@ # Debugging bootstrap -There are two main ways to debug bootstrap itself. The first is through println logging, and the second is through the `tracing` feature. - -> FIXME: this section should be expanded +There are two main ways of debugging (and profiling bootstrap). The first is through println logging, and the second is through the `tracing` feature. ## `println` logging Bootstrap has extensive unstructured logging. Most of it is gated behind the `--verbose` flag (pass `-vv` for even more detail). -If you want to know which `Step` ran a command, you could invoke bootstrap like so: +If you want to see verbose output of executed Cargo commands and other kinds of detailed logs, pass `-v` or `-vv` when invoking bootstrap. Note that the logs are unstructured and may be overwhelming. ``` $ ./x dist rustc --dry-run -vv learning about cargo running: RUSTC_BOOTSTRAP="1" "/home/jyn/src/rust2/build/x86_64-unknown-linux-gnu/stage0/bin/cargo" "metadata" "--format-version" "1" "--no-deps" "--manifest-path" "/home/jyn/src/rust2/Cargo.toml" (failure_mode=Exit) (created at src/bootstrap/src/core/metadata.rs:81:25, executed at src/bootstrap/src/core/metadata.rs:92:50) running: RUSTC_BOOTSTRAP="1" "/home/jyn/src/rust2/build/x86_64-unknown-linux-gnu/stage0/bin/cargo" "metadata" "--format-version" "1" "--no-deps" "--manifest-path" "/home/jyn/src/rust2/library/Cargo.toml" (failure_mode=Exit) (created at src/bootstrap/src/core/metadata.rs:81:25, executed at src/bootstrap/src/core/metadata.rs:92:50) -> Assemble { target_compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu } } - > Libdir { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, target: x86_64-unknown-linux-gnu } - > Sysroot { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, force_recompile: false } -Removing sysroot /home/jyn/src/rust2/build/tmp-dry-run/x86_64-unknown-linux-gnu/stage1 to avoid caching bugs - < Sysroot { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, force_recompile: false } - < Libdir { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, target: x86_64-unknown-linux-gnu } ... ``` -This will go through all the recursive dependency calculations, where `Step`s internally call `builder.ensure()`, without actually running cargo or the compiler. - -In some cases, even this may not be enough logging (if so, please add more!). In that case, you can omit `--dry-run`, which will show the normal output inline with the debug logging: - -``` - c Sysroot { compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu }, force_recompile: false } -using sysroot /home/jyn/src/rust2/build/x86_64-unknown-linux-gnu/stage0-sysroot -Building stage0 library artifacts (x86_64-unknown-linux-gnu) -running: cd "/home/jyn/src/rust2" && env ... RUSTC_VERBOSE="2" RUSTC_WRAPPER="/home/jyn/src/rust2/build/bootstrap/debug/rustc" "/home/jyn/src/rust2/build/x86_64-unknown-linux-gnu/stage0/bin/cargo" "build" "--target" "x86_64-unknown-linux-gnu" "-Zbinary-dep-depinfo" "-Zroot-dir=/home/jyn/src/rust2" "-v" "-v" "--manifest-path" "/home/jyn/src/rust2/library/sysroot/Cargo.toml" "--message-format" "json-render-diagnostics" - 0.293440230s INFO prepare_target{force=false package_id=sysroot v0.0.0 (/home/jyn/src/rust2/library/sysroot) target="sysroot"}: cargo::core::compiler::fingerprint: fingerprint error for sysroot v0.0.0 (/home/jyn/src/rust2/library/sysroot)/Build/TargetInner { name_inferred: true, ..: lib_target("sysroot", ["lib"], "/home/jyn/src/rust2/library/sysroot/src/lib.rs", Edition2021) } -... -``` - -In most cases this should not be necessary. - -TODO: we should convert all this to structured logging so it's easier to control precisely. - ## `tracing` in bootstrap -Bootstrap has conditional [`tracing`][tracing] setup to provide structured logging. +Bootstrap has a conditional `tracing` feature, which provides the following features: +- It enables structured logging using [`tracing`][tracing] events and spans. +- It generates a [Chrome trace file] that can be used to visualize the hierarchy and durations of executed steps and commands. + - You can open the generated `chrome-trace.json` file using Chrome, on the `chrome://tracing` tab, or e.g. using [Perfetto]. +- It generates [GraphViz] graphs that visualize the dependencies between executed steps. + - You can open the generated `step-graph-*.dot` file using e.g. [xdot] to visualize the step graph, or use e.g. `dot -Tsvg` to convert the GraphViz file to an SVG file. +- It generates a command execution summary, which shows which commands were executed, how many of their executions were cached, and what commands were the slowest to run. + - The generated `command-stats.txt` file is in a simple human-readable format. + +The structured logs will be written to standard error output (`stderr`), while the other outputs will be stored in files in the `/bootstrap-trace/` directory. For convenience, bootstrap will also create a symlink to the latest generated trace output directory at `/bootstrap-trace/latest`. + +> Note that if you execute bootstrap with `--dry-run`, the tracing output directory might change. Bootstrap will always print a path where the tracing output files were stored at the end of its execution. [tracing]: https://docs.rs/tracing/0.1.41/tracing/index.html +[Chrome trace file]: https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/ +[Perfetto]: https://ui.perfetto.dev/ +[GraphViz]: https://graphviz.org/doc/info/lang.html +[xdot]: https://github.com/jrfonseca/xdot.py ### Enabling `tracing` output -Bootstrap will conditionally build `tracing` support and enable `tracing` output if the `BOOTSTRAP_TRACING` env var is set. +To enable the conditional `tracing` feature, run bootstrap with the `BOOTSTRAP_TRACING` environment variable. -#### Basic usage - -Example basic usage[^just-trace]: - -[^just-trace]: It is not recommended 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. +[tracing_subscriber filter]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html ```bash -$ BOOTSTRAP_TRACING=bootstrap=TRACE ./x build library --stage 1 +$ BOOTSTRAP_TRACING=trace ./x build library --stage 1 ``` Example output[^unstable]: ``` -$ BOOTSTRAP_TRACING=bootstrap=TRACE ./x check src/bootstrap/ +$ BOOTSTRAP_TRACING=trace ./x build library --stage 1 --dry-run 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 -``` - -#### Controlling tracing output - -The env var `BOOTSTRAP_TRACING` accepts a [`tracing` env-filter][tracing-env-filter]. - -There are two orthogonal ways to control which kind of tracing logs you want: - -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` - -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 + Finished `dev` profile [unoptimized] target(s) in 0.05s +15:56:52.477 INFO > tool::LibcxxVersionTool {target: x86_64-unknown-linux-gnu} (builder/mod.rs:1715) +15:56:52.575 INFO > compile::Assemble {target_compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }} (builder/mod.rs:1715) +15:56:52.575 INFO > tool::Compiletest {compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, target: x86_64-unknown-linux-gnu} (builder/mod.rs:1715) +15:56:52.576 INFO > tool::ToolBuild {build_compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, target: x86_64-unknown-linux-gnu, tool: "compiletest", path: "src/tools/compiletest", mode: ToolBootstrap, source_type: InTree, extra_features: [], allow_features: "internal_output_capture", cargo_args: [], artifact_kind: Binary} (builder/mod.rs:1715) +15:56:52.576 INFO > builder::Libdir {compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, target: x86_64-unknown-linux-gnu} (builder/mod.rs:1715) +15:56:52.576 INFO > compile::Sysroot {compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, force_recompile: false} (builder/mod.rs:1715) +15:56:52.578 INFO > compile::Assemble {target_compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }} (builder/mod.rs:1715) +15:56:52.578 INFO > tool::Compiletest {compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, target: x86_64-unknown-linux-gnu} (builder/mod.rs:1715) +15:56:52.578 INFO > tool::ToolBuild {build_compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, target: x86_64-unknown-linux-gnu, tool: "compiletest", path: "src/tools/compiletest", mode: ToolBootstrap, source_type: InTree, extra_features: [], allow_features: "internal_output_capture", cargo_args: [], artifact_kind: Binary} (builder/mod.rs:1715) +15:56:52.578 INFO > builder::Libdir {compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, target: x86_64-unknown-linux-gnu} (builder/mod.rs:1715) +15:56:52.578 INFO > compile::Sysroot {compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }, force_recompile: false} (builder/mod.rs:1715) + Finished `release` profile [optimized] target(s) in 0.11s +Tracing/profiling output has been written to /build/bootstrap-trace/latest +Build completed successfully in 0:00:00 ``` [^unstable]: This output is always subject to further changes. +#### Controlling tracing output + +The environment variable `BOOTSTRAP_TRACING` accepts a [`tracing_subscriber` filter][tracing-env-filter]. If you set `BOOTSTRAP_TRACING=trace`, you will enable all logs, but that can be overwhelming. You can thus use the filter to reduce the amount of data logged. + +There are two orthogonal ways to control which kind of tracing logs you want: + +1. You can specify the log **level**, e.g. `debug` or `trace`. + - If you select a level, all events/spans with an equal or higher priority level will be shown. +2. You can also control the log **target**, e.g. `bootstrap` or `bootstrap::core::config` or a custom target like `CONFIG_HANDLING` or `STEP`. + - Custom targets are used to limit what kinds of spans you are interested in, as the `BOOTSTRAP_TRACING=trace` output can be quite verbose. Currently, you can use the following custom targets: + - `CONFIG_HANDLING`: show spans related to config handling + - `STEP`: show all executed steps. Note that executed commands have `info` event level. + - `COMMAND`: show all executed commands. Note that executed commands have `trace` event level. + +You can of course combine them (custom target logs are typically gated behind `TRACE` log level additionally): + +```bash +$ BOOTSTRAP_TRACING=CONFIG_HANDLING=trace,STEP=info,COMMAND=trace ./x build library --stage 1 +``` + [tracing-env-filter]: https://docs.rs/tracing-subscriber/0.3.19/tracing_subscriber/filter/struct.EnvFilter.html +Note that the level that you specify using `BOOTSTRAP_TRACING` also has an effect on the spans that will be recorded in the Chrome trace file. + ##### FIXME(#96176): specific tracing for `compiler()` vs `compiler_for()` The additional targets `COMPILER` and `COMPILER_FOR` are used to help trace what @@ -123,12 +103,6 @@ if [#96176][cleanup-compiler-for] is resolved. [cleanup-compiler-for]: https://github.com/rust-lang/rust/issues/96176 -### Rendering step graph - -When you run bootstrap with the `BOOTSTRAP_TRACING` environment variable configured, bootstrap will automatically output a DOT file that shows all executed steps and their dependencies. The files will have a prefix `bootstrap-steps`. You can use e.g. `xdot` to visualize the file or e.g. `dot -Tsvg` to convert the DOT file to a SVG file. - -A separate DOT file will be outputted for dry-run and non-dry-run execution. - ### Using `tracing` in bootstrap Both `tracing::*` macros and the `tracing::instrument` proc-macro attribute need to be gated behind `tracing` feature. Examples: @@ -149,15 +123,6 @@ impl Step for Foo { todo!() } - #[cfg_attr( - feature = "tracing", - instrument( - level = "trace", - name = "Foo::run", - skip_all, - fields(compiler = ?builder.compiler), - ), - )] fn run(self, builder: &Builder<'_>) -> Self::Output { trace!(?run, "entered Foo::run"); @@ -172,21 +137,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. -### Profiling bootstrap - -You can set the `BOOTSTRAP_PROFILE=1` environment variable to enable command execution profiling during bootstrap. This generates: - -* A Chrome trace file (for visualization in `chrome://tracing` or [Perfetto](https://ui.perfetto.dev)) if tracing is enabled via `BOOTSTRAP_TRACING=COMMAND=trace` -* A plain-text summary file, `bootstrap-profile-{pid}.txt`, listing all commands sorted by execution time (slowest first), along with cache hits and working directories - -Note: the `.txt` report is always generated when `BOOTSTRAP_PROFILE=1` is set — tracing is not required. - -Example usage: - -```bash -$ BOOTSTRAP_PROFILE=1 BOOTSTRAP_TRACING=COMMAND=trace ./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 .