Rust: 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 https://github.com/rust-lang/rust/pull/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 https://github.com/rust-lang/rust/issues/54712#issuecomment-485656192, 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:
https://github.com/rust-lang/rust/blob/3bee49f42b6dfb039d2a8e59e5181e26531c3c11/src/libtest/lib.rs#L75

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.

[RalfJung]

Wow, how do you get such times? run-pass takes many minutes for me, that's like 3k tests or so?

[eddyb]

As I mentioned in https://github.com/rust-lang/rust/issues/54712#issuecomment-485656192, this is a -j48 machine.

[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).