Possible rustc build time regression between 2017-04-14 and 2017-06-21 with CARGO_INCREMENTAL=1 and --release

[MaikKlein]

I created an repository to recreate this issue https://github.com/MaikKlein/regression/tree/59cab5ac57a668d52d33fa1e9ebca4c0b6fc9c3b

rustc --version --verbose
rustc 1.20.0-nightly (622e7e648 2017-06-21)
binary: rustc
commit-hash: 622e7e6487b6fb7fdbb901720cd4214f9179ed67
commit-date: 2017-06-21
host: x86_64-unknown-linux-gnu
release: 1.20.0-nightly
LLVM version: 4.0

CARGO_INCREMENTAL=1 cargo build --release
Finished release [optimized] target(s) in 471.63 sec

rustc --version --verbose
rustc 1.18.0-nightly (bbdaad0dc 2017-04-14)
binary: rustc
commit-hash: bbdaad0dc8dc64e036ccee817f90a91876b32a9d
commit-date: 2017-04-14
host: x86_64-unknown-linux-gnu
release: 1.18.0-nightly
LLVM version: 3.9

CARGO_INCREMENTAL=1 cargo build --release
Finished release [optimized] target(s) in 85.78 secs

I am on Ubuntu 16.04 x64.

[MaikKlein]

I added -Z time-passes output into the git repository

https://github.com/MaikKlein/regression/blob/master/output-04-14

and

https://github.com/MaikKlein/regression/blob/master/output-06-21

Here seems to be the problem

2017-06-21

  time: 5.723; rss: 499MB	llvm function passes [0]
  time: 385.102; rss: 475MB	llvm module passes [0]
  time: 22.069; rss: 462MB	codegen passes [0]
  time: 0.001; rss: 462MB	codegen passes [0]
time: 413.558; rss: 462MB	LLVM passes

[eddyb]

cc @michaelwoerister

[nagisa]

Make sure it is not fixed by #42771

[MaikKlein]

@nagisa

rustc --version --verbose
rustc 1.20.0-nightly (ab5bec255 2017-06-22)
binary: rustc
commit-hash: ab5bec25530aac43dfd64384b405c909b6e405e3
commit-date: 2017-06-22
host: x86_64-unknown-linux-gnu
release: 1.20.0-nightly
LLVM version: 4.0

This should contain #42771

CARGO_INCREMENTAL=1 cargo build --release
 Finished release [optimized] target(s) in 346.4 secs

Down from 471 seconds to 346 seconds.

[michaelwoerister]

I suspect this is because of rust-lang/cargo#4065 which makes cargo compile crates.io crates non-incrementally. The time-passes logs show many codegen units for the older toolchain and just one for the newer version.

The reasoning behind this change is that we don't need to compile things from crates.io incrementally because they don't change. That way you get a high-performance binary without impacting the ability to build your local code incrementally. When you run cargo clean though, you probably have to recompile those crates.io crates again.

@rust-lang/cargo, is there a way to keep crates.io dependencies around when doing a cargo clean?

[michaelwoerister]

I opened rust-lang/cargo#4234 in relation to this.

[michaelwoerister]

rust-lang/cargo#4234 has been merged. Care to give it another try with the latest Cargo, @MaikKlein?

[MaikKlein]

@michaelwoerister It is much better now.

Finished release [optimized] target(s) in 147.29 secs

Although I am not sure about the multi threading. I know gnome-system-monitor is not the most reliable tool but this is what the compilation looks. https://i.imgur.com/qyHaC5f.png

rustc --version --verbose
rustc 1.20.0-nightly (2fbba5bdb 2017-07-04)
binary: rustc
commit-hash: 2fbba5bdbadeef403a64e9e1568cdad225cbcec1
commit-date: 2017-07-04
host: x86_64-unknown-linux-gnu
release: 1.20.0-nightly
LLVM version: 4.0

cargo --version --verbose
cargo 0.21.0-nightly (eb6cf012a 2017-07-02)
release: 0.21.0
commit-hash: eb6cf012a6cc23c9c89c4009564de9fccc38b9cb
commit-date: 2017-07-02

[michaelwoerister]

Although I am not sure about the multi threading.

Does the graph stay that way? Only the LLVM part is multi-threaded, so the other cores can only be used towards the end of compilation. On the other hand, if this is a build with full re-use, then the LLVM part is skipped entirely and you won't see any multi-threading.

[MaikKlein]

@michaelwoerister I am doing cargo clean before I build.

I watched it now a couple of times and it only uses multiple cores in the beginning. After around 60s only one core is at 100% for the rest of the compilation. (see the image above)

Are there any good tools to record data for cpu usage? I looked at top but that isn't really readable.

[MaikKlein]

@michaelwoerister I actually also compiled it on Windows 10 because I am running an older kernel on linux but I see exactly the same behavior.

Only ~8% of my CPU is being used.

[michaelwoerister]

@MaikKlein, I just tried it myself and the problem seems to be that one of the codegen units in the gltf crate ends up being disproportionally more expensive to optimize than all the other codegen units. So while n-1 of the n codegens are already finished, everything sits waiting for another minute until that one core/codegen unit is done too.

[michaelwoerister]

Here's the relevant -Ztime-passes output:

  time: 0.141; rss: 488MB	llvm function passes [7]
  time: 0.185; rss: 496MB	llvm function passes [4]
  time: 0.205; rss: 500MB	llvm function passes [5]
  time: 0.286; rss: 504MB	llvm function passes [2]
  time: 0.300; rss: 507MB	llvm function passes [3]
  time: 0.359; rss: 508MB	llvm function passes [6]
  time: 0.461; rss: 510MB	llvm function passes [8]
  time: 0.903; rss: 521MB	llvm module passes [7]
  time: 1.186; rss: 529MB	llvm module passes [5]
  time: 1.577; rss: 535MB	llvm module passes [2]
  time: 0.793; rss: 533MB	codegen passes [7]
  time: 0.001; rss: 530MB	codegen passes [0]
  time: 0.938; rss: 536MB	codegen passes [5]
  time: 2.196; rss: 535MB	llvm module passes [4]
  time: 0.889; rss: 543MB	codegen passes [2]
  time: 2.542; rss: 543MB	llvm module passes [3]
  time: 0.881; rss: 546MB	codegen passes [4]
  time: 3.185; rss: 553MB	llvm module passes [8]
  time: 0.809; rss: 551MB	codegen passes [3]
  time: 4.082; rss: 554MB	llvm function passes [1]
  time: 4.402; rss: 560MB	llvm module passes [6]
  time: 1.293; rss: 560MB	codegen passes [8]
  time: 1.075; rss: 560MB	codegen passes [6]
  time: 65.189; rss: 609MB	llvm module passes [1]      <----------------- !!!
  time: 12.557; rss: 601MB	codegen passes [1]

[MaikKlein]

@michaelwoerister That makes sense, I guess this issue can be closed now?

[michaelwoerister]

Thanks for the report!