Running `rustc -vV` is slow

[matklad]

Hi! At Cargo, we are observing a regression in no-op builds from 1.18.0 to current stable. Looks like a significant portion of slowness can be attributed to regression in rustc itself. In particular, Cargo invokes

rustc -vV

and

rustc --crate-name ___ --print=file-names --crate-type bin --crate-type rlib --crate-type dylib --crate-type cdylib --crate-type staticlib --crate-type proc-macro --print=sysroot --print=cfg

commands, and they both appear to have become significantly slower over time:

~/trash/foo master*
λ time rustc +stable -Vv
rustc 1.25.0 (84203cac6 2018-03-25)
binary: rustc
commit-hash: 84203cac67e65ca8640b8392348411098c856985
commit-date: 2018-03-25
host: x86_64-unknown-linux-gnu
release: 1.25.0
LLVM version: 6.0
rustc +stable -Vv  0.10s user 0.01s system 90% cpu 0.126 total

~/trash/foo master*
λ time rustc +1.18.0 -Vv
rustc 1.18.0 (03fc9d622 2017-06-06)
binary: rustc
commit-hash: 03fc9d622e0ea26a3d37f5ab030737fcca6928b9
commit-date: 2017-06-06
host: x86_64-unknown-linux-gnu
release: 1.18.0
LLVM version: 3.9
rustc +1.18.0 -Vv  0.04s user 0.01s system 99% cpu 0.047 total

λ time rustc +stable x --crate-name ___ --print=file-names --crate-type bin --crate-type rlib --crate-type dylib --crate-type cdylib --crate-type staticlib --crate-type proc-macro --print=sysroot --print=cfg
___
lib___.rlib
lib___.so
lib___.so
lib___.a
lib___.so
/home/matklad/.rustup/toolchains/stable-x86_64-unknown-linux-gnu
debug_assertions
proc_macro
target_arch="x86_64"
target_endian="little"
target_env="gnu"
target_family="unix"
target_os="linux"
target_pointer_width="64"
unix
rustc +stable x --crate-name ___ --print=file-names --crate-type bin  rlib     0.09s user 0.01s system 88% cpu 0.105 total

λ time rustc +1.18.0 x --crate-name ___ --print=file-names --crate-type bin --crate-type rlib --crate-type dylib --crate-type cdylib --crate-type staticlib --crate-type proc-macro --print=sysroot --print=cfg
___
lib___.rlib
lib___.so
lib___.so
lib___.a
lib___.so
/home/matklad/.rustup/toolchains/1.18.0-x86_64-unknown-linux-gnu
debug_assertions
proc_macro
target_arch="x86_64"
target_endian="little"
target_env="gnu"
target_family="unix"
target_os="linux"
target_pointer_width="64"
unix
rustc +1.18.0 x --crate-name ___ --print=file-names --crate-type bin  rlib     0.03s user 0.01s system 99% cpu 0.039 total

[est31]

There is tons of noise but you can see that it's gotten a bit better since:

$ time rustc +1.25.0 -vV
rustc 1.25.0 (84203cac6 2018-03-25)
binary: rustc
commit-hash: 84203cac67e65ca8640b8392348411098c856985
commit-date: 2018-03-25
host: x86_64-unknown-linux-gnu
release: 1.25.0
LLVM version: 6.0

real    0m0,096s
user    0m0,073s
sys     0m0,004s
$ time rustc +1.25.0 -vV
rustc 1.25.0 (84203cac6 2018-03-25)
binary: rustc
commit-hash: 84203cac67e65ca8640b8392348411098c856985
commit-date: 2018-03-25
host: x86_64-unknown-linux-gnu
release: 1.25.0
LLVM version: 6.0

real    0m0,074s
user    0m0,074s
sys     0m0,000s
$ time rustc +1.35.0 -vV
rustc 1.35.0 (3c235d560 2019-05-20)
binary: rustc
commit-hash: 3c235d5600393dfe6c36eeed34042efad8d4f26e
commit-date: 2019-05-20
host: x86_64-unknown-linux-gnu
release: 1.35.0
LLVM version: 8.0

real    0m0,033s
user    0m0,033s
sys     0m0,000s
$ time rustc +1.35.0 -vV
rustc 1.35.0 (3c235d560 2019-05-20)
binary: rustc
commit-hash: 3c235d5600393dfe6c36eeed34042efad8d4f26e
commit-date: 2019-05-20
host: x86_64-unknown-linux-gnu
release: 1.35.0
LLVM version: 8.0

real    0m0,046s
user    0m0,028s
sys     0m0,000s
$ time rustc -vV
rustc 1.44.1 (c7087fe00 2020-06-17)
binary: rustc
commit-hash: c7087fe00d2ba919df1d813c040a5d47e43b0fe7
commit-date: 2020-06-17
host: x86_64-unknown-linux-gnu
release: 1.44.1
LLVM version: 9.0

real    0m0,034s
user    0m0,006s
sys     0m0,012s
$ time rustc -vV
rustc 1.44.1 (c7087fe00 2020-06-17)
binary: rustc
commit-hash: c7087fe00d2ba919df1d813c040a5d47e43b0fe7
commit-date: 2020-06-17
host: x86_64-unknown-linux-gnu
release: 1.44.1
LLVM version: 9.0

real    0m0,018s
user    0m0,005s
sys     0m0,013s

Compare that to cargo (also has tons of noise, sometimes it's as much as 20 ms):

$ time cargo --version
cargo 1.44.1 (88ba85757 2020-06-11)

real    0m0,005s
user    0m0,000s
sys     0m0,005s

strace rustc -vV 2>&1 | wc -l tells me there are 412 syscalls issued, while cargo --version only issues 334 syscalls.

[bjorn3]

For me rustc + rustup wrapper takes 100ms:

Benchmark 1: rustc -vV
  Time (mean ± σ):      93.8 ms ±   1.2 ms    [User: 81.5 ms, System: 12.2 ms]
  Range (min … max):    92.7 ms …  98.2 ms    30 runs

Rustc without rustup wrapper takes 13ms:

Benchmark 1: /home/bjorn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc -vV
  Time (mean ± σ):      13.2 ms ±   0.7 ms    [User: 6.5 ms, System: 6.7 ms]
  Range (min … max):    12.5 ms …  17.9 ms    161 runs

A no-op cargo check on the rust repo gives:

Benchmark 1: cargo check
  Time (mean ± σ):     249.6 ms ±   4.2 ms    [User: 216.4 ms, System: 32.9 ms]
  Range (min … max):   244.6 ms … 257.9 ms    12 runs

Without rustup wrapper it gives:

Benchmark 1: /home/bjorn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/cargo check
  Time (mean ± σ):     163.2 ms ±   0.5 ms    [User: 136.7 ms, System: 26.3 ms]
  Range (min … max):   162.3 ms … 164.0 ms    18 runs

I think the rustc side of this issue is fixed. Only the rustup (rust-lang/rustup#2626) and cargo (rust-lang/cargo#5315) parts are still pending.