Regression in compile time when optimizing for size

[crawford]

After updating to Rust 1.57, I'm seeing a huge increase in compilation time for an embedded project that I'm working on. The code is unfortunately not open source, but I'm hoping I can provide enough information here to work around that. If I've forgotten to include anything or made bad assumptions, please let me know.

I don't have specific numbers for the slowdown because I haven't waiting long enough for the compilation to finish, but I can say that what used to take ~90 seconds for a full build is now taking more than 10 minutes. The project targets thumbv7em-none-eabihf and is optimized for size. Here are the profiles defined in the cargo manifest:

[profile.dev]
panic = "abort"
codegen-units = 1
debug = true
opt-level = "s"
lto = false

[profile.release]
panic = "abort"
codegen-units = 1
debug = true
lto = true
opt-level = "s"

Here's the interesting thing: we have seen no increase in compilation time when building the main binary. It's the tests that are actually exhibiting the behavior. The tests target x86_64-unknown-linux-gnu and are built with cargo test. If I remove opt-level = "s" from the profiles, I'm able to build the tests just as quickly as before.

I bisected the nightlies and determined that this slowdown seems to have been introduced into nightly-2021-10-14; nightly-2021-10-13 and 1.56.1 don't exhibit this behavior.

[camelid]

I bisected the nightlies and determined that this slowdown seems to have been introduced into nightly-2021-10-14; nightly-2021-10-13 and 1.56.1 don't exhibit this behavior.

@crawford could you use cargo-bisect-rustc to try to bisect to an exact commit? You'll probably want to use the --prompt flag.

[hkratz]

Or the new --timeout flag

    -t, --timeout <timeout>
            Assume failure after specified number of seconds (for bisecting hangs)

[crawford]

@camelid I gave that a shot last night, but I was having trouble getting it to run correctly. Your suggestion to use --prompt allowed me to figure out what was going wrong, so thank you! (I'm surprised -v doesn't print the cargo output)

@hkratz I'm on NixOS, which requires some patching of binaries before they can be run, so (long story short) I'm using an older pre-built version which doesn't have the timeout flag. I do have the timeout program though. I'm looking forward to being able to use the timeout flag directly!

Thank you for both of your suggestions. I'm really glad I was able to get this running on my system. What a fantastic tool!

Here's the output (regression in ef4b306):

********************************************************************************
Regression in ef4b3069baafa75bc047a80b58cc130e80576a4e
********************************************************************************

searched nightlies: from nightly-2021-10-13 to nightly-2021-10-14
regressed nightly: nightly-2021-10-14
searched commits: from https://github.com/rust-lang/rust/commit/d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c to https://github.com/rust-lang/rust/commit/dfc5add915e8bf4accbb7cf4de00351a7c6126a1
regressed commit: https://github.com/rust-lang/rust/commit/ef4b3069baafa75bc047a80b58cc130e80576a4e

[camelid]

cc @the8472

[the8472]

No concrete idea, just stabs in the dark:

Since this is optimization-level dependent I suspect LLVM is going crazy somewhere. This should be testable with -Z time-passes or -Z self-profile

The added inline annotation itself shouldn't cause rustc to generate massive amounts of additional IR, I think. Unless maybe the code somehow contains many more &mut Iterator types than Iterator types, e.g. via &mut &mut &mut Iterator chains? This should be testable with llvm-lines

Edit: Another possibility is that your test cases contain some code triggering pathological behavior while the release build doesn't.

Here's the interesting thing: we have seen no increase in compilation time when building the main binary. It's the tests that are actually exhibiting the behavior. The tests target x86_64-unknown-linux-gnu and are built with cargo test.

The profiles differ in the lto flag. Does lto = true make a different for the tests?

Edit: Additionally they also differ in the defaulted incremental parameter, so that needs to be checked too.

If I remove opt-level = "s" from the profiles, I'm able to build the tests just as quickly as before.

That covers s and 0 (default for dev). Have you also tried other opt levels? z, 1, 2, 3?

[apiraino]

@crawford something that could also help diagnose the issue is an MCVE (which I understand might not be easily isolated from a closed-source project)

