mir-opt tests extremely slow.

[eddyb]

test [mir-opt] mir-opt/combine_array_len.rs has been running for over 60 seconds
test [mir-opt] mir-opt/inline-closure-borrows-arg.rs has been running for over 60 seconds
test [mir-opt] mir-opt/inline-closure.rs has been running for over 60 seconds
test [mir-opt] mir-opt/inline-trait-method.rs has been running for over 60 seconds
test [mir-opt] mir-opt/inline-trait-method_2.rs has been running for over 60 seconds
test [mir-opt] mir-opt/issue-38669.rs has been running for over 60 seconds
test [mir-opt] mir-opt/issue-41110.rs has been running for over 60 seconds
test [mir-opt] mir-opt/issue-41697.rs has been running for over 60 seconds

@Mark-Simulacrum is it possible this is all time spent in compiletest processing the output?

cc @rust-lang/compiler @RalfJung

[eddyb]

I can't reproduce anymore, but I've seen this before (usually just one message).

[RalfJung]

Maybe #58103 made emitting all this MIR really slow?

[Zoxc]

I think these have been slow for quite a while though.

[eddyb]

mir-opt is now my main bottleneck in running the tests (if not for #54712 (comment), it would be the only bottleneck in the entire build+test process), these are the numbers:

Suite	Time (seconds)
mir-opt	76.182
codegen	2.291
codegen-units	0.531
incremental	7.362
pretty	0.823
ui	33.044
compile-fail	0.640
run-make	0.638
run-fail	2.130
run-pass	58.316

Bonus: I get these messages (which hint to the slowest of all mir-opt tests, although perhaps I would want the message to be configurable, I consider tests that take over 10 seconds "effectively broken"):

test [mir-opt] mir-opt/lower_128bit_debug_test.rs has been running for over 60 seconds
test [mir-opt] mir-opt/lower_128bit_test.rs has been running for over 60 seconds

[eddyb]

Nominating for discussion (specifically, investigating this) at the next @rust-lang/compiler team meeting.

[eddyb]

I wanted to try get warnings for 10s instead of 60s, but sadly, it's hardcoded into libtest:

rust/src/libtest/lib.rs

Line 75 in 3bee49f

const TEST_WARN_TIMEOUT_S: u64 = 60;

And because we build compiletest against downloaded libtest, I had to add (to compiletest's Cargo.toml) test = { path = "../../libtest" }, and comment out extern crate test;.

---

Here are the warnings for mir-opt (click to open)

test [mir-opt] mir-opt/basic_assignment.rs has been running for over 10 seconds
test [mir-opt] mir-opt/array-index-is-temporary.rs has been running for over 10 seconds
test [mir-opt] mir-opt/box_expr.rs has been running for over 10 seconds
test [mir-opt] mir-opt/combine_array_len.rs has been running for over 10 seconds
test [mir-opt] mir-opt/copy_propagation_arg.rs has been running for over 10 seconds
test [mir-opt] mir-opt/deaggregator_test.rs has been running for over 10 seconds
test [mir-opt] mir-opt/deaggregator_test_enum.rs has been running for over 10 seconds
test [mir-opt] mir-opt/deaggregator_test_enum_2.rs has been running for over 10 seconds
test [mir-opt] mir-opt/deaggregator_test_multiple.rs has been running for over 10 seconds
test [mir-opt] mir-opt/generator-drop-cleanup.rs has been running for over 10 seconds
test [mir-opt] mir-opt/inline-closure-borrows-arg.rs has been running for over 10 seconds
test [mir-opt] mir-opt/inline-any-operand.rs has been running for over 10 seconds
test [mir-opt] mir-opt/inline-retag.rs has been running for over 10 seconds
test [mir-opt] mir-opt/inline-closure.rs has been running for over 10 seconds
test [mir-opt] mir-opt/inline-trait-method.rs has been running for over 10 seconds
test [mir-opt] mir-opt/inline-trait-method_2.rs has been running for over 10 seconds
test [mir-opt] mir-opt/issue-41110.rs has been running for over 10 seconds
test [mir-opt] mir-opt/issue-41888.rs has been running for over 10 seconds
test [mir-opt] mir-opt/issue-41697.rs has been running for over 10 seconds
test [mir-opt] mir-opt/issue-49232.rs has been running for over 10 seconds
test [mir-opt] mir-opt/lower_128bit_test.rs has been running for over 10 seconds
test [mir-opt] mir-opt/lower_128bit_debug_test.rs has been running for over 10 seconds
test [mir-opt] mir-opt/match_false_edges.rs has been running for over 10 seconds
test [mir-opt] mir-opt/match_test.rs has been running for over 10 seconds
test [mir-opt] mir-opt/nll/region-subtyping-basic.rs has been running for over 10 seconds
test [mir-opt] mir-opt/remove_fake_borrows.rs has been running for over 10 seconds
test [mir-opt] mir-opt/packed-struct-drop-aligned.rs has been running for over 10 seconds
test [mir-opt] mir-opt/retag.rs has been running for over 10 seconds
test [mir-opt] mir-opt/simplify_if.rs has been running for over 10 seconds
test [mir-opt] mir-opt/simplify_match.rs has been running for over 10 seconds
test [mir-opt] mir-opt/storage_live_dead_in_statics.rs has been running for over 10 seconds
test [mir-opt] mir-opt/uniform_array_move_out.rs has been running for over 10 seconds
test [mir-opt] mir-opt/unusual-item-types.rs has been running for over 10 seconds

This is terrible: 33 out of 42 mir-opt tests take longer than 10 seconds.
And we haven't really noticed because of our (huge) minute-long warning delay.

The only other test suite that gets *any* warnings is run-pass (click to open)

test [run-pass] run-pass/issues/issue-29227.rs has been running for over 10 seconds
test [run-pass] run-pass/issues/issue-50811.rs has been running for over 10 seconds
test [run-pass] run-pass/mpsc_stress.rs has been running for over 10 seconds
test [run-pass] run-pass/numbers-arithmetic/saturating-float-casts.rs has been running for over 10 seconds
test [run-pass] run-pass/panic-runtime/lto-unwind.rs has been running for over 10 seconds
test [run-pass] run-pass/rustc-rust-log.rs has been running for over 10 seconds
test [run-pass] run-pass/stack-probes-lto.rs has been running for over 10 seconds

That's only 7 out of 2957, and some (all?) of those are intentional stress tests.

[eddyb]

One solution @oli-obk and I are considering is adding an analogue of LLVM's -print-{before,after}, but for MIR, and as an alternative to -Z dump-mir (which creates a directory with many files).
Then, we can mostly use UI tests instead of mir-opt.

[pnkfelix]

triage: It would be great to resolve this. It would also be great if all of our rustc developers had a -j48 machine so that we would all share the same problem here.

however, I think given the reality of our common-case hardware, I do not think this falls into the P-high prioritization bucket. (Again, I do want to resolve it. but I don't want to revisit it's status every week.)

So I'm going to assign this P-medium priority for now. (And leave it nominated for discussion at the meeting.)

[nikomatsakis]

Removing nomination since it's not clear what's left to discuss at the meeting.

[eddyb]

Not sure whether it's a change in the build server I'm using, or Rust itself, but while the other passes take more or less the same time, I've recently observed an increase in mir-opt times from 76s to 280s (and most, if not all of them, now warn about taking more than 60 seconds).

[eddyb]

Huh, I wanted to do some other testing and found these results for mir-opt:

-j	Time	> 60s
1	92s	0
4	94s	0
12	138s	3
24	178s	22
48	197s	49

That is, the more threads (forced with -jN), the longer the total time it is, and the more "running over 60 seconds" messages are printed. Keep in mind there's only 55 tests to begin with.

-j2 and -j3 seem to sometimes be lower than -j1 but are less reproducible (presumably because of which tests happen to overlap with which others?), so I didn't include them.

I wonder if it's caused a lot of contention, maybe IO (since -Zdump-mir writes a lot of files)?
The ui testsuite (including run-pass) still manages to run 8974 tests in 116s, so even if this machine has gotten a bit slower, mir-opt is disproportionately affected.

[eddyb]

Okay all that analysis was pointless except it led me to realize all of those rustc processes are producing likely millions of syscalls.

mir-opt takes only a couple seconds once it's buffered (PR up at #64344).