"x.py check" that does nothing feels like it has gotten slower

[RalfJung]

When working on the UI test suite, it is common to hit Ctrl-S in the IDE and then quickly switch to a terminal to run the test. Since RA triggers a check-on-save, this means that the tests can only start running once the check-build is completed. However, since nothing in the compiler changed, this check-build should be completed very quickly.

However, some time recently this seems to have gotten significantly slower. I now usually have to wait for multiple seconds before a test build can start, which was not the case in the past. This is on a system with an NVMe SSD and a pretty good CPU (pretty good for a laptop, anyway) -- it should be plenty fast enough for this.

To reproduce, run ./x check compiler, wait until it is completed, and then run time ./x check compiler. The result is:

$ time ./x check compiler
Building bootstrap
    Finished `dev` profile [unoptimized] target(s) in 0.27s
Checking stage0 library artifacts (x86_64-unknown-linux-gnu)
    Finished `release` profile [optimized + debuginfo] target(s) in 0.14s
Checking stage0 compiler artifacts {rustc-main, rustc_abi, rustc_arena, rustc_ast, rustc_ast_ir, rustc_ast_lowering, rustc_ast_passes, rustc_ast_pretty, rustc_attr, rustc_baked_icu_data, rustc_borrowck, rustc_builtin_macros, rustc_codegen_llvm, rustc_codegen_ssa, rustc_const_eval, rustc_data_structures, rustc_driver, rustc_driver_impl, rustc_error_codes, rustc_error_messages, rustc_errors, rustc_expand, rustc_feature, rustc_fluent_macro, rustc_fs_util, rustc_graphviz, rustc_hir, rustc_hir_analysis, rustc_hir_pretty, rustc_hir_typeck, rustc_incremental, rustc_index, rustc_index_macros, rustc_infer, rustc_interface, rustc_lexer, rustc_lint, rustc_lint_defs, rustc_llvm, rustc_log, rustc_macros, rustc_metadata, rustc_middle, rustc_mir_build, rustc_mir_dataflow, rustc_mir_transform, rustc_monomorphize, rustc_next_trait_solver, rustc_parse, rustc_parse_format, rustc_passes, rustc_pattern_analysis, rustc_privacy, rustc_query_impl, rustc_query_system, rustc_resolve, rustc_sanitizers, rustc_serialize, rustc_session, rustc_smir, rustc_span, rustc_symbol_mangling, rustc_target, rustc_trait_selection, rustc_traits, rustc_transmute, rustc_ty_utils, rustc_type_ir, rustc_type_ir_macros, stable_mir} (x86_64-unknown-linux-gnu)
    Finished `release` profile [optimized + debuginfo] target(s) in 1.70s
Build completed successfully in 0:00:05

real    0m5,650s
user    0m5,324s
sys 0m0,334s

As you can see, there are less than 2s spent inside cargo. And yet overall this took more than 5s. This means that bootstrap spent 3s doing... something? Whatever it did takes two times longer than cargo took to verify that the entire compiler sources remain unchanged.

Would be nice to find a way to speed that up. :) Cc @rust-lang/bootstrap

[Kobzol]

It takes ~1s on my laptop. Have you tried running git gc?

[RalfJung]

That does help quite a bit, thanks for the hint:

$ time ./x check compiler
Building bootstrap
    Finished `dev` profile [unoptimized] target(s) in 0.13s
Checking stage0 library artifacts (x86_64-unknown-linux-gnu)
    Finished `release` profile [optimized + debuginfo] target(s) in 0.07s
Checking stage0 compiler artifacts {rustc-main, rustc_abi, rustc_arena, rustc_ast, rustc_ast_ir, rustc_ast_lowering, rustc_ast_passes, rustc_ast_pretty, rustc_attr, rustc_baked_icu_data, rustc_borrowck, rustc_builtin_macros, rustc_codegen_llvm, rustc_codegen_ssa, rustc_const_eval, rustc_data_structures, rustc_driver, rustc_driver_impl, rustc_error_codes, rustc_error_messages, rustc_errors, rustc_expand, rustc_feature, rustc_fluent_macro, rustc_fs_util, rustc_graphviz, rustc_hir, rustc_hir_analysis, rustc_hir_pretty, rustc_hir_typeck, rustc_incremental, rustc_index, rustc_index_macros, rustc_infer, rustc_interface, rustc_lexer, rustc_lint, rustc_lint_defs, rustc_llvm, rustc_log, rustc_macros, rustc_metadata, rustc_middle, rustc_mir_build, rustc_mir_dataflow, rustc_mir_transform, rustc_monomorphize, rustc_next_trait_solver, rustc_parse, rustc_parse_format, rustc_passes, rustc_pattern_analysis, rustc_privacy, rustc_query_impl, rustc_query_system, rustc_resolve, rustc_sanitizers, rustc_serialize, rustc_session, rustc_smir, rustc_span, rustc_symbol_mangling, rustc_target, rustc_trait_selection, rustc_traits, rustc_transmute, rustc_ty_utils, rustc_type_ir, rustc_type_ir_macros, stable_mir} (x86_64-unknown-linux-gnu)
    Finished `release` profile [optimized + debuginfo] target(s) in 0.80s
Build completed successfully in 0:00:02

real    0m2,800s
user    0m2,559s
sys 0m0,240s

Still, ~68% of the runtime of this command are spent in bootstrap, not in cargo.

[Kobzol]

Could you please generate a flamegraph of this invocation? There is a perf command for gathering the trace shown here: https://github.com/rust-lang/rust/issues/126423#issue-2351827621 Or you can use e.g. https://github.com/flamegraph-rs/flamegraph or https://github.com/mstange/samply.