Add RUSTC_PROGRESS env var to show the current queries and their arguments #113888

oli-obk · 2023-07-20T11:51:21Z

This should make debugging hangs much simpler, as you know in which query it's happening.

If compilation progresses, but slowly, this can also be used to actually follow that progress. Most of the time it's too fast and the displayed progress spinners disappear and get replaced by new ones.

The spinners look like the ones from the first example in https://crates.io/crates/indicatif

r? @bjorn3

cc @cjgillot

rustbot · 2023-07-20T11:51:30Z

Thanks for the pull request, and welcome! The Rust team is excited to review your changes, and you should hear from @bjorn3 (or someone else) soon.

Please see the contribution instructions for more information. Namely, in order to ensure the minimum review times lag, PR authors and assigned reviewers should ensure that the review label (S-waiting-on-review and S-waiting-on-author) stays updated, invoking these commands when appropriate:

@rustbot author: the review is finished, PR author should check the comments and take action accordingly
@rustbot review: the author is ready for a review, this PR will be queued again in the reviewer's queue

rustbot · 2023-07-20T11:51:32Z

These commits modify the Cargo.lock file. Unintentional changes to Cargo.lock can be introduced when switching branches and rebasing PRs.

If this was unintentional then you should revert the changes before this PR is merged.
Otherwise, you can ignore this comment.

oli-obk · 2023-07-20T14:58:38Z

@bors try @rust-timer queue

bors · 2023-07-20T14:58:47Z

⌛ Trying commit 8f467472de80fdebc0f2cc982ee4a15c8e0498dd with merge 25870bf3850ad5c029b807587de948c07a16612c...

bors · 2023-07-20T16:15:19Z

☀️ Try build successful - checks-actions
Build commit: 25870bf3850ad5c029b807587de948c07a16612c (25870bf3850ad5c029b807587de948c07a16612c)

rust-timer · 2023-07-20T19:33:36Z

Finished benchmarking commit (25870bf3850ad5c029b807587de948c07a16612c): comparison URL.

Overall result: ❌ regressions - ACTION NEEDED

Benchmarking this pull request likely means that it is perf-sensitive, so we're automatically marking it as not fit for rolling up. While you can manually mark this PR as fit for rollup, we strongly recommend not doing so since this PR may lead to changes in compiler perf.

Next Steps: If you can justify the regressions found in this try perf run, please indicate this with @rustbot label: +perf-regression-triaged along with sufficient written justification. If you cannot justify the regressions please fix the regressions and do another perf run. If the next run shows neutral or positive results, the label will be automatically removed.

@bors rollup=never
@rustbot label: -S-waiting-on-perf +perf-regression

Instruction count

This is a highly reliable metric that was used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	7.9%	[0.4%, 31.1%]	246
Regressions ❌ (secondary)	10.9%	[0.6%, 37.8%]	170
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-	-	0
All ❌✅ (primary)	7.9%	[0.4%, 31.1%]	246

Max RSS (memory usage)

Results

This is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	3.5%	[3.3%, 3.6%]	2
Regressions ❌ (secondary)	-	-	0
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-1.2%	[-1.2%, -1.2%]	1
All ❌✅ (primary)	3.5%	[3.3%, 3.6%]	2

Cycles

Results

This is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	5.1%	[0.6%, 16.7%]	208
Regressions ❌ (secondary)	7.9%	[1.0%, 25.1%]	141
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-	-	0
All ❌✅ (primary)	5.1%	[0.6%, 16.7%]	208

Binary size

This benchmark run did not return any relevant results for this metric.

Bootstrap: 648.618s -> 666.964s (2.83%)

bjorn3 · 2023-07-22T09:53:29Z

@rustbot author

The regressions will need to be fixed first. I do like the overall idea, but maybe it should be limited to queries that don't finish instantly and have some debouncing and a depth limit to prevent scrolling (which presumably messes up rendering). Also for queries that iterate over items maybe it could be an actual progress bar rather than a spinner.

