Substantial debug-test-optimized-depedencies Performance Regression in 1.59

[TheBlueMatt]

We were trying to change our Cargo.toml to

[profile.dev.package."*"]
opt-level = 2

to get opt on our dependencies during test but not on the crate being tested. In rustc 1.58.1, this is a performance improvement in the generated test suite. On rustc 1.59.0 this is a very substantial regression in total runtime of tests (~2 minutes CPU time on 1.58.1 to 18 minutes CPU time, not including compile time). This effect is robust with different opt-levels (swapping the 1s and 2s above) and between Debian rustc and rustup rustc.

The increase in CPU time seems to almost all be in std/core, perf on the regressed binary for a single test (similar results for all tests) shows the following, but core itself doesn't show up at all in perf on 1.58.1.

+   26.40%    24.37%  ln::functional_  lightning-8c1dd3bce02d4ddc   [.] core::ptr::mut_ptr::<impl *mut T>::is_null
+   25.79%    23.79%  ln::functional_  lightning-8c1dd3bce02d4ddc   [.] <core::slice::iter::IterMut<T> as core::iter::traits::iterator::Iterator>::next
+   23.12%    21.85%  ln::functional_  lightning-8c1dd3bce02d4ddc   [.] core::ptr::mut_ptr::<impl *mut T>::guaranteed_eq
+   11.31%    10.16%  ln::functional_  lightning-8c1dd3bce02d4ddc   [.] std::io::readbuf::ReadBuf::initialize_unfilled_to
+    9.80%     6.16%  ln::functional_  lightning-8c1dd3bce02d4ddc   [.] core::ptr::non_null::NonNull<T>::as_ptr
+    8.65%     6.89%  ln::functional_  lightning-8c1dd3bce02d4ddc   [.] core::ptr::metadata::from_raw_parts_mut
+    2.46%     2.45%  ln::functional_  lightning-8c1dd3bce02d4ddc   [.] core::ptr::non_null::NonNull<T>::new_unchecked

This effect is also robust against -Zbuild-std=panic_abort (and ps aux confirms that core is getting built with opt-level=2) and even RUSTFLAGS="-C prefer-dynamic" (which ldd confirms dynamically links libstd+libtest).

The PR to do this on our repo is at lightningdevkit/rust-lightning#1497 which you should be able to simply check out locally and cargo test with 1.58 and 1.59 (well, run it twice to skip the compile part of the test) to see the regression. Specific numbers at #97460 (comment).

For those reading the comments there was some confusion about the cargo 1.57 change on the test profile, you can skip to #97460 (comment)

@rustbot modify labels: +regression-from-stable-to-stable -regression-untriaged

[wesleywiser]

[profile.dev]
opt-level = 1

Sets the rustc -Copt-level=1 flag when compiling your dependencies as well as your crate.

[profile.dev.package."*"]
opt-level = 2

Sets the rustc -Copt-level=2 flag when compiling only your dependencies, leaving your crate built with -Copt-level=0.

[TheBlueMatt]

Sets the rustc -Copt-level=1 flag when compiling your dependencies as well as your crate.

So this changed in cargo/rustc 1.59?

[TheBlueMatt]

Sets the rustc -Copt-level=1 flag when compiling your dependencies as well as your crate.

Also, this doesn't match ps aux output during build - on 1.58.1 and 1.59 I show no opt-level argument passed to rustc at all for the --test build.

[TheBlueMatt]

So this changed in cargo/rustc 1.59?

To answer my own question, yes, this changed in 1.59, dev now passes opt-level=1 to rustc on 1.59 on the --test build. That said, it doesn't address the point here - opt-level=0 (looking at rustc calls, at least) on 1.58 led to substantially more performant code.

[TheBlueMatt]

(FWIW this does match my observation that rustc 1.59 [dev] opt-level=1 runs much faster than 1.58 [dev] opt-level=1, but it seems there's no option to get back to the performance/compile-time tradeoffs we had at 1.58)

[wesleywiser]

So this changed in cargo/rustc 1.59?

I'm not aware of any changes to rustc or cargo in the 1.59 release that would have an effect here. (You can find the list of PRs that landed in 1.59 for both projects here and here)

Also, this doesn't match ps aux output during build - on 1.58.1 and 1.59 I show no opt-level argument passed to rustc at all for the --test build.

I see this with Rust 1.59:

$ cat Cargo.toml
[package]
name = "hello_world"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]

[profile.dev]
opt-level = 1

