Skip to content

Commit a0306bf

Browse files
KobzolKobzol
committed
Update debugging/profiling bootstrap page
1 parent 3e77562 commit a0306bf

File tree

1 file changed

+49
-99
lines changed

1 file changed

+49
-99
lines changed

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

Lines changed: 49 additions & 99 deletions
Original file line numberDiff line numberDiff line change
@@ -1,120 +1,100 @@
11
# Debugging bootstrap
22

3-
There are two main ways to debug bootstrap itself. The first is through println logging, and the second is through the `tracing` feature.
4-
5-
> FIXME: this section should be expanded
3+
There are two main ways of debugging (and profiling bootstrap). The first is through println logging, and the second is through the `tracing` feature.
64

75
## `println` logging
86

97
Bootstrap has extensive unstructured logging. Most of it is gated behind the `--verbose` flag (pass `-vv` for even more detail).
108

11-
If you want to know which `Step` ran a command, you could invoke bootstrap like so:
9+
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.
1210

1311
```
1412
$ ./x dist rustc --dry-run -vv
1513
learning about cargo
1614
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)
1715
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)
18-
> Assemble { target_compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu } }
19-
> Libdir { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, target: x86_64-unknown-linux-gnu }
20-
> Sysroot { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, force_recompile: false }
21-
Removing sysroot /home/jyn/src/rust2/build/tmp-dry-run/x86_64-unknown-linux-gnu/stage1 to avoid caching bugs
22-
< Sysroot { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, force_recompile: false }
23-
< Libdir { compiler: Compiler { stage: 1, host: x86_64-unknown-linux-gnu }, target: x86_64-unknown-linux-gnu }
24-
...
25-
```
26-
27-
This will go through all the recursive dependency calculations, where `Step`s internally call `builder.ensure()`, without actually running cargo or the compiler.
28-
29-
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:
30-
31-
```
32-
c Sysroot { compiler: Compiler { stage: 0, host: x86_64-unknown-linux-gnu }, force_recompile: false }
33-
using sysroot /home/jyn/src/rust2/build/x86_64-unknown-linux-gnu/stage0-sysroot
34-
Building stage0 library artifacts (x86_64-unknown-linux-gnu)
35-
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"
36-
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) }
3716
...
3817
```
3918

40-
In most cases this should not be necessary.
19+
## `tracing` in bootstrap
4120

42-
TODO: we should convert all this to structured logging so it's easier to control precisely.
21+
Bootstrap 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.
4329