oli-obk · 2023-07-25T07:55:17Z

@bors try @rust-timer queue

bors · 2023-07-25T07:55:27Z

⌛ Trying commit 39e340c85fd764c56e287febf4f4e044e6fb92dc with merge bbcb061f5a43bcae315f546c35dd15c7f6db9b02...

oli-obk · 2023-07-25T07:58:05Z

which presumably messes up rendering

I am fixing this upstream: console-rs/indicatif#563

maybe it should be limited to queries that don't finish instantly and have some debouncing

yea, I'm working on this now.

Also for queries that iterate over items maybe it could be an actual progress bar rather than a spinner.

IMO what we should do is allow any part of rustc to add such progress bars, and have them automatically appear in the right spot (below the query that does the iteration, and above the queries that are called during the iteration)

bjorn3 · 2023-07-25T13:32:13Z

The try build seems to leave some artifacts behind:

$ echo 'fn main() {}' | RUSTC_PROGRESS=1 rustc +bbcb061f5a43bcae315f546c35dd15c7f6db9b02 -
⠁ analysis                                                                                                                                                                                   ⠁ analysis
⠁ collect_and_partition_mono_items
  └⠁ dep_kind                                                                                                                                                                                ⠁ fn_abi_of_instance                                                                                                                                                                         ⠁ fn_abi_of_instance                                                                                                                                                                         ⠁ fn_abi_of_instance
⠁ fn_abi_of_instance
⠁ fn_abi_of_instance
⠁ fn_abi_of_instance

oli-obk · 2023-07-25T13:34:09Z

