You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
Rollup merge of #145261 - Kobzol:bootstrap-tracing, r=jieyouxu
Improve tracing in bootstrap
I was annoyed that bootstrap had like 5 separate ways of debugging/tracing/profiling, and it was hard for me to understand how are individual steps executed. This PR tries to unify severla things behind `BOOTSTRAP_TRACING`, and improve tracing/profiling in general:
- All generated tracing outputs are now stored in a single directory to make it easier to examine them, plus bootstrap prepares a `latest` symlink to the latest generated tracing output directory for convenience.
- All executed spans are now logged automatically (without requiring usage of `#[tracing::instrument]`).
- A custom span/event formatter was implemented, to provide domain-specific output (like location of executed commands or spans) and hopefully also to reduce visual clutter.
- `tracing_forest` was removed. While it did some useful postprocessing, it didn't expose enough information for making the dynamic step spans work.
- You can now explicitly log steps (`STEP=info`) and/or commands (`COMMAND=info`), to have more granular control over what gets logged.
- `print-step-timings` also show when a step starts its execution (not just when it ends it), so that when some step fails in CI, we can actually see what step it was (before we would only see the end of the previous step).
- The rustc-dev-guide page on debugging/profiling bootstrap was updated.
There are still some things that work outside of tracing (`print-step-timings` and `dump-bootstrap-shims`), but I think that for now this improvement is good enough.
I removed the `> step`, `< step` verbose output, because I found it unusable, as verbose bootstrap output also enables verbose Cargo output, and then you simply drown in too much data, and because I think that the new tracing system makes it obsolete (although it does require recompilation with the `tracing` feature). If you want to keep it, happy to revert 690c781475acb890f33d928186bdaea9ef179330. And the information about cached steps is now also shown in the Graphviz step dependency graph.
We can modify the tracing output however we want, as we now implement it ourselves. Notably, we could also show exit logs for step spans, currently I only show enter spans. Maybe creating indents for each executed nested command is also not needed. Happy to hear feedback!
Some further improvements could be to print step durations, if we decide to also log step exit events. We could also try to enable tracing in CI logs, but it might be too verbose.
Best reviewed commit-by-commit.
r? ``@jieyouxu``
CC ``@Shourya742``
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.
6
4
7
5
## `println` logging
8
6
9
7
Bootstrap has extensive unstructured logging. Most of it is gated behind the `--verbose` flag (pass `-vv` for even more detail).
10
8
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.
12
10
13
11
```
14
12
$ ./x dist rustc --dry-run -vv
15
13
learning about cargo
16
14
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)
17
15
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)
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:
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.
43
29
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`.
45
31
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.
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.
57
43
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.
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
93
70
```
94
71
72
+
[^unstable]: This output is always subject to further changes.
73
+
95
74
#### Controlling tracing output
96
75
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.
98
77
99
78
There are two orthogonal ways to control which kind of tracing logs you want:
100
79
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.
107
87
108
88
You can of course combine them (custom target logs are typically gated behind `TRACE` log level additionally):
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
-
132
106
### Using `tracing` in bootstrap
133
107
134
108
Both `tracing::*` macros and the `tracing::instrument` proc-macro attribute need to be gated behind `tracing` feature. Examples:
@@ -172,21 +137,6 @@ For `#[instrument]`, it's recommended to:
172
137
- Explicitly pick an instrumentation name via `name = ".."` to distinguish between e.g. `run` of different steps.
173
138
- Take care to not cause diverging behavior via tracing, e.g. building extra things only when tracing infra is enabled.
174
139
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.
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