25% regression in serde compile time

[dtolnay]

I narrowed this down to 1699293...c284f88. To reproduce:

rustup update nightly-2017-12-24 nightly-2017-12-25
git clone https://github.com/serde-rs/serde
cd serde/serde
git checkout v1.0.27
cargo update
cargo clean && time cargo +nightly-2017-12-24 build
cargo clean && time cargo +nightly-2017-12-25 build

For me nightly-2017-12-24 takes 7.4 seconds and nightly-2017-12-25 takes 9.2 seconds.

[arielb1]

A not-too-deep check reveals that trait selection might have slowed down. Seriously? (I didn't track it down to that commit, should probably bisect it to a single commit in that range).

[nikomatsakis]

triage: P-high

Good to know what happened.

[nikomatsakis]

I'll try to bisect.

[nikomatsakis]

Curious. I was not able to reproduce when building those commits from scratch, though I did see the perf difference with the nightly builds. I'll double-check. It could have to do with some of my config.toml options (e.g., debuginfo or debug-assertions), but that seems a bit surprising.

[nikomatsakis]

I tried with no config.toml at all and still got basically the same timing for those two commits: 11.6s in both cases.

[nikomatsakis]

cc @rust-lang/compiler -- can someone else try to reproduce from source?

[Zoxc]

I also built these two revisions from source. Both of my builds have the same timing of ~40 seconds for cargo build -j1. This is the same result as nightly-2017-12-25, while nightly-2017-12-24 builds in ~30 seconds.

[nikomatsakis]

@Zoxc thanks! Not entirely sure what to make of that.

[nikomatsakis]

cc @rust-lang/infra -- can we try using the PR-by-PR builds to narrow this down further or gain some insight? I'm not sure how to access those.

[kennytm]

@nikomatsakis The problem isn't in rustc, but cargo. Note that starting from Dec 25 cargo passes -C incremental=... to rustc. This means the regression is introduced by rust-lang/cargo#4817 or some other PRs between rust-lang/cargo@930f9d9...e08f310.

~/serde ((v1.0.27)):160$ cargo clean && time cargo +nightly-2017-12-24 build -vv
   Compiling serde v1.0.27 (file:///~/serde/serde)
     Running `rustc --crate-name serde src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 --cfg 'feature="default"' --cfg 'feature="std"' -C metadata=7c335e5d4a9ee66d -C extra-filename=-7c335e5d4a9ee66d --out-dir /~/serde/target/debug/deps -L dependency=/~/serde/target/debug/deps`
    Finished dev [unoptimized + debuginfo] target(s) in 9.50 secs

real	0m9.752s
user	0m9.463s
sys	0m0.409s

~/serde ((v1.0.27)):161$ cargo clean && time cargo +nightly-2017-12-25 build -vv
   Compiling serde v1.0.27 (file:///~/serde/serde)
     Running `rustc --crate-name serde serde/src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 --cfg 'feature="default"' --cfg 'feature="std"' -C metadata=633312819f55a634 -C extra-filename=-633312819f55a634 --out-dir /~/serde/target/debug/deps -C incremental=/~/serde/target/debug/incremental -L dependency=/~/serde/target/debug/deps`
    Finished dev [unoptimized + debuginfo] target(s) in 12.42 secs

real	0m13.098s
user	0m11.421s
sys	0m0.814s

~/serde ((v1.0.27)):162$ cargo clean && time cargo +16992930835ce3376a4aaed42307726e1fc78e45 build -vv
   Compiling serde v1.0.27 (file:///~/serde/serde)
     Running `rustc --crate-name serde serde/src/lib.rs --crate-type lib --emit=dep-info,link -C debuginfo=2 --cfg 'feature="default"' --cfg 'feature="std"' -C metadata=7a2f2aaec6829696 -C extra-filename=-7a2f2aaec6829696 --out-dir /~/serde/target/debug/deps -C incremental=/~/serde/target/debug/incremental -L dependency=/~/serde/target/debug/deps`
    Finished dev [unoptimized + debuginfo] target(s) in 12.82 secs

real	0m13.442s
user	0m11.809s
sys	0m0.781s

Edit: Disabling incremental with CARGO_INCREMENTAL=0 does bring down the build time from ~11s to ~9s.

[dtolnay]

Is 25% within the expected range of slowdown from incremental compilation on a clean build?

[nikomatsakis]

@dtolnay unknown, but it seems worth optimizing!

Question: what happens on subsequent compiles?

[nikomatsakis]

OK, so, here are latest measurements:

Nightly	cargo clean && cargo build	touch src/lib.rs && cargo build
2017-12-24	9.82	9.82
2017-12-25	11.63	4.35
2018-01-15	11.5	4.23
2018-01-20	11.28	4.15
2018-01-23	11.48	4.22
2018-01-25	10.57	4.12
2018-02-02	10.59	4.4
2018-02-04	10.70	4.3
2018-02-05	9.84	3.75
2018-02-07	9.77	3.73

Seems like something changed in between 2018-02-04 and 2018-02-05.

[nikomatsakis]

Could be disabling ThinLTO?

[nikomatsakis]

In any case, the regression appears to be gone, in an absolute sense. A quick glance at the profiles suggested we are spending a lot of time hashing, but I'd have to do a custom build with framepointers to get real data. I'm inclined to close this, though.

[nikomatsakis]

(It could well be that ThinLTO was making hashing etc add a lot more overhead than it otherwise should.)

[nikomatsakis]

triage: P-medium

Priority is not so hot. @michaelwoerister is going to do some final investigation and decide whether to close or what.

[pnkfelix]

triage: @michaelwoerister will confirm that build times are back to normal. If so, he will close as "not a regression" (or at least no longer a regression...)

[michaelwoerister]

I did some measurements with the current nightly and the versions from the OP:

> cargo clean && cargo build

2017-12-24 - 6.92 secs
2017-12-25 - 8.49 secs
2018-03-06 - 7.11 secs

This confirms that a default build has gotten slower between the first two nightlies and then faster again. However, I think, the slowdown is due to incremental compilation becoming the default between the two nightlies. Forcing incremental compilation to off shows that there little difference between them, and that the compiler has actually become a bit faster since:

> cargo clean && CARGO_INCREMENTAL=0 cargo build

2017-12-24 - 6.89 secs
2017-12-25 - 6.83 secs
2018-03-06 - 6.10 secs

Vice versa, forcing incr. comp. to on shows little difference between the December nightlies and that incr. comp. especially has become faster:

> cargo clean && CARGO_INCREMENTAL=1 cargo build

2017-12-24 - 8.57 secs
2017-12-25 - 8.46 secs
2018-03-06 - 7.12 secs

Hopefully you'll also see a benefit from incr. comp.:

touch src/lib.rs && cargo build
2017-12-24 - 6.85 secs
2017-12-25 - 3.54 secs
2018-03-06 - 2.94 secs

I think this explains the build time regression between the two nightlies. It is expected that clean incremental builds are slower. For the Dec 25 nightly the overhead is ~24% in my measurements, for the current nightly its ~16%. Hopefully we can bring this down further in the future.