Improve tracing in bootstrap #145261

Kobzol · 2025-08-11T16:42:08Z

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 690c781. 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

So that it is easier to see which was the last started step when a failure happens on CI.

When verbose mode is enabled, it is very hard to see the actually executed steps.

They could easily get out of sync and miss some fields. Now all steps are instrumented automatically.

…nabled

rustbot · 2025-08-11T16:42:14Z

This PR changes how LLVM is built. Consider updating src/bootstrap/download-ci-llvm-stamp.

The rustc-dev-guide subtree was changed. If this PR only touches the dev guide consider submitting a PR directly to rust-lang/rustc-dev-guide otherwise thank you for updating the dev guide with your changes.

cc @BoxyUwU, @jieyouxu, @Kobzol, @tshepang

jieyouxu · 2025-08-12T12:48:19Z

I'll take a look tmrw, ran out of time today.

src/bootstrap/Cargo.toml

jieyouxu

Thanks, I tried this locally, and I do like it more than the tracing-forest defaults

jieyouxu · 2025-08-13T12:56:15Z

src/bootstrap/Cargo.lock

Remark: I wonder if we should suppress the e.g.

Building stage0 tool lld-wrapper (x86_64-unknown-linux-gnu)

messages that interleave the tracing output, but this is fine

I think that the interleaving is a feature, not a bug - you can then figure out where were the messages actually printed, in relation to how were the steps executed. That being said, we currently print these logs to stdout, but the tracing is printed to stderr, so the interleaving can be a bit non-deterministic.

Right. That is fine.

jieyouxu · 2025-08-13T12:57:48Z

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 690c781.

I'm not convinced this is worth keeping around, I found that every time I tried that, I also get drowned in all the verbosity

jieyouxu · 2025-08-13T12:58:20Z

@bors r+

bors · 2025-08-13T12:58:22Z

📌 Commit 0b8c6ad has been approved by jieyouxu

It is now in the queue for this repository.

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 690c781. 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`

Rollup of 13 pull requests Successful merges: - #122661 (Change the desugaring of `assert!` for better error output) - #142372 (Improve `--remap-path-prefix` documentation) - #143075 (compiler: Allow `extern "interrupt" fn() -> !`) - #145005 (strip prefix of temporary file names when it exceeds filesystem name length limit) - #145065 (resolve: Introduce `RibKind::Block`) - #145120 (llvm: Accept new LLVM lifetime format) - #145189 (Weekly `cargo update`) - #145261 (Improve tracing in bootstrap) - #145266 (Reduce some queries around associated items) - #145299 (doc test: fix mpsc.rs try_send doc test) - #145331 (Make std use the edition 2024 prelude) - #145353 (bootstrap: Fix jemalloc 64K page support for aarch64 tools) - #145361 (Suppress wrapper suggestion when expected and actual ty are the same adt and the variant is unresolved) Failed merges: - #145324 (Rename and document `ONLY_HOSTS` in bootstrap) - #145372 (resolve: Miscellaneous cleanups) r? `@ghost` `@rustbot` modify labels: rollup

Kobzol · 2025-08-14T14:59:27Z

@bors rollup

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 690c781. 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`

Rollup of 11 pull requests Successful merges: - #137872 (Include whitespace in "remove |" suggestion and make it hidden) - #144631 (Fix test intrinsic-raw_eq-const-bad for big-endian) - #145233 (cfg_select: Support unbraced expressions) - #145261 (Improve tracing in bootstrap) - #145324 (Rename and document `ONLY_HOSTS` in bootstrap) - #145353 (bootstrap: Fix jemalloc 64K page support for aarch64 tools) - #145379 (bootstrap: Support passing `--timings` to cargo) - #145397 (Rust documentation, use `rustc-dev-guide` :3) - #145398 (Use `default_field_values` in `Resolver`) - #145401 (cleanup: Remove useless `[T].iter().last()`) - #145403 (Adjust error message grammar to be less awkward) r? `@ghost` `@rustbot` modify labels: rollup

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 690c781. 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``