@rustbot label +E-needs-mcve

[crawford]

Hmmm, I'm not sure what happened in my test, but I must have set the timeout too low. It also occurred to me that sccache may have been influencing my tests, so I went ahead and temporarily disabled that. I've re-run the bisection numerous times with varying timeouts (mostly to try to reproduce the original result, but to no avail) and I'm seeing a different result from what I had originally reported:

********************************************************************************
Regression in a16f686e4a0ea15dcd3b5aa3db7b1cba27bb9453
********************************************************************************

searched nightlies: from nightly-2021-10-13 to nightly-2021-10-14
regressed nightly: nightly-2021-10-14
searched commits: from https://github.com/rust-lang/rust/commit/d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c to https://github.com/rust-lang/rust/commit/dfc5add915e8bf4accbb7cf4de00351a7c6126a1
regressed commit: https://github.com/rust-lang/rust/commit/a16f686e4a0ea15dcd3b5aa3db7b1cba27bb9453

So it looks like a16f686 is actually the culprit. Sorry for the false alarm, @the8472.

In the meantime, I let a full build finish (it took 10m 10s) and it resulted in a test binary that is 1.5 GB in size! For comparison, the test binary without optimization is 11 MB.

I also tried altering the optimization levels (LTO is disabled in all of these) and found that 2, 3, s, and z all trigger the slowdown.

[camelid]

So it looks like a16f686 is actually the culprit.

Hmm, it's possible, but it seems quite unlikely to me that that's the cause.

[wtfsck]

I'm also getting a16f686 as the culprit but I agree it doesn't look like the correct commit since it's cargo related.

cargo-bisect-rustc also said these regressed

• RESULT: dfc5add, ===> Yes
• RESULT: 5728bd6, ===> Yes

Full output:

installing nightly-2021-10-13
cargo for x86_64-unknown-linux-gnu: 6.23 MB / 6.23 MB
testing...
RESULT: nightly-2021-10-13, ===> No

installing nightly-2021-10-14
cargo for x86_64-unknown-linux-gnu: 6.25 MB / 6.25 MB
testing...
RESULT: nightly-2021-10-14, ===> Yes

searched toolchains nightly-2021-10-13 through nightly-2021-10-14
installing nightly-2021-10-14
testing...


********************************************************************************
Regression in nightly-2021-10-14
********************************************************************************

fetching https://static.rust-lang.org/dist/2021-10-13/channel-rust-nightly-git-commit-hash.txt
nightly manifest 2021-10-13: 40 B / 40 B
converted 2021-10-13 to d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c
fetching https://static.rust-lang.org/dist/2021-10-14/channel-rust-nightly-git-commit-hash.txt
nightly manifest 2021-10-14: 40 B / 40 B
converted 2021-10-14 to dfc5add915e8bf4accbb7cf4de00351a7c6126a1
looking for regression commit between 2021-10-13 and 2021-10-14
refreshing repository at "/a/b/rust"
From https://github.com/rust-lang/rust
 * branch                    HEAD       -> FETCH_HEAD
opening existing repository at "/a/b/rust"
fetching (via local git) commits from d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c to dfc5add915e8bf4accbb7cf4de00351a7c6126a1
refreshing repository at "/a/b/rust"
From https://github.com/rust-lang/rust
 * branch                    HEAD       -> FETCH_HEAD
opening existing repository at "/a/b/rust"
looking up first commit
looking up second commit
checking that commits are by bors and thus have ci artifacts...
finding bors merge commits
found 7 bors merge commits in the specified range
  commit[0] 2021-10-12UTC: Auto merge of #89105 - DevinR528:reachable-fix, r=Nadrieril
  commit[1] 2021-10-12UTC: Auto merge of #89774 - the8472:inline-mut-iter-next, r=m-ou-se
  commit[2] 2021-10-13UTC: Auto merge of #89802 - ehuss:update-cargo, r=ehuss
  commit[3] 2021-10-13UTC: Auto merge of #89587 - camelid:all-candidates, r=petrochenkov
  commit[4] 2021-10-13UTC: Auto merge of #89847 - JohnTitor:rollup-xfymeo4, r=JohnTitor
  commit[5] 2021-10-13UTC: Auto merge of #89822 - tmiasko:overflap-duplicates, r=cjgillot
  commit[6] 2021-10-13UTC: Auto merge of #89555 - oli-obk:nll_member_constraint_diag, r=estebank
