1# Debugging bootstrap23There are two main ways of debugging (and profiling bootstrap). The first is through println logging, and the second is through the `tracing` feature.45## `println` logging67Bootstrap has extensive unstructured logging. Most of it is gated behind the `--verbose` flag (pass `-vv` for even more detail).89If 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.1011```12$ ./x dist rustc --dry-run -vv13learning about cargo14running: 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)15running: 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)16...17```1819## `tracing` in bootstrap2021Bootstrap has a conditional `tracing` feature, which provides the following features:22- It enables structured logging using [`tracing`][tracing] events and spans.23- It generates a [Chrome trace file] that can be used to visualize the hierarchy and durations of executed steps and commands.24  - You can open the generated `chrome-trace.json` file using Chrome, on the `chrome://tracing` tab, or e.g. using [Perfetto].25- It generates [GraphViz] graphs that visualize the dependencies between executed steps.26  - 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.27- 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.28  - The generated `command-stats.txt` file is in a simple human-readable format.2930The structured logs will be written to standard error output (`stderr`), while the other outputs will be stored in files in the `<build-dir>/bootstrap-trace/<pid>` directory. For convenience, bootstrap will also create a symlink to the latest generated trace output directory at `<build-dir>/bootstrap-trace/latest`.3132> 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.3334[tracing]: https://docs.rs/tracing/0.1.41/tracing/index.html35[Chrome trace file]: https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/36[Perfetto]: https://ui.perfetto.dev/37[GraphViz]: https://graphviz.org/doc/info/lang.html38[xdot]: https://github.com/jrfonseca/xdot.py3940### Enabling `tracing` output4142To enable the conditional `tracing` feature, run bootstrap with the `BOOTSTRAP_TRACING` environment variable.4344[tracing_subscriber filter]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html4546```bash47$ BOOTSTRAP_TRACING=trace ./x build library --stage 148```4950Example output[^unstable]:5152```53$ BOOTSTRAP_TRACING=trace ./x build library --stage 1 --dry-run54Building bootstrap55    Finished `dev` profile [unoptimized] target(s) in 0.05s5615:56:52.477  INFO > tool::LibcxxVersionTool {target: x86_64-unknown-linux-gnu} (builder/mod.rs:1715)5715:56:52.575  INFO > compile::Assemble {target_compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }} (builder/mod.rs:1715)5815: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)5915: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)6015: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)6115: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)6215:56:52.578  INFO > compile::Assemble {target_compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu, forced_compiler: false }} (builder/mod.rs:1715)6315: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)6415: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)6515: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)6615: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)67    Finished `release` profile [optimized] target(s) in 0.11s68Tracing/profiling output has been written to <src-root>/build/bootstrap-trace/latest69Build completed successfully in 0:00:0070```7172[^unstable]: This output is always subject to further changes.7374#### Controlling tracing output7576The 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.7778There are two orthogonal ways to control which kind of tracing logs you want:79801. You can specify the log **level**, e.g. `debug` or `trace`.81   - If you select a level, all events/spans with an equal or higher priority level will be shown.822. You can also control the log **target**, e.g. `bootstrap` or `bootstrap::core::config` or a custom target like `CONFIG_HANDLING` or `STEP`.83    - 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:84        - `CONFIG_HANDLING`: show spans related to config handling.85        - `STEP`: show all executed steps. Executed commands have `info` event level.86        - `COMMAND`: show all executed commands. Executed commands have `trace` event level.87        - `IO`: show performed I/O operations. Executed commands have `trace` event level.88            - Note that many I/O are currently not being traced.8990You can of course combine them (custom target logs are typically gated behind `TRACE` log level additionally):9192```bash93$ BOOTSTRAP_TRACING=CONFIG_HANDLING=trace,STEP=info,COMMAND=trace ./x build library --stage 194```9596[tracing-env-filter]: https://docs.rs/tracing-subscriber/0.3.19/tracing_subscriber/filter/struct.EnvFilter.html9798Note 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.99100##### FIXME(#96176): specific tracing for `compiler()` vs `compiler_for()`101102The additional targets `COMPILER` and `COMPILER_FOR` are used to help trace what103`builder.compiler()` and `builder.compiler_for()` does. They should be removed104if [#96176][cleanup-compiler-for] is resolved.105106[cleanup-compiler-for]: https://github.com/rust-lang/rust/issues/96176107108### Using `tracing` in bootstrap109110Both `tracing::*` macros and the `tracing::instrument` proc-macro attribute need to be gated behind `tracing` feature. Examples:111112```rs113#[cfg(feature = "tracing")]114use tracing::instrument;115116struct Foo;117118impl Step for Foo {119    type Output = ();120121    #[cfg_attr(feature = "tracing", instrument(level = "trace", name = "Foo::should_run", skip_all))]122    fn should_run(run: ShouldRun<'_>) -> ShouldRun<'_> {123        trace!(?run, "entered Foo::should_run");124125        todo!()126    }127128    fn run(self, builder: &Builder<'_>) -> Self::Output {129        trace!(?run, "entered Foo::run");130131        todo!()132    }    133}134```135136For `#[instrument]`, it's recommended to:137138- Gate it behind `trace` level for fine-granularity, possibly `debug` level for core functions.139- Explicitly pick an instrumentation name via `name = ".."` to distinguish between e.g. `run` of different steps.140- Take care to not cause diverging behavior via tracing, e.g. building extra things only when tracing infra is enabled.141142### rust-analyzer integration?143144Unfortunately, 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>.