44-
## `tracing` in bootstrap
30+
The 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`.
4531

46-
Bootstrap has conditional [`tracing`][tracing] setup to provide structured logging.
32+
> 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.
4733
4834
[tracing]: https://docs.rs/tracing/0.1.41/tracing/index.html
35+
[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.html
38+
[xdot]: https://github.com/jrfonseca/xdot.py
4939

5040
### Enabling `tracing` output
5141

52-
Bootstrap will conditionally build `tracing` support and enable `tracing` output if the `BOOTSTRAP_TRACING` env var is set.
53-
54-
#### Basic usage
55-
56-
Example basic usage[^just-trace]:
42+
To enable the conditional `tracing` feature, run bootstrap with the `BOOTSTRAP_TRACING` environment variable.
5743

58-
[^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.
44+
[tracing_subscriber filter]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html
5945

6046
```bash
61-
$ BOOTSTRAP_TRACING=bootstrap=TRACE ./x build library --stage 1
47+
$ BOOTSTRAP_TRACING=trace ./x build library --stage 1
6248
```
6349

6450
Example output[^unstable]:
6551

6652
```
67-
$ BOOTSTRAP_TRACING=bootstrap=TRACE ./x check src/bootstrap/
53+
$ BOOTSTRAP_TRACING=trace ./x build library --stage 1 --dry-run
6854
Building bootstrap
69-
Compiling bootstrap v0.0.0 (/home/joe/repos/rust/src/bootstrap)
70-
Finished `dev` profile [unoptimized] target(s) in 2.74s
71-
DEBUG bootstrap parsing flags
72-
bootstrap::core::config::flags::Flags::parse args=["check", "src/bootstrap/"]
73-
DEBUG bootstrap parsing config based on flags
74-
DEBUG bootstrap creating new build based on config
75-
bootstrap::Build::build
76-
TRACE bootstrap setting up job management
77-
TRACE bootstrap downloading rustfmt early
78-
bootstrap::handling hardcoded subcommands (Format, Suggest, Perf)
79-
DEBUG bootstrap not a hardcoded subcommand; returning to normal handling, cmd=Check { all_targets: false }
80-
DEBUG bootstrap handling subcommand normally
81-
bootstrap::executing real run
82-
bootstrap::(1) executing dry-run sanity-check
83-
bootstrap::(2) executing actual run
84-
Checking stage0 library artifacts (x86_64-unknown-linux-gnu)
85-
Finished `release` profile [optimized + debuginfo] target(s) in 0.04s
86-
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)
87-
Finished `release` profile [optimized + debuginfo] target(s) in 0.23s
88-
Checking stage0 bootstrap artifacts (x86_64-unknown-linux-gnu)
89-
Checking bootstrap v0.0.0 (/home/joe/repos/rust/src/bootstrap)
90-
Finished `release` profile [optimized + debuginfo] target(s) in 0.64s
91-
DEBUG bootstrap checking for postponed test failures from `test --no-fail-fast`
92-
Build completed successfully in 0:00:08
55+
Finished `dev` profile [unoptimized] target(s) in 0.05s
56+
15:56:52.477 INFO > tool::LibcxxVersionTool {target: x86_64-unknown-linux-gnu} (builder/mod.rs:1715)
57+
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)
58+
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)
59+
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)
60+
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)
61+
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)
62+
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)
63+
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)
64+
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)
65+
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)
66+
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)
67+
Finished `release` profile [optimized] target(s) in 0.11s
68+
Tracing/profiling output has been written to <src-root>/build/bootstrap-trace/latest
69+
Build completed successfully in 0:00:00
9370
```
9471

72+
[^unstable]: This output is always subject to further changes.
73+
9574
#### Controlling tracing output
9675

97-
The env var `BOOTSTRAP_TRACING` accepts a [`tracing` env-filter][tracing-env-filter].
76+
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.
9877

9978
There are two orthogonal ways to control which kind of tracing logs you want:
10079

101-
1. You can specify the log **level**, e.g. `DEBUG` or `TRACE`.
102-
2. You can also control the log **target**, e.g. `bootstrap` or `bootstrap::core::config` vs custom targets like `CONFIG_HANDLING`.
103-
- 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:
104-
- `CONFIG_HANDLING`
105-
106-
The `TRACE` filter will enable *all* `trace` level or less verbose level tracing output.
80+
1. 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.
82+
2. 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. Note that executed commands have `info` event level.
86+
- `COMMAND`: show all executed commands. Note that executed commands have `trace` event level.
10787

10888
You can of course combine them (custom target logs are typically gated behind `TRACE` log level additionally):
10989

11090
```bash
111-
$ BOOTSTRAP_TRACING=CONFIG_HANDLING=TRACE ./x build library --stage 1
91+
$ BOOTSTRAP_TRACING=CONFIG_HANDLING=trace,STEP=info,COMMAND=trace ./x build library --stage 1
11292
```
11393

114-
[^unstable]: This output is always subject to further changes.
115-
11694
[tracing-env-filter]: https://docs.rs/tracing-subscriber/0.3.19/tracing_subscriber/filter/struct.EnvFilter.html
11795

96+
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.
97+
11898
##### FIXME(#96176): specific tracing for `compiler()` vs `compiler_for()`
11999

120100
The additional targets `COMPILER` and `COMPILER_FOR` are used to help trace what
@@ -123,12 +103,6 @@ if [#96176][cleanup-compiler-for] is resolved.
123103

124104
[cleanup-compiler-for]: https://github.com/rust-lang/rust/issues/96176
125105

126-
### Rendering step graph
127-
128-
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.
129-
130-
A separate DOT file will be outputted for dry-run and non-dry-run execution.
131-
132106
### Using `tracing` in bootstrap
133107

134108
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 {
149123
todo!()
150124
}
151125

152-
#[cfg_attr(
153-
feature = "tracing",
154-
instrument(
155-
level = "trace",
156-
name = "Foo::run",
157-
skip_all,
158-
fields(compiler = ?builder.compiler),
159-
),
160-
)]
161126
fn run(self, builder: &Builder<'_>) -> Self::Output {
162127
trace!(?run, "entered Foo::run");
163128

@@ -172,21 +137,6 @@ For `#[instrument]`, it's recommended to:
172137
- Explicitly pick an instrumentation name via `name = ".."` to distinguish between e.g. `run` of different steps.
173138
- Take care to not cause diverging behavior via tracing, e.g. building extra things only when tracing infra is enabled.
174139

175-
### Profiling bootstrap
176-
177-
You can set the `BOOTSTRAP_PROFILE=1` environment variable to enable command execution profiling during bootstrap. This generates:
178-
179-
* A Chrome trace file (for visualization in `chrome://tracing` or [Perfetto](https://ui.perfetto.dev)) if tracing is enabled via `BOOTSTRAP_TRACING=COMMAND=trace`
180-
* 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
181-
182-
Note: the `.txt` report is always generated when `BOOTSTRAP_PROFILE=1` is set — tracing is not required.
183-
184-
Example usage:
185-
186-
```bash
187-
$ BOOTSTRAP_PROFILE=1 BOOTSTRAP_TRACING=COMMAND=trace ./x build library
188-
```
189-
190140
### rust-analyzer integration?
191141

192142
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>.

0 commit comments

Comments
 (0)