rustbuild is 1.4 times slower than make at building and testing

[petrochenkov]

Build everything (without LLVM):

Build system	Target	Time	Penalty
make	make -j8	17m56.338s	0%
rustbuild	../x.py build -j8	24m42.664s	+38%

Build stage 1 and test something (without LLVM):

Build system	Target	Time	Penalty
make	make check-stage1-rpass -j8	10m22.479s	0%
rustbuild	../x.py test --stage 1 src/test/run-pass -j8	14m20.133s	+38%

Default build config + enabled ninja were used in both cases.

cc @alexcrichton

[petrochenkov]

There's also huge regression in building/testing time caused by not running stage2 tests and build for stage2-stuff-required-only-for-plugins in parallel.
Both actions are independent and take a lot of time (roughly the same amount) and performed simultaneously in the old build system given enough HW parallelism is available. rustbuild performs them in sequence effectively doubling the time required for building/testing stage2.

In addition, the build system itself (src/bootstrap) is compiled without optimizations, but I'm not sure it affects anything noticeably.

[alexcrichton]

This certainly comes as a surprise to me, fundamentally there's virtually no difference between rustbuild and the makefiles in how crates are compiled or sequenced. Could you gist full logs of the rustbuild build (which has timings) and help gather timing data related to the makefile build as well? That'd help diagnose this issue and see what's going on.

It's true that tests aren't run as parallel as they were before, although I wouldn't expect that to cause such a large difference in time.

I don't believe compiling src/bootstrap with optimizations will help at all, I've tested it historically and it was basically just as fast.

[petrochenkov]

I'll try to do some more detailed measurements during the week, but my first impression was that something was under-parallelized, either due to bad dependency graph or some other reasons.

[petrochenkov]

-j1 performance for stage 1 testing:

Build system	Target	Time, Run 1/2/3	Penalty, Run 1/2/3
make	make check-stage1-pfail -j1	12m44.359s / 12m54.642s / 13m2.230s	0%
rustbuild	../x.py test --stage 1 src/test/parse-fail -j1	14m32.663s / 14m48.467s / 14m54.922s	+14% / +15% / +14%

This means something not related to parallelism is in play as well.
Here's list of crates that are built by rustbuild, but not built by make:

Building stage0 std artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
   Compiling build_helper v0.1.0 (file:///C:/msys64/home/we/rust/src/build_helper) <- part of rustbuild itself
   Compiling gcc v0.3.38 <- part of rustbuild itself
   Compiling std_shim v0.1.0 (file:///C:/msys64/home/we/rust/src/rustc/std_shim) <- part of rustbuild itself
Building stage0 test artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
   Compiling test_shim v0.1.0 (file:///C:/msys64/home/we/rust/src/rustc/test_shim) <- part of rustbuild itself
Building stage0 compiler artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
   Compiling build_helper v0.1.0 (file:///C:/msys64/home/we/rust/src/build_helper) <- part of rustbuild itself
   Compiling gcc v0.3.38 <- part of rustbuild itself
   Compiling rustdoc v0.0.0 (file:///C:/msys64/home/we/rust/src/librustdoc) <- why?
Building stage1 std artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
   Compiling gcc v0.3.38 <- part of rustbuild itself
   Compiling build_helper v0.1.0 (file:///C:/msys64/home/we/rust/src/build_helper) <- part of rustbuild itself
   Compiling std_shim v0.1.0 (file:///C:/msys64/home/we/rust/src/rustc/std_shim) <- part of rustbuild itself
Building stage1 test artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
   Compiling test_shim v0.1.0 (file:///C:/msys64/home/we/rust/src/rustc/test_shim) <- part of rustbuild itself
Building stage1 tool compiletest (x86_64-pc-windows-gnu)
   Compiling log v0.0.0 (file:///C:/msys64/home/we/rust/src/liblog) <- building log second time
   Compiling serialize v0.0.0 (file:///C:/msys64/home/we/rust/src/libserialize) <- building serialize second time
   Compiling log v0.3.6 <- building log third time, now from crates.io
   Compiling env_logger v0.3.5 <- ?

[petrochenkov]

Is there a way to tell cargo to report build times for each crate?

[petrochenkov]

According to -Z time-passes everything except for rustdoc is cheap, maybe ~5 seconds in total, or even less.
rustdoc is heavy - 45 seconds.
Still not clear where the remaining minute came from.

+ total build times reported by rustbuild, not especially informative:

Building stage0 std artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
    Finished release [optimized] target(s) in 121.77 secs
Building stage0 test artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
    Finished release [optimized] target(s) in 8.52 secs
Building stage0 compiler artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
    Finished release [optimized] target(s) in 576.56 secs
Building stage1 std artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
    Finished release [optimized] target(s) in 125.42 secs
Building stage1 test artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
    Finished release [optimized] target(s) in 8.14 secs
Building stage1 tool compiletest (x86_64-pc-windows-gnu)
    Finished release [optimized] target(s) in 14.1 secs

Sum of the above times: 854.5 seconds, total time 872.5 seconds (i.e. 18 seconds spent on running pfail tests, syncronizing submodules and doing other infra).

[alexcrichton]

Thanks for the info! Most of those extra crates should be quite small and not take any time at all to compile (except rustdoc).

I wonder, how long does the submodule management take locally? That's something I've seen take quite awhile and the makefiles only do it on ./configure whereas rustbuild does it on each run. Maybe that's another case for timing?

Unfortunately I don't know of a way to get Cargo to print out per-crate timings, or at least not a built-in method. A change to src/bootstrap/rustc.rs may do the trick though.

[petrochenkov]

I wonder, how long does the submodule management take locally?

3-4 seconds maybe, not something to worry about.

Unfortunately I don't know of a way to get Cargo to print out per-crate timings, or at least not a built-in method. A change to src/bootstrap/rustc.rs may do the trick though.

Yeah, I'll modify rustc, or rustbuild, or whatever necessary to get these timings tomorrow. That extra minute should hide somewhere after all.

[petrochenkov]

Here are raw times in seconds for make check-stage1-pfail -j1 and ../x.py test --stage 1 src/test/parse-fail -j1 from modified rustc.
I did some minimal cleanup and made times relative to the start, but haven't analyzed anything yet.
-> means going into rustc, <- means going out of rustc.

make:

-> rustc 0 query_metadata
<- rustc 0 query_metadata
-> rustc 0 query_metadata
<- rustc 0 query_metadata
-> rustc 3 libcore/lib.rs
<- rustc 12 libcore/lib.rs
-> rustc 12 rtstartup/rsbegin.rs
<- rustc 12 rtstartup/rsbegin.rs
-> rustc 12 rtstartup/rsend.rs
<- rustc 12 rtstartup/rsend.rs
-> rustc 13 liblibc/src/lib.rs
<- rustc 13 liblibc/src/lib.rs
-> rustc 13 librand/lib.rs
<- rustc 14 librand/lib.rs
-> rustc 14 liballoc_system/lib.rs
<- rustc 15 liballoc_system/lib.rs
-> rustc 15 liballoc/lib.rs
<- rustc 15 liballoc/lib.rs
-> rustc 16 librustc_unicode/lib.rs
<- rustc 16 librustc_unicode/lib.rs
-> rustc 16 libcollections/lib.rs
<- rustc 18 libcollections/lib.rs
-> rustc 50 libcompiler_builtins/lib.rs
<- rustc 50 libcompiler_builtins/lib.rs
-> rustc 50 libpanic_abort/lib.rs
<- rustc 50 libpanic_abort/lib.rs
-> rustc 51 libunwind/lib.rs
<- rustc 51 libunwind/lib.rs
-> rustc 51 libpanic_unwind/lib.rs
<- rustc 51 libpanic_unwind/lib.rs
-> rustc 113 liballoc_jemalloc/lib.rs
<- rustc 113 liballoc_jemalloc/lib.rs
-> rustc 152 libstd/lib.rs
<- rustc 160 libstd/lib.rs
-> rustc 160 libgetopts/lib.rs
<- rustc 161 libgetopts/lib.rs
-> rustc 162 libterm/lib.rs
<- rustc 164 libterm/lib.rs
-> rustc 165 libtest/lib.rs
<- rustc 169 libtest/lib.rs
-> rustc 169 liblog/lib.rs
<- rustc 170 liblog/lib.rs
-> rustc 171 libserialize/lib.rs
<- rustc 174 libserialize/lib.rs
-> rustc 174 tools/compiletest/src/main.rs
<- rustc 182 tools/compiletest/src/main.rs
-> rustc 186 libarena/lib.rs
<- rustc 186 libarena/lib.rs
-> rustc 187 libflate/lib.rs
<- rustc 188 libflate/lib.rs
-> rustc 188 libgraphviz/lib.rs
<- rustc 188 libgraphviz/lib.rs
-> rustc 189 librustc_bitflags/lib.rs
<- rustc 189 librustc_bitflags/lib.rs
-> rustc 189 libsyntax_pos/lib.rs
<- rustc 190 libsyntax_pos/lib.rs
-> rustc 190 librustc_errors/lib.rs
<- rustc 195 librustc_errors/lib.rs
-> rustc 195 librustc_data_structures/lib.rs
<- rustc 196 librustc_data_structures/lib.rs
-> rustc 197 libsyntax/lib.rs
<- rustc 256 libsyntax/lib.rs
-> rustc 257 libfmt_macros/lib.rs
<- rustc 257 libfmt_macros/lib.rs
-> rustc 267 librustc_llvm/lib.rs
<- rustc 270 librustc_llvm/lib.rs
-> rustc 270 librustc_back/lib.rs
<- rustc 281 librustc_back/lib.rs
-> rustc 281 librustc_const_math/lib.rs
<- rustc 282 librustc_const_math/lib.rs
-> rustc 283 librustc/lib.rs
<- rustc 379 librustc/lib.rs
-> rustc 379 librustc_const_eval/lib.rs
<- rustc 389 librustc_const_eval/lib.rs
-> rustc 390 librustc_mir/lib.rs
<- rustc 407 librustc_mir/lib.rs
-> rustc 408 librustc_borrowck/lib.rs
<- rustc 423 librustc_borrowck/lib.rs
-> rustc 423 librustc_platform_intrinsics/lib.rs
<- rustc 428 librustc_platform_intrinsics/lib.rs
-> rustc 428 librustc_typeck/lib.rs
<- rustc 475 librustc_typeck/lib.rs
-> rustc 476 librustc_resolve/lib.rs
<- rustc 492 librustc_resolve/lib.rs
-> rustc 493 librustc_incremental/lib.rs
<- rustc 509 librustc_incremental/lib.rs
-> rustc 509 librustc_trans/lib.rs
<- rustc 546 librustc_trans/lib.rs
-> rustc 547 librustc_privacy/lib.rs
<- rustc 550 librustc_privacy/lib.rs
-> rustc 550 librustc_lint/lib.rs
<- rustc 556 librustc_lint/lib.rs
-> rustc 557 libproc_macro/lib.rs
<- rustc 558 libproc_macro/lib.rs
-> rustc 558 libsyntax_ext/lib.rs
<- rustc 576 libsyntax_ext/lib.rs
-> rustc 577 librustc_metadata/lib.rs
<- rustc 616 librustc_metadata/lib.rs
-> rustc 617 librustc_plugin/lib.rs
<- rustc 618 librustc_plugin/lib.rs
-> rustc 618 libproc_macro_tokens/lib.rs
<- rustc 619 libproc_macro_tokens/lib.rs
-> rustc 620 libproc_macro_plugin/lib.rs
<- rustc 622 libproc_macro_plugin/lib.rs
-> rustc 623 librustc_passes/lib.rs
<- rustc 630 librustc_passes/lib.rs
-> rustc 631 librustc_save_analysis/lib.rs
<- rustc 646 librustc_save_analysis/lib.rs
-> rustc 646 librustc_driver/lib.rs
<- rustc 679 librustc_driver/lib.rs
-> rustc 679 driver/driver.rs
<- rustc 679 driver/driver.rs
-> rustc 689 libcore/lib.rs
<- rustc 697 libcore/lib.rs
-> rustc 698 rtstartup/rsbegin.rs
<- rustc 698 rtstartup/rsbegin.rs
-> rustc 698 rtstartup/rsend.rs
<- rustc 698 rtstartup/rsend.rs
-> rustc 698 liblibc/src/lib.rs
<- rustc 698 liblibc/src/lib.rs
-> rustc 699 librand/lib.rs
<- rustc 699 librand/lib.rs
-> rustc 700 liballoc_system/lib.rs
<- rustc 700 liballoc_system/lib.rs
-> rustc 700 liballoc/lib.rs
<- rustc 701 liballoc/lib.rs
-> rustc 701 librustc_unicode/lib.rs
<- rustc 701 librustc_unicode/lib.rs
-> rustc 702 libcollections/lib.rs
<- rustc 704 libcollections/lib.rs
-> rustc 704 libcompiler_builtins/lib.rs
<- rustc 704 libcompiler_builtins/lib.rs
-> rustc 705 libpanic_abort/lib.rs
<- rustc 705 libpanic_abort/lib.rs
-> rustc 705 libunwind/lib.rs
<- rustc 705 libunwind/lib.rs
-> rustc 706 libpanic_unwind/lib.rs
<- rustc 706 libpanic_unwind/lib.rs
-> rustc 706 liballoc_jemalloc/lib.rs
<- rustc 706 liballoc_jemalloc/lib.rs
-> rustc 707 libstd/lib.rs
<- rustc 714 libstd/lib.rs
-> rustc 715 libterm/lib.rs
<- rustc 717 libterm/lib.rs
-> rustc 718 libgetopts/lib.rs
<- rustc 719 libgetopts/lib.rs
-> rustc 719 libtest/lib.rs
<- rustc 723 libtest/lib.rs
-> rustc 724 librustc_bitflags/lib.rs
<- rustc 724 librustc_bitflags/lib.rs

rustbuild:

-> rustbuild 0 start
-> rustc 1 query_metadata
<- rustc 1 query_metadata
-> rustc 7 rtstartup/rsbegin.rs
<- rustc 7 rtstartup/rsbegin.rs
-> rustc 7 rtstartup/rsend.rs
<- rustc 7 rtstartup/rsend.rs
-> rustc 7 rustc/libc_shim/build.rs
<- rustc 7 rustc/libc_shim/build.rs
-> rustc 7 libunwind/build.rs
<- rustc 7 libunwind/build.rs
-> rustc 7 libcore/lib.rs
<- rustc 16 libcore/lib.rs
-> rustc 16 librustc_unicode/lib.rs
<- rustc 16 librustc_unicode/lib.rs
-> rustc 16 librand/lib.rs
<- rustc 17 librand/lib.rs
-> rustc 17 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/gcc-0.3.38/src/lib.rs
<- rustc 20 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/gcc-0.3.38/src/lib.rs
-> rustc 20 libcompiler_builtins/build.rs
<- rustc 21 libcompiler_builtins/build.rs
-> rustc 25 libcompiler_builtins/lib.rs
<- rustc 25 libcompiler_builtins/lib.rs
-> rustc 25 liballoc/lib.rs
<- rustc 25 liballoc/lib.rs
-> rustc 25 libcollections/lib.rs
<- rustc 27 libcollections/lib.rs
-> rustc 27 build_helper/lib.rs
<- rustc 27 build_helper/lib.rs
-> rustc 27 libstd/build.rs
<- rustc 28 libstd/build.rs
-> rustc 28 liballoc_jemalloc/build.rs
<- rustc 29 liballoc_jemalloc/build.rs
-> rustc 126 rustc/libc_shim/../../liblibc/src/lib.rs
<- rustc 126 rustc/libc_shim/../../liblibc/src/lib.rs
-> rustc 126 libunwind/lib.rs
<- rustc 126 libunwind/lib.rs
-> rustc 126 liballoc_system/lib.rs
<- rustc 126 liballoc_system/lib.rs
-> rustc 126 libpanic_unwind/lib.rs
<- rustc 127 libpanic_unwind/lib.rs
-> rustc 127 liballoc_jemalloc/lib.rs
<- rustc 127 liballoc_jemalloc/lib.rs
-> rustc 127 libpanic_abort/lib.rs
<- rustc 127 libpanic_abort/lib.rs
-> rustc 127 libstd/lib.rs
<- rustc 135 libstd/lib.rs
-> rustc 135 rustc/std_shim/lib.rs
<- rustc 135 rustc/std_shim/lib.rs
-> rustc 135 libterm/lib.rs
<- rustc 137 libterm/lib.rs
-> rustc 137 libgetopts/lib.rs
<- rustc 138 libgetopts/lib.rs
-> rustc 138 libtest/lib.rs
<- rustc 142 libtest/lib.rs
-> rustc 142 rustc/test_shim/lib.rs
<- rustc 143 rustc/test_shim/lib.rs
-> rustc 143 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/gcc-0.3.38/src/lib.rs
<- rustc 146 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/gcc-0.3.38/src/lib.rs
-> rustc 146 librustc_platform_intrinsics/lib.rs
<- rustc 150 librustc_platform_intrinsics/lib.rs
-> rustc 150 liblog/lib.rs
<- rustc 151 liblog/lib.rs
-> rustc 151 libfmt_macros/lib.rs
<- rustc 152 libfmt_macros/lib.rs
-> rustc 152 libserialize/lib.rs
<- rustc 155 libserialize/lib.rs
-> rustc 155 librustc_bitflags/lib.rs
<- rustc 155 librustc_bitflags/lib.rs
-> rustc 155 build_helper/lib.rs
<- rustc 155 build_helper/lib.rs
-> rustc 155 librustc_llvm/build.rs
<- rustc 156 librustc_llvm/build.rs
-> rustc 156 libflate/build.rs
<- rustc 157 libflate/build.rs
-> rustc 157 libflate/lib.rs
<- rustc 157 libflate/lib.rs
-> rustc 163 libarena/lib.rs
<- rustc 164 libarena/lib.rs
-> rustc 164 librustc_data_structures/lib.rs
<- rustc 165 librustc_data_structures/lib.rs
-> rustc 165 libgraphviz/lib.rs
<- rustc 165 libgraphviz/lib.rs
-> rustc 165 librustdoc/build.rs
<- rustc 165 librustdoc/build.rs
-> rustc 167 librustc_llvm/lib.rs
<- rustc 171 librustc_llvm/lib.rs
-> rustc 171 libsyntax_pos/lib.rs
<- rustc 172 libsyntax_pos/lib.rs
-> rustc 172 librustc_errors/lib.rs
<- rustc 176 librustc_errors/lib.rs
-> rustc 176 libsyntax/lib.rs
<- rustc 235 libsyntax/lib.rs
-> rustc 235 libproc_macro/lib.rs
<- rustc 236 libproc_macro/lib.rs
-> rustc 236 libsyntax_ext/lib.rs
<- rustc 253 libsyntax_ext/lib.rs
-> rustc 254 librustc_back/lib.rs
<- rustc 264 librustc_back/lib.rs
-> rustc 264 libproc_macro_tokens/lib.rs
<- rustc 265 libproc_macro_tokens/lib.rs
-> rustc 265 librustc_const_math/lib.rs
<- rustc 266 librustc_const_math/lib.rs
-> rustc 266 librustc/lib.rs
<- rustc 361 librustc/lib.rs
-> rustc 361 librustc_incremental/lib.rs
<- rustc 377 librustc_incremental/lib.rs
-> rustc 377 librustc_const_eval/lib.rs
<- rustc 387 librustc_const_eval/lib.rs
-> rustc 387 librustc_trans/lib.rs
<- rustc 424 librustc_trans/lib.rs
-> rustc 424 librustc_save_analysis/lib.rs
<- rustc 439 librustc_save_analysis/lib.rs
-> rustc 439 librustc_privacy/lib.rs
<- rustc 442 librustc_privacy/lib.rs
-> rustc 442 librustc_resolve/lib.rs
<- rustc 459 librustc_resolve/lib.rs
-> rustc 459 librustc_passes/lib.rs
<- rustc 466 librustc_passes/lib.rs
-> rustc 466 librustc_mir/lib.rs
<- rustc 484 librustc_mir/lib.rs
-> rustc 484 librustc_borrowck/lib.rs
<- rustc 499 librustc_borrowck/lib.rs
-> rustc 499 librustc_typeck/lib.rs
<- rustc 545 librustc_typeck/lib.rs
-> rustc 545 librustc_lint/lib.rs
<- rustc 551 librustc_lint/lib.rs
-> rustc 551 librustc_metadata/lib.rs
<- rustc 590 librustc_metadata/lib.rs
-> rustc 590 librustc_plugin/lib.rs
<- rustc 592 librustc_plugin/lib.rs
-> rustc 592 libproc_macro_plugin/lib.rs
<- rustc 594 libproc_macro_plugin/lib.rs
-> rustc 594 librustc_driver/lib.rs
<- rustc 626 librustc_driver/lib.rs
-> rustc 626 librustdoc/lib.rs
<- rustc 671 librustdoc/lib.rs
-> rustc 671 rustc/rustc.rs
<- rustc 672 rustc/rustc.rs
-> rustc 672 rustc/rustdoc.rs
<- rustc 673 rustc/rustdoc.rs
-> rustc 673 rtstartup/rsbegin.rs
<- rustc 673 rtstartup/rsbegin.rs
-> rustc 673 rtstartup/rsend.rs
<- rustc 673 rtstartup/rsend.rs
-> rustc 673 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/gcc-0.3.38/src/lib.rs
<- rustc 676 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/gcc-0.3.38/src/lib.rs
-> rustc 676 rustc/libc_shim/build.rs
<- rustc 676 rustc/libc_shim/build.rs
-> rustc 676 libunwind/build.rs
<- rustc 676 libunwind/build.rs
-> rustc 676 libcompiler_builtins/build.rs
<- rustc 677 libcompiler_builtins/build.rs
-> rustc 681 libcore/lib.rs
<- rustc 690 libcore/lib.rs
-> rustc 690 librustc_unicode/lib.rs
<- rustc 690 librustc_unicode/lib.rs
-> rustc 690 libcompiler_builtins/lib.rs
<- rustc 690 libcompiler_builtins/lib.rs
-> rustc 690 librand/lib.rs
<- rustc 691 librand/lib.rs
-> rustc 691 build_helper/lib.rs
<- rustc 691 build_helper/lib.rs
-> rustc 691 libstd/build.rs
<- rustc 692 libstd/build.rs
-> rustc 692 liballoc_jemalloc/build.rs
<- rustc 693 liballoc_jemalloc/build.rs
-> rustc 791 liballoc/lib.rs
<- rustc 791 liballoc/lib.rs
-> rustc 791 libcollections/lib.rs
<- rustc 793 libcollections/lib.rs
-> rustc 793 rustc/libc_shim/../../liblibc/src/lib.rs
<- rustc 793 rustc/libc_shim/../../liblibc/src/lib.rs
-> rustc 793 liballoc_jemalloc/lib.rs
<- rustc 793 liballoc_jemalloc/lib.rs
-> rustc 793 libpanic_abort/lib.rs
<- rustc 793 libpanic_abort/lib.rs
-> rustc 793 liballoc_system/lib.rs
<- rustc 793 liballoc_system/lib.rs
-> rustc 793 libunwind/lib.rs
<- rustc 793 libunwind/lib.rs
-> rustc 793 libpanic_unwind/lib.rs
<- rustc 793 libpanic_unwind/lib.rs
-> rustc 794 libstd/lib.rs
<- rustc 801 libstd/lib.rs
-> rustc 801 rustc/std_shim/lib.rs
<- rustc 801 rustc/std_shim/lib.rs
-> rustc 802 libterm/lib.rs
<- rustc 804 libterm/lib.rs
-> rustc 804 libgetopts/lib.rs
<- rustc 805 libgetopts/lib.rs
-> rustc 805 libtest/lib.rs
<- rustc 809 libtest/lib.rs
-> rustc 809 rustc/test_shim/lib.rs
<- rustc 810 rustc/test_shim/lib.rs
-> rustc 810 liblog/lib.rs
<- rustc 811 liblog/lib.rs
-> rustc 811 tools/compiletest/build.rs
<- rustc 811 tools/compiletest/build.rs
-> rustc 811 libserialize/lib.rs
<- rustc 814 libserialize/lib.rs
-> rustc 814 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/log-0.3.6/src/lib.rs
<- rustc 814 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/log-0.3.6/src/lib.rs
-> rustc 814 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/env_logger-0.3.5/src/lib.rs
<- rustc 815 .cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/env_logger-0.3.5/src/lib.rs
-> rustc 815 tools/compiletest/src/main.rs
<- rustc 823 tools/compiletest/src/main.rs
<- rustbuild 830 end

[petrochenkov]

Analysis!

Time spent in rustc for each target, in seconds; sorted by difference between make and rustbuild; targets with difference <= 1 second are skipped

Target	make	rustbuild
librustdoc/lib.rs	0	45
.cargo/registry/src/github1.v50.ltd-1ecc6299db9ec823/gcc-0.3.38/src/lib.rs	0	9
libserialize/lib.rs	3	6
liballoc_jemalloc/build.rs	0	2
libstd/build.rs	0	2
libcompiler_builtins/build.rs	0	2
rustc/test_shim/lib.rs	0	2

Good news: rustbuild doesn't affect time spent in rustc! This is how it should be in theory, but you never know what to expect from Cargo.
Bad news: rustdoc is build in vain and eats a lot of time.
Bad news: gcc crate is not entirely free and is build thrice (!).

Time spent outside of rustc before each target, in seconds; sorted by difference between make and rustbuild; targets with difference <= 1 second are skipped; look at my previous message with raw times to interpret what "before target" means:

Target	make	rustbuild	notes
liballoc/lib.rs	0	98	jemalloc
rustc/libc_shim/../../liblibc/src/lib.rs	0	97	jemalloc
rtstartup/rsbegin.rs	1	6	syncronizing submodules
libarena/lib.rs	4	6	copying files around
librustc_bitflags/lib.rs	2	0
librustc_llvm/lib.rs	10	2	rustllvm
libcore/lib.rs	13	4	copying files around
libcompiler_builtins/lib.rs	32	4	compiler-rt
libstd/lib.rs	40	1	libbacktrace
liballoc_jemalloc/lib.rs	62	0	jemalloc

Good news: build infrastructure itself (Cargo + rustbuild) doesn't eat noticeable amount of time compared to make. I'm happy this is the case.
Good news: libbacktrace and compiler-rt disappear somewhere in rustbuild.
Bad news: Something shady happens with jemalloc, it is built twice and each build takes 1.5 times more time. In total jemalloc adds more than 2 minutes of build time compared to make.

Total times:
Time spent in rustc - before: 532s, after: 602s.
Time spent outside of rustc - before: 192s, after: 220s

[alexcrichton]

Thanks for the detailed analysis @petrochenkov! Definitely quite helpful.

From these numbers it looks like there's two lion's share items we can tackle:

1. Don't compile rustdoc in stage0 and stage1
2. Cache builds of jemalloc more aggressively

Jemalloc is definitely the easier of the two here. We unconditionally run configure and unconditionally run make, but we can likely just reuse the cached state from a previous build if it's not invalidated.

Rustdoc is a bit harder, unfortunately. The major thing here is we need to avoid compiling librustdoc. We could toy around with moving librustdoc to src/tools and compile it in a more on-demand basis, but I think I'd probably prefer to make it an optional dependency and only ever ask for rustc. On demand (in one-off fashions) we'd then ask for a rustdoc build.

I think that should cover almost everything, right? Or were there other pieces that were taking quite awhile?

[petrochenkov]

I think that should cover almost everything, right? Or were there other pieces that were taking quite awhile?

Yes, this should fix most of performance problems for stage 1 and -j1 - all the results are listed above, there shouldn't be other pieces.

[petrochenkov]

Closing in favor of #39505 and #39507.