$ strace -e execve -f -- cargo +1.59 test
...
[pid 12014] execve("/home/wesley/.rustup/toolchains/1.59-x86_64-unknown-linux-gnu/bin/rustc", ["/home/wesley/.rustup/toolchains/"..., "--crate-name", "hello_world", "--edition=2021", "src/main.rs", "--error-format=json", "--json=diagnostic-rendered-ansi,"..., "--emit=dep-info,link", "-C", "opt-level=1", "-C", "embed-bitcode=no", "-C", "debuginfo=2", "-C", "debug-assertions=on", "--test", "-C", "metadata=79aa5460ab0a171e", "-C", "extra-filename=-79aa5460ab0a171e", "--out-dir", "/tmp/hello_world/target/debug/de"..., "-C", "incremental=/tmp/hello_world/tar"..., "-L", "dependency=/tmp/hello_world/targ"...], 0x56026762fa60 /* 52 vars */) = 0
...

Which shows -Copt-level=1 being passed to the compiler.

I see the same on 1.58 as well

$ strace -e fork,execve -f -- cargo +1.58 test
...
[pid 12093] execve("/home/wesley/.rustup/toolchains/1.58-x86_64-unknown-linux-gnu/bin/rustc", ["/home/wesley/.rustup/toolchains/"..., "--crate-name", "hello_world", "--edition=2021", "src/main.rs", "--error-format=json", "--json=diagnostic-rendered-ansi", "--emit=dep-info,link", "-C", "opt-level=1", "-C", "embed-bitcode=no", "-C", "debuginfo=2", "-C", "debug-assertions=on", "--test", "-C", "metadata=5eb06840b766433d", "-C", "extra-filename=-5eb06840b766433d", "--out-dir", "/tmp/hello_world/target/debug/de"..., "-C", "incremental=/tmp/hello_world/tar"..., "-L", "dependency=/tmp/hello_world/targ"...], 0x556798a2b0c0 /* 52 vars */) = 0
...

Edit: I realized that is 1.58.1 but I see the same thing on 1.58.0 and 1.57.

[TheBlueMatt]

Grrrrrrr I'm so sorry, I was looking at the wrong version, the regression was between 1.56 and 1.58, let me go test now.

[wesleywiser]

1.57 contained the Cargo "named profiles" feature (rust-lang/cargo#9943) which notes:

The test profile now inherits settings from the dev profile (and bench from release).

From what I'm seeing, prior to 1.57, the above Cargo.toml has no effect on cargo test.

Edit: Another interesting note from that PR:

Artifacts may no longer be shared in some circumstances. This can lead to substantially increased target directory sizes (and build times), particularly if the test profile is not the same as the dev profile. Previously, dependencies would use the dev profile for both. If the user wants to retain the old behavior, they can use an override like [profile.test.package."*"] and set the same settings as dev.

[TheBlueMatt]

Ah, right, so that makes sense. That doesn't, however, explain why tests got so much slower on 1.59. Ran some numbers with dev-1 and dev.package.*-2:

dev-1 with cargo/rustc 1.56: 2m55 user
dev.package.*-2 with carg/rustc 1.57: 2m15 user
dev.package.*-2 with cargo/rustc 1.58.1: 2m17 user
dev.package.*-2 with cargo/rustc 1.59.0: 15m51 user

[wesleywiser]

dev.package.-2 with cargo/rustc 1.58.1: 2m17 user
dev.package.-2 with cargo/rustc 1.59.0: 15m51 user

This is way more than the 25% regression in core::ptr::mut_ptr::<impl *mut T>::is_null your profile found. Is there a chance what we're actually seeing is a change in build time? Could you post the results of cargo +1.58.1 test -vv and cargo +1.59.0 test -vv?

[TheBlueMatt]

In all the above results that's a second run of cargo test after the first, it was also observed by two of my colleagues in lightningdevkit/rust-lightning#1497

That's why my initial response was to -Zbuild-std but that didn't change anything :(

[TheBlueMatt]

Sorry, the above profile was a bit confusing - on the 1.58.1 build core/std stuff doesn't show up in perf at all - on 1.59.0 its ~90% of runtime, if you total the second column above.

[TheBlueMatt]

Updated the issue description to remove all the stuff about dev-1 and the stuff that was just the cargo change, leaving only the parts talking about the dev.package.* opt-leve=2 runtime regression.

[workingjubilee]

Tagging this as medium priority because it is such a large regression if correct, but in a less-common combination of compiler settings, so something going awry is both expected but also it going this awry is surprising.