Cargo no-op build time is huge

[matklad]

You can get some internal profiling metrics by running CARGO_PROFILE=1 cargo build. Here's what I get with 1.18.0 and with current stable:

$ 1.18.0
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
         11ms - resolving
              0ms - updating: registry https://github.com/rust-lang/crates.io-index
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
         11ms - resolving
              0ms - updating: registry https://github.com/rust-lang/crates.io-index
          0ms - resolving w/ overrides...
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
         11ms - resolving
              0ms - updating: registry https://github.com/rust-lang/crates.io-index
          0ms - resolving w/ overrides...
          4ms - resolving
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
         11ms - resolving
              0ms - updating: registry https://github.com/rust-lang/crates.io-index
          0ms - resolving w/ overrides...
          4ms - resolving
         59ms - compiling
              0ms - preparing layout
              0ms - preparing: rustraytracer v0.1.0 (file:///home/matklad/projects/rustraytracer)/rustraytracer
              0ms - preparing: regex v0.2.6/regex
              0ms - preparing: thread_local v0.3.5/thread_local
              0ms - preparing: unreachable v1.0.0/unreachable
              0ms - preparing: void v1.0.2/void
              0ms - preparing: lazy_static v1.0.0/lazy_static
              0ms - preparing: utf8-ranges v1.0.0/utf8-ranges
              0ms - preparing: memchr v2.0.1/memchr
              0ms - preparing: libc v0.2.36/libc
              0ms - preparing: regex-syntax v0.4.2/regex-syntax
              0ms - preparing: aho-corasick v0.6.4/aho_corasick
              0ms - preparing: rayon v1.0.0/rayon
              0ms - preparing: rayon-core v1.4.0/rayon-core
              0ms - preparing: rand v0.4.2/rand
              0ms - preparing: crossbeam-deque v0.2.0/crossbeam-deque
              0ms - preparing: crossbeam-utils v0.2.2/crossbeam-utils
              0ms - preparing: cfg-if v0.1.2/cfg-if
              0ms - preparing: crossbeam-epoch v0.3.0/crossbeam-epoch
              0ms - preparing: nodrop v0.1.12/nodrop
              0ms - preparing: arrayvec v0.4.7/arrayvec
              0ms - preparing: memoffset v0.2.1/memoffset
              0ms - preparing: lazy_static v0.2.11/lazy_static
              0ms - preparing: scopeguard v0.3.3/scopeguard
              0ms - preparing: num_cpus v1.8.0/num_cpus
              0ms - preparing: rayon-core v1.4.0/build-script-build
              0ms - preparing: rayon-core v1.4.0/build-script-build
              0ms - preparing: either v1.4.0/either
              0ms - preparing: utils v0.1.0 (file:///home/matklad/projects/rustraytracer/libs/utils)/utils
              0ms - preparing: time v0.1.39/time
              0ms - preparing: geom v0.1.0 (file:///home/matklad/projects/rustraytracer/libs/geom)/geom
              0ms - preparing: rustc-serialize v0.3.24/rustc-serialize
              0ms - preparing: rustraytracer v0.1.0 (file:///home/matklad/projects/rustraytracer)/rustraytracer
              1ms - executing the job graph

$ stable
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
         13ms - resolving
              0ms - updating: registry `https://github.com/rust-lang/crates.io-index`
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
         13ms - resolving
              0ms - updating: registry `https://github.com/rust-lang/crates.io-index`
          0ms - resolving w/ overrides...
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
         13ms - resolving
              0ms - updating: registry `https://github.com/rust-lang/crates.io-index`
          0ms - resolving w/ overrides...
          0ms - resolving
          0ms - updating: file:///home/matklad/projects/rustraytracer
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/geom
          0ms - updating: file:///home/matklad/projects/rustraytracer/libs/utils
         13ms - resolving
              0ms - updating: registry `https://github.com/rust-lang/crates.io-index`
          0ms - resolving w/ overrides...
          0ms - resolving
        169ms - compiling
              0ms - preparing layout
              0ms - preparing: rustraytracer v0.1.0 (file:///home/matklad/projects/rustraytracer)/rustraytracer
              0ms - preparing: utils v0.1.0 (file:///home/matklad/projects/rustraytracer/libs/utils)/utils
              0ms - preparing: rand v0.4.2/rand
              0ms - preparing: libc v0.2.36/libc
              0ms - preparing: time v0.1.39/time
              0ms - preparing: regex v0.2.6/regex
              0ms - preparing: memchr v2.0.1/memchr
              0ms - preparing: utf8-ranges v1.0.0/utf8-ranges
              0ms - preparing: regex-syntax v0.4.2/regex-syntax
              0ms - preparing: thread_local v0.3.5/thread_local
              0ms - preparing: lazy_static v1.0.0/lazy_static
              0ms - preparing: unreachable v1.0.0/unreachable
              0ms - preparing: void v1.0.2/void
              0ms - preparing: aho-corasick v0.6.4/aho_corasick
              0ms - preparing: geom v0.1.0 (file:///home/matklad/projects/rustraytracer/libs/geom)/geom
              0ms - preparing: rustc-serialize v0.3.24/rustc-serialize
              0ms - preparing: rayon v1.0.0/rayon
              0ms - preparing: either v1.4.0/either
              0ms - preparing: rayon-core v1.4.0/rayon-core
              0ms - preparing: crossbeam-deque v0.2.0/crossbeam-deque
              0ms - preparing: crossbeam-epoch v0.3.0/crossbeam-epoch
              0ms - preparing: memoffset v0.2.1/memoffset
              0ms - preparing: lazy_static v0.2.11/lazy_static
              0ms - preparing: cfg-if v0.1.2/cfg-if
              0ms - preparing: crossbeam-utils v0.2.2/crossbeam-utils
              0ms - preparing: arrayvec v0.4.7/arrayvec
              0ms - preparing: nodrop v0.1.12/nodrop
              0ms - preparing: scopeguard v0.3.3/scopeguard
              0ms - preparing: num_cpus v1.8.0/num_cpus
              0ms - preparing: rayon-core v1.4.0/build-script-build
              0ms - preparing: rayon-core v1.4.0/build-script-build
              0ms - preparing: rustraytracer v0.1.0 (file:///home/matklad/projects/rustraytracer)/rustraytracer
              0ms - executing the job graph

Looks like we've regressed pretty significantly over time :-(

[alexcrichton]

Is there a link as well to reproduce locally with?

[matklad]

I've just tried it on the canonical random project of mine, http://github.com/matklad/rustraytracer

[matklad]

So, even fresh "hello world" build is 180 ms

[matklad]

scrape_build_config takes 100ms

[matklad]

Originally I had a hypothesis that this might be a regression in rustup shims as well, but, because I use the same rustup to try 1.18.0, that hypothesis is probably wrong.

[matklad]

Hm, looks like a regression in rustc actually?

~/trash/foo master*
λ 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.02s user 0.01s system 98% cpu 0.035 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.10s user 0.01s system 90% cpu 0.124 total

[matklad]

And this is true even for rustc -vV

λ 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.11s user 0.01s system 98% cpu 0.128 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.03s user 0.01s system 98% cpu 0.047 total

[matklad]

opened rust-lang/rust#49761 at rustc =P

[alexcrichton]

Some discussion about this here: https://botbot.me/mozilla/cargo/2018-04-07/?msg=98731867&page=2

The tl;dr; is:

• Cargo's not 100% accurate with how it looks at rustc today, for example if you modify rustc itself without changing the version Cargo won't detect this.
• Instead of making rustc faster one option is to not run rustc at all, caching it for subsequent builds
• We can probably get away by looking at the mtime of rustc-the-executable and having special logic for rustup
  • Unclear how this affects custom toolchains in Cargo and whether it would cache appropriately