yea, this is fixed in the latest version (not using the indicatif builtin spinner logic, but rolling our own that doesn't race with adding/removing entries).

oli-obk · 2023-07-25T13:34:35Z

@rustbot ready

bjorn3 · 2023-07-25T13:44:39Z

yea, this is fixed in the latest version (not using the indicatif builtin spinner logic, but rolling our own that doesn't race with adding/removing entries).

Great! Currently building it locally to play around with it a bit. Just a random thought I came up with: Could this reuse the self-profile infrastructure? So every time a start self-profile event is emitted a spinner is added and every time an end event is emitted a spinner is removed. Or is there a mismatch between the semantics of self-profile and this progress thing?

bjorn3 · 2023-07-25T13:45:17Z

compiler/rustc_session/src/session.rs

@@ -1506,6 +1511,8 @@ pub fn build_session(
    let asm_arch =
        if target_cfg.allow_asm { InlineAsmArch::from_str(&target_cfg.arch).ok() } else { None };

+    let progress_bars = std::env::var_os("RUSTC_PROGRESS").map(|_| Session::init_progress_bars());


Maybe check if the value is not 0 to allow disabling it using RUSTC_PROGRESS=0?

bjorn3 · 2023-07-25T14:08:12Z

Tried it on cranelift-codegen and almost all of the time it only shows analysis as only spinner and the spinner itself doesn't spin most of the time and at the end it leaves behind the ⠄ analysis of the spinner and for echo 'fn main() {}' | RUSTC_PROGRESS=1 rustc - it now doesn't show any spinner at all.

oli-obk · 2023-07-25T14:12:50Z

for echo 'fn main() {}' | RUSTC_PROGRESS=1 rustc - it now doesn't show any spinner at all.

probably because it finishes in under 100ms 😆 so it never gets rendered

oli-obk · 2023-07-25T14:13:58Z

Tried it on cranelift-codegen and almost all of the time it only shows analysis as only spinner and the spinner itself doesn't spin most of the time and at the end it leaves behind the ⠄ analysis of the spinner

I never tested it with cargo. There may be collisions with cargo's own output

bjorn3 · 2023-07-25T14:35:38Z

It doesn't seem to show up at all with cargo, so I had to manually run the command that cargo would run. It also seems to have some issues when diagnostics get printed.

bjorn3 · 2023-07-25T14:37:38Z

for echo 'fn main() {}' | RUSTC_PROGRESS=1 rustc - it now doesn't show any spinner at all.

probably because it finishes in under 100ms laughing so it never gets rendered

Maybe a snapshot of the current queries every 100ms would be more useful? Or showing repeated invocations of the same query if they add up to more than 100ms (so eg the typeck query will show up even if every every individual function gets typechecked in 99ms)

oli-obk · 2023-07-25T15:01:43Z

It doesn't seem to show up at all with cargo, so I had to manually run the command that cargo would run. It also seems to have some issues when diagnostics get printed.

yes, I'm refactoring some stuff to get rid of the issue around diagnostics and other rustc output: #114054

oli-obk · 2023-07-26T09:04:57Z

Maybe a snapshot of the current queries every 100ms would be more useful?

that's what happens

Or showing repeated invocations of the same query if they add up to more than 100ms (so eg the typeck query will show up even if every every individual function gets typechecked in 99ms)

That's a different territory that I want to do later. Basically accumulate -Ztime-passes style information live instead of printing the information later.

bjorn3 · 2023-07-26T14:46:36Z

Maybe a snapshot of the current queries every 100ms would be more useful?

that's what happens

Why does it not show any queries besides analysis then for the entire time? The odds of every single 100ms snapshot of a 10+ second compilation containing no queries besides analysis is extremely low, right?

bjorn3 · 2023-07-26T14:47:04Z

Or showing repeated invocations of the same query if they add up to more than 100ms (so eg the typeck query will show up even if every every individual function gets typechecked in 99ms)

That's a different territory that I want to do later. Basically accumulate -Ztime-passes style information live instead of printing the information later.

👍

oli-obk · 2023-07-26T14:52:04Z

Why does it not show any queries besides analysis then for the entire time? The odds of every single 100ms snapshot of a 10+ second compilation containing no queries besides analysis is extremely low, right?

Ah I missed something here. You should not really see anything for hello world, as it's too fast. Longer builds should show a nice stack where stuff spins. If the spinner isn't running at all, something is very wrong. I am seeing it work locally for a test with a long running const evaluation. Maybe your build is really fast in rustc and just takes a long time in codegen?

bjorn3 · 2023-07-26T15:06:39Z

Maybe your build is really fast in rustc and just takes a long time in codegen?

According to -Zself-profile analysis took 34s on cranelift_codegen. This time I did see proc_macro_decls_static as sub query, but that one only takes 1.4s according to -Zself-profile and I saw it for several seconds. Also the analysis spinner was still shown (and not spinning at that time) while it was doing codegen. I saw the cursor move a couple of times, so indicatif was still redrawing.

bors · 2023-08-07T02:16:56Z

☔ The latest upstream changes (presumably #114565) made this pull request unmergeable. Please resolve the merge conflicts.

apiraino · 2023-08-24T10:25:24Z

Switching to waiting on author for a rebase and (I think) to address Qs in the latest comments. Feel free to request a review with @rustbot ready, thanks!

@rustbot author

rustbot · 2023-10-05T10:07:02Z

Third-party dependency whitelist may have been modified! You must ensure that any new dependencies have compatible licenses before merging.

cc @davidtwco, @wesleywiser

davidtwco · 2023-10-27T13:25:30Z

Third-party dependency whitelist may have been modified! You must ensure that any new dependencies have compatible licenses before merging.

cc @davidtwco, @wesleywiser

Licenses of all these dependencies seem good to me.

…ments

bors · 2024-02-14T08:04:39Z

☔ The latest upstream changes (presumably #120454) made this pull request unmergeable. Please resolve the merge conflicts.

oli-obk · 2024-03-14T16:38:06Z

I haven't found the motivation to work on this in 6 months, gonna accept I won't be finding it again any time soon

rustbot assigned bjorn3 Jul 20, 2023