validated commits found, specifying toolchains

installing d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c
cargo for x86_64-unknown-linux-gnu: 6.23 MB / 6.23 MB
testing...
RESULT: d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c, ===> No

installing dfc5add915e8bf4accbb7cf4de00351a7c6126a1
cargo for x86_64-unknown-linux-gnu: 6.25 MB / 6.25 MB
testing...
RESULT: dfc5add915e8bf4accbb7cf4de00351a7c6126a1, ===> Yes

installing 5728bd64b49b0e78d0180efed75ef0870ae60266
cargo for x86_64-unknown-linux-gnu: 6.25 MB / 6.25 MB
testing...
RESULT: 5728bd64b49b0e78d0180efed75ef0870ae60266, ===> Yes

installing ef4b3069baafa75bc047a80b58cc130e80576a4e
cargo for x86_64-unknown-linux-gnu: 6.23 MB / 6.23 MB
testing...
RESULT: ef4b3069baafa75bc047a80b58cc130e80576a4e, ===> No

installing a16f686e4a0ea15dcd3b5aa3db7b1cba27bb9453
cargo for x86_64-unknown-linux-gnu: 6.25 MB / 6.25 MB
testing...
RESULT: a16f686e4a0ea15dcd3b5aa3db7b1cba27bb9453, ===> Yes

searched toolchains d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c through dfc5add915e8bf4accbb7cf4de00351a7c6126a1


********************************************************************************
Regression in a16f686e4a0ea15dcd3b5aa3db7b1cba27bb9453
********************************************************************************

==================================================================================
= Please file this regression report on the rust-lang/rust GitHub repository     =
=        New issue: https://github.com/rust-lang/rust/issues/new                 =
=     Known issues: https://github.com/rust-lang/rust/issues                     =
= Copy and paste the text below into the issue report thread.  Thanks!           =
==================================================================================

searched nightlies: from nightly-2021-10-13 to nightly-2021-10-14
regressed nightly: nightly-2021-10-14
searched commit range: https://github.com/rust-lang/rust/compare/d7c97a02d1215e4ef26c31cb72dbaf16fd548b2c...dfc5add915e8bf4accbb7cf4de00351a7c6126a1
regressed commit: https://github.com/rust-lang/rust/commit/a16f686e4a0ea15dcd3b5aa3db7b1cba27bb9453

[camelid]

cargo-bisect-rustc also said these regressed

FWIW, that doesn't mean those commits regressed; it just means the regression was present in them. I.e., it very well may have occurred before them.

[wtfsck]

This seems to be cargo related. I've copied cargo 1.56.1 to stable (1.57.0) and after that it compiles as fast as before.

I can only reproduce it when building with --release.

Seems to be rust-lang/cargo#9943

[hkratz]

@wtfsck Could you run cargo build --release -v once with 1.57.0 + cargo 1.57.0 and once with 1.57.0 + cargo 1.56.1 and compare the rustc invocations? That should give us some clue what's going on.

[wtfsck]

@hkratz It was cargo test --release. Seems like cargo 1.56.1 and earlier ignored [profile.release] (if cargo test --release) but 1.57.0 uses it. Removing --release and adding a new [profile.test] fixes it for me.

[apiraino]

@crawford checking in about this issue. Did you have a chance to try the new stable 1.58? There are substancial improvement in the compile time (can't say, though, if they apply to your codebase)

[crawford]

@apiraino Sorry I disappeared after initially filing the issue. I haven't had much time to revisit this to help narrow it down. I just gave 1.58 a try and am still seeing the slowdown when optimizing for size. My current workaround is still functional though:

[profile.test]
opt-level = 0

[apiraino]

Assigning priority as discussed in the Zulip thread of the Prioritization Working Group.

@rustbot label -I-prioritize +P-medium

[kpreid]

@rustbot label +S-needs-repro -E-needs-mcve