Kobzol added 17 commits August 11, 2025 18:21

Store bootstrap tracing outputs to a unified directory

e6dddcb

Store latest symlink to the latest tracing output directory

c97b606

Store Chrome step trace into the tracing directory

f819729

Use shorter command span label

aad5795

Print step timings also when the stap starts to execute

3a115ba

So that it is easier to see which was the last started step when a failure happens on CI.

Replace tracing_forest with custom span formatting

c846f7c

Create a span for each executed step

1e14229

Remove ad-hoc print of executed/cached steps in verbose mode

690c781

When verbose mode is enabled, it is very hard to see the actually executed steps.

Remove manual #[instrument] annotations on steps

d403934

They could easily get out of sync and miss some fields. Now all steps are instrumented automatically.

Move tracing setup to the tracing module

604c180

Correctly show executed command name in Chrome trace

c3682b2

Always profile commands and generate Chrome profile when tracing is e…

b4a357f

…nabled

Do not create a span for cached commands

f9a4588

Create tracing directory symlink even during dry run

12828f7

Use pretty_step_name in step_graph

3e77562

Update debugging/profiling bootstrap page

a0306bf

Print created location of executed commands

6f584bc

rustbot assigned jieyouxu Aug 11, 2025

klensy reviewed Aug 12, 2025

View reviewed changes

src/bootstrap/Cargo.toml Outdated Show resolved Hide resolved

Remove one dependency from tracing bootstrap build

0b8c6ad

jieyouxu approved these changes Aug 13, 2025

View reviewed changes

jieyouxu reviewed Aug 13, 2025

View reviewed changes

bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Aug 13, 2025

Zalathar mentioned this pull request Aug 14, 2025

Rollup of 13 pull requests #145373

Closed

This was referenced Aug 14, 2025

Rollup of 12 pull requests #145406

Closed

Rollup of 11 pull requests #145407

Merged

bors merged commit ebd4a10 into rust-lang:master Aug 15, 2025
10 checks passed

rustbot added this to the 1.91.0 milestone Aug 15, 2025

Kobzol deleted the bootstrap-tracing branch August 15, 2025 05:07

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Improve tracing in bootstrap #145261

Improve tracing in bootstrap #145261

Kobzol commented Aug 11, 2025 •

edited

Loading

Uh oh!

rustbot commented Aug 11, 2025

Uh oh!

jieyouxu commented Aug 12, 2025

Uh oh!

Uh oh!

jieyouxu left a comment

Uh oh!

jieyouxu Aug 13, 2025

Uh oh!

Kobzol Aug 13, 2025

Uh oh!

jieyouxu Aug 13, 2025

Uh oh!

jieyouxu commented Aug 13, 2025 •

edited

Loading

Uh oh!

jieyouxu commented Aug 13, 2025

Uh oh!

bors commented Aug 13, 2025

Uh oh!

Kobzol commented Aug 14, 2025

Uh oh!

Uh oh!

Uh oh!

Improve tracing in bootstrap #145261

Improve tracing in bootstrap #145261

Conversation

Kobzol commented Aug 11, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

rustbot commented Aug 11, 2025

Uh oh!

jieyouxu commented Aug 12, 2025

Uh oh!

Uh oh!

jieyouxu left a comment

Choose a reason for hiding this comment

Uh oh!

jieyouxu Aug 13, 2025

Choose a reason for hiding this comment

Uh oh!

Kobzol Aug 13, 2025

Choose a reason for hiding this comment

Uh oh!

jieyouxu Aug 13, 2025

Choose a reason for hiding this comment

Uh oh!

jieyouxu commented Aug 13, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jieyouxu commented Aug 13, 2025

Uh oh!

bors commented Aug 13, 2025

Uh oh!

Kobzol commented Aug 14, 2025

Uh oh!

Uh oh!

Uh oh!

Kobzol commented Aug 11, 2025 •

edited

Loading

jieyouxu commented Aug 13, 2025 •

edited

Loading