How to identify relevant time-passes to crates

I'm trying to observe time spent across multiple passes while building my binary having lots of dependencies.

But the information is mixed up and cannot tag time-passes to relevant crate.

Below is the partial log

  Compiling proc-macro2 v1.0.86
   Compiling unicode-ident v1.0.12
   Compiling libc v0.2.158
   Compiling cfg-if v1.0.0
   Compiling autocfg v1.3.0
   Compiling serde v1.0.210
   Compiling memchr v2.7.4
   Compiling version_check v0.9.5
   Compiling once_cell v1.19.0
   Compiling log v0.4.22
   Compiling pin-project-lite v0.2.14
   Compiling itoa v1.0.11
time:   0.000; rss:   48MB ->   53MB (   +4MB)	crate_injection
time:   0.005; rss:   53MB ->   67MB (  +15MB)	expand_crate
time:   0.005; rss:   53MB ->   67MB (  +15MB)	macro_expand_crate
time:   0.002; rss:   67MB ->   71MB (   +4MB)	late_resolve_crate
time:   0.003; rss:   67MB ->   71MB (   +4MB)	resolve_crate
time:   0.001; rss:   71MB ->   75MB (   +3MB)	looking_for_entry_point
time:   0.002; rss:   71MB ->   75MB (   +3MB)	misc_checking_1
time:   0.001; rss:   75MB ->   79MB (   +4MB)	coherence_checking
time:   0.000; rss:   48MB ->   53MB (   +4MB)	crate_injection
time:   0.005; rss:   53MB ->   68MB (  +15MB)	expand_crate
time:   0.005; rss:   53MB ->   68MB (  +15MB)	macro_expand_crate
time:   0.002; rss:   68MB ->   71MB (   +4MB)	late_resolve_crate
time:   0.003; rss:   68MB ->   71MB (   +4MB)	resolve_crate
time:   0.007; rss:   53MB ->   62MB (   +9MB)	expand_crate
time:   0.007; rss:   48MB ->   62MB (  +13MB)	macro_expand_crate
time:   0.000; rss:   62MB ->   63MB (   +1MB)	finalize_macro_resolutions
time:   0.001; rss:   71MB ->   74MB (   +3MB)	looking_for_entry_point
time:   0.002; rss:   71MB ->   74MB (   +3MB)	misc_checking_1
time:   0.002; rss:   74MB ->   79MB (   +4MB)	coherence_checking
time:   0.003; rss:   62MB ->   63MB (   +1MB)	resolve_crate
time:   0.018; rss:   75MB ->   95MB (  +20MB)	type_check_crate
time:   0.000; rss:   48MB ->   53MB (   +4MB)	crate_injection
time:   0.001; rss:   48MB ->   57MB (   +9MB)	expand_crate
time:   0.001; rss:   63MB ->   66MB (   +3MB)	write_dep_info
time:   0.010; rss:   66MB ->   71MB (   +5MB)	looking_for_derive_registrar
time:   0.013; rss:   66MB ->   71MB (   +5MB)	misc_checking_1
time:   0.001; rss:   48MB ->   57MB (   +9MB)	macro_expand_crate
time:   0.000; rss:   57MB ->   61MB (   +4MB)	finalize_macro_resolutions
time:   0.000; rss:   57MB ->   61MB (   +4MB)	resolve_crate
time:   0.010; rss:   53MB ->   74MB (  +21MB)	expand_crate
time:   0.007; rss:   71MB ->   78MB (   +7MB)	coherence_checking
time:   0.000; rss:   61MB ->   66MB (   +4MB)	misc_checking_3
time:   0.010; rss:   53MB ->   74MB (  +21MB)	macro_expand_crate
time:   0.004; rss:   74MB ->   78MB (   +4MB)	late_resolve_crate
time:   0.005; rss:   74MB ->   78MB (   +4MB)	resolve_crate
time:   0.007; rss:   78MB ->   80MB (   +2MB)	looking_for_derive_registrar
time:   0.008; rss:   78MB ->   82MB (   +4MB)	misc_checking_1
time:   0.020; rss:   95MB ->  105MB (  +10MB)	MIR_borrow_checking
time:   0.003; rss:   74MB ->   80MB (   +6MB)	LLVM_passes
time:   0.000; rss:   66MB ->   80MB (  +15MB)	codegen_to_LLVM_IR
time:   0.016; rss:   66MB ->   80MB (  +15MB)	codegen_crate
time:   0.004; rss:   52MB ->   66MB (  +14MB)	expand_crate
time:   0.004; rss:   52MB ->   66MB (  +14MB)	macro_expand_crate
time:   0.001; rss:   80MB ->   77MB (   -4MB)	free_global_ctxt
time:   0.001; rss:   66MB ->   70MB (   +4MB)	late_resolve_crate
time:   0.001; rss:   66MB ->   70MB (   +4MB)	resolve_crate
time:   0.029; rss:   74MB ->  102MB (  +28MB)	type_check_crate
time:   0.000; rss:   77MB ->   77MB (   +0MB)	finish_ongoing_codegen
time:   0.000; rss:   77MB ->   77MB (   +0MB)	link_rlib
time:   0.001; rss:   77MB ->   77MB (   +0MB)	link_binary
time:   0.001; rss:   77MB ->   77MB (   +0MB)	link_crate
time:   0.001; rss:   77MB ->   77MB (   +0MB)	link
time:   0.034; rss:   33MB ->   73MB (  +41MB)	total
time:   0.001; rss:   70MB ->   74MB (   +4MB)	misc_checking_1
time:   0.000; rss:   74MB ->   78MB (   +4MB)	coherence_checking
time:   0.006; rss:  105MB ->  107MB (   +3MB)	MIR_effect_checking
   Compiling bytes v1.7.1
time:   0.031; rss:   71MB ->   92MB (  +21MB)	type_check_crate
time:   0.003; rss:   44MB ->   48MB (   +4MB)	parse_crate
time:   0.000; rss:   48MB ->   50MB (   +2MB)	setup_global_ctxt
time:   0.011; rss:   74MB ->   91MB (  +17MB)	type_check_crate
time:   0.025; rss:   82MB ->   98MB (  +16MB)	coherence_checking
time:   0.002; rss:   92MB ->   95MB (   +4MB)	monomorphization_collector_graph_walk
time:   0.009; rss:   91MB ->  101MB (   +9MB)	MIR_borrow_checking
time:   0.003; rss:   92MB ->   95MB (   +4MB)	generate_crate_metadata
time:   0.011; rss:   50MB ->   76MB (  +26MB)	expand_crate
time:   0.022; rss:  102MB ->  107MB (   +4MB)	MIR_borrow_checking
time:   0.011; rss:   50MB ->   76MB (  +26MB)	macro_expand_crate
time:   0.004; rss:   45MB ->   49MB (   +4MB)	parse_crate
time:   0.000; rss:   49MB ->   51MB (   +2MB)	setup_global_ctxt
time:   0.002; rss:  101MB ->  103MB (   +2MB)	MIR_effect_checking
time:   0.002; rss:   40MB ->   44MB (   +4MB)	parse_crate
time:   0.001; rss:   44MB ->   46MB (   +2MB)	setup_global_ctxt
time:   0.006; rss:   76MB ->   79MB (   +3MB)	late_resolve_crate
time:   0.008; rss:   76MB ->   79MB (   +3MB)	resolve_crate
time:   0.016; rss:   51MB ->   73MB (  +22MB)	expand_crate
time:   0.018; rss:   51MB ->   73MB (  +22MB)	macro_expand_crate
time:   0.007; rss:   46MB ->   68MB (  +22MB)	expand_crate
time:   0.008; rss:   46MB ->   68MB (  +22MB)	macro_expand_crate
time:   0.000; rss:   68MB ->   70MB (   +2MB)	finalize_macro_resolutions
time:   0.009; rss:   79MB ->   81MB (   +3MB)	looking_for_derive_registrar
time:   0.004; rss:   70MB ->   73MB (   +3MB)	late_resolve_crate
time:   0.005; rss:   68MB ->   73MB (   +5MB)	resolve_crate
time:   0.037; rss:  107MB ->  119MB (  +11MB)	monomorphization_collector_graph_walk
time:   0.013; rss:   79MB ->   81MB (   +3MB)	misc_checking_1
time:   0.006; rss:   51MB ->   60MB (  +10MB)	expand_crate
time:   0.007; rss:   51MB ->   60MB (  +10MB)	macro_expand_crate
time:   0.006; rss:   73MB ->   75MB (   +2MB)	looking_for_derive_registrar
time:   0.005; rss:  119MB ->  120MB (   +1MB)	partition_and_assert_distinct_symbols
time:   0.001; rss:   60MB ->   65MB (   +5MB)	late_resolve_crate
time:   0.007; rss:   73MB ->   75MB (   +2MB)	misc_checking_1
time:   0.002; rss:   60MB ->   65MB (   +5MB)	resolve_crate
time:   0.014; rss:   73MB ->   78MB (   +5MB)	late_resolve_crate
time:   0.017; rss:   73MB ->   78MB (   +5MB)	resolve_crate
time:   0.004; rss:   65MB ->   69MB (   +3MB)	looking_for_derive_registrar
time:   0.005; rss:   65MB ->   69MB (   +3MB)	misc_checking_1
time:   0.002; rss:   69MB ->   77MB (   +9MB)	coherence_checking
time:   0.003; rss:   69MB ->   77MB (   +9MB)	type_check_crate
time:   0.002; rss:   77MB ->   82MB (   +4MB)	MIR_borrow_checking
time:   0.005; rss:   95MB ->  119MB (  +24MB)	codegen_to_LLVM_IR
time:   0.039; rss:   95MB ->  119MB (  +24MB)	codegen_crate
time:   0.013; rss:  107MB ->  110MB (   +2MB)	LLVM_passes
time:   0.001; rss:  119MB ->  105MB (  -14MB)	free_global_ctxt
time:   0.004; rss:   47MB ->   60MB (  +12MB)	expand_crate
time:   0.001; rss:  105MB ->  105MB (   +0MB)	link_rlib
time:   0.002; rss:   82MB ->   86MB (   +4MB)	generate_crate_metadata
time:   0.000; rss:  105MB ->  104MB (   -1MB)	link_binary_remove_temps
time:   0.004; rss:   47MB ->   60MB (  +13MB)	macro_expand_crate
time:   0.001; rss:  105MB ->  104MB (   -2MB)	link_binary
time:   0.001; rss:  105MB ->  102MB (   -4MB)	link_crate
time:   0.001; rss:  105MB ->  102MB (   -4MB)	link
time:   0.119; rss:   32MB ->   92MB (  +60MB)	total
time:   0.070; rss:   82MB ->  111MB (  +29MB)	type_check_crate
time:   0.010; rss:   78MB ->   79MB (   +1MB)	looking_for_derive_registrar
time:   0.005; rss:   60MB ->   65MB (   +5MB)	late_resolve_crate
time:   0.007; rss:   60MB ->   65MB (   +5MB)	resolve_crate
   Compiling scopeguard v1.2.0
time:   0.075; rss:   50MB ->   89MB (  +39MB)	expand_crate
time:   0.077; rss:   50MB ->   89MB (  +39MB)	macro_expand_crate
time:   0.016; rss:   78MB ->   81MB (   +4MB)	misc_checking_1
time:   0.021; rss:   75MB ->   90MB (  +15MB)	coherence_checking
time:   0.008; rss:   96MB ->  102MB (   +6MB)	LLVM_passes
time:   0.000; rss:   86MB ->  102MB (  +17MB)	codegen_to_LLVM_IR
time:   0.011; rss:   86MB ->  102MB (  +17MB)	codegen_crate
time:   0.030; rss:   81MB ->  100MB (  +18MB)	coherence_checking
time:   0.002; rss:  102MB ->   92MB (  -10MB)	free_global_ctxt
time:   0.001; rss:   92MB ->   93MB (   +0MB)	finish_ongoing_codegen
time:   0.001; rss:   93MB ->   93MB (   +0MB)	link_rlib
time:   0.002; rss:   93MB ->   93MB (   +0MB)	link_binary
time:   0.002; rss:   93MB ->   93MB (   +0MB)	link_crate
time:   0.003; rss:   92MB ->   93MB (   +1MB)	link
time:   0.055; rss:   32MB ->   89MB (  +57MB)	total
time:   0.051; rss:  107MB ->  121MB (  +14MB)	monomorphization_collector_graph_walk
time:   0.009; rss:   65MB ->   68MB (   +3MB)	looking_for_derive_registrar
time:   0.011; rss:   65MB ->   68MB (   +3MB)	misc_checking_1
time:   0.059; rss:  103MB ->  116MB (  +13MB)	monomorphization_collector_graph_walk
time:   0.005; rss:  122MB ->  123MB (   +1MB)	partition_and_assert_distinct_symbols
time:   0.005; rss:  116MB ->  118MB (   +2MB)	partition_and_assert_distinct_symbols
time:   0.016; rss:   89MB ->   89MB (   +0MB)	compute_effective_visibilities
time:   0.016; rss:   68MB ->   81MB (  +13MB)	coherence_checking
time:   0.065; rss:   75MB ->  108MB (  +34MB)	type_check_crate
time:   0.048; rss:   81MB ->  105MB (  +24MB)	coherence_checking
time:   0.021; rss:   89MB ->   96MB (   +7MB)	late_resolve_crate
time:   0.080; rss:   81MB ->  111MB (  +30MB)	type_check_crate
time:   0.048; rss:   51MB ->   81MB (  +30MB)	expand_crate
time:   0.049; rss:   51MB ->   82MB (  +31MB)	macro_expand_crate
time:   0.060; rss:  111MB ->  116MB (   +6MB)	MIR_borrow_checking
time:   0.007; rss:   96MB ->   96MB (   +0MB)	resolve_check_unused
time:   0.058; rss:   89MB ->   96MB (   +7MB)	resolve_crate
time:   0.011; rss:  116MB ->  119MB (   +3MB)	MIR_effect_checking
time:   0.001; rss:   42MB ->   46MB (   +4MB)	parse_crate
time:   0.000; rss:   46MB ->   48MB (   +2MB)	setup_global_ctxt
time:   0.016; rss:   82MB ->   84MB (   +2MB)	late_resolve_crate
time:   0.002; rss:   48MB ->   57MB (   +8MB)	expand_crate
time:   0.002; rss:   48MB ->   57MB (   +8MB)	macro_expand_crate
time:   0.000; rss:   57MB ->   61MB (   +4MB)	compute_effective_visibilities
time:   0.071; rss:   81MB ->  112MB (  +30MB)	type_check_crate
time:   0.018; rss:   82MB ->   84MB (   +2MB)	resolve_crate
time:   0.030; rss:  108MB ->  112MB (   +3MB)	MIR_borrow_checking
time:   0.001; rss:   57MB ->   61MB (   +4MB)	resolve_crate
time:   0.001; rss:   61MB ->   65MB (   +4MB)	looking_for_derive_registrar
time:   0.001; rss:   61MB ->   65MB (   +4MB)	misc_checking_1
time:   0.065; rss:   68MB ->   92MB (  +24MB)	type_check_crate
time:   0.000; rss:   45MB ->   49MB (   +4MB)	setup_global_ctxt
time:   0.003; rss:   65MB ->   74MB (   +9MB)	coherence_checking
time:   0.007; rss:   65MB ->   77MB (  +12MB)	type_check_crate
time:   0.004; rss:   51MB ->   65MB (  +14MB)	expand_crate
time:   0.004; rss:   51MB ->   65MB (  +14MB)	macro_expand_crate
time:   0.001; rss:   65MB ->   69MB (   +4MB)	late_resolve_crate
time:   0.002; rss:   65MB ->   69MB (   +4MB)	resolve_crate
time:   0.004; rss:   77MB ->   84MB (   +7MB)	MIR_borrow_checking
time:   0.001; rss:   69MB ->   73MB (   +4MB)	misc_checking_1
time:   0.001; rss:   73MB ->   78MB (   +4MB)	coherence_checking
time:   0.001; rss:   84MB ->   86MB (   +2MB)	generate_crate_metadata
time:   0.020; rss:  125MB ->  146MB (  +21MB)	codegen_to_LLVM_IR
time:   0.159; rss:  107MB ->  146MB (  +39MB)	codegen_crate
time:   0.095; rss:  144MB ->  145MB (   +0MB)	LLVM_passes
time:   0.008; rss:   73MB ->   91MB (  +18MB)	type_check_crate
time:   0.039; rss:  111MB ->  116MB (   +4MB)	MIR_borrow_checking
time:   0.004; rss:  146MB ->  107MB (  -39MB)	free_global_ctxt
time:   0.008; rss:   91MB ->   99MB (   +9MB)	MIR_borrow_checking
time:   0.030; rss:   84MB ->   91MB (   +7MB)	looking_for_derive_registrar
time:   0.012; rss:  116MB ->  116MB (   +0MB)	MIR_effect_checking
time:   0.002; rss:   99MB ->  102MB (   +3MB)	MIR_effect_checking
time:   0.007; rss:  101MB ->  101MB (   +0MB)	drop_ast
time:   0.032; rss:  112MB ->  115MB (   +3MB)	MIR_borrow_checking
time:   0.042; rss:   96MB ->  101MB (   +5MB)	looking_for_derive_registrar
time:   0.002; rss:  116MB ->  117MB (   +1MB)	lint_checking
time:   0.008; rss:  115MB ->  115MB (   +0MB)	MIR_effect_checking
time:   0.008; rss:  116MB ->  117MB (   +1MB)	misc_checking_3
time:   0.036; rss:   92MB ->   96MB (   +3MB)	MIR_borrow_checking
time:   0.000; rss:   86MB ->  104MB (  +18MB)	codegen_to_LLVM_IR
time:   0.023; rss:   86MB ->  104MB (  +18MB)	codegen_crate
time:   0.001; rss:  104MB ->   88MB (  -15MB)	free_global_ctxt
time:   0.009; rss:   95MB ->   88MB (   -6MB)	LLVM_passes
time:   0.041; rss:   84MB ->   91MB (   +7MB)	misc_checking_1
time:   0.000; rss:   88MB ->   88MB (   +0MB)	join_worker_thread
time:   0.001; rss:   88MB ->   88MB (   +0MB)	finish_ongoing_codegen
time:   0.000; rss:   88MB ->   89MB (   +0MB)	link_rlib
time:   0.001; rss:   88MB ->   89MB (   +0MB)	link_binary
time:   0.001; rss:   88MB ->   89MB (   +0MB)	link_crate
time:   0.002; rss:   88MB ->   89MB (   +0MB)	link
time:   0.072; rss:   33MB ->   85MB (  +53MB)	total
time:   0.045; rss:  121MB ->  131MB (  +11MB)	monomorphization_collector_graph_walk
time:   0.012; rss:  122MB ->  148MB (  +26MB)	codegen_to_LLVM_IR
time:   0.165; rss:  103MB ->  148MB (  +45MB)	codegen_crate
time:   0.064; rss:  143MB ->  136MB (   -7MB)	LLVM_passes
time:   0.006; rss:  115MB ->  115MB (   +0MB)	misc_checking_3
time:   0.039; rss:  114MB ->  127MB (  +13MB)	monomorphization_collector_graph_walk
time:   0.003; rss:  148MB ->  106MB (  -42MB)	free_global_ctxt

How can I map expand_crate step / total step to a crate ?

Genarated the info by running RUSTFLAGS="-Ztime-passes" cargo build --bin router on nightly to observe passes

There might be a way to identify that, but I would recommend narrowing down the problem instead. First, use the --timings flag to get a look at which crate is slow to build:

cargo clean
RUSTFLAGS="-Ztime-passes" cargo build --bin router --timings

Ignore the -Ztime-passes output here; we are just making sure we aren't changing the RUSTFLAGS for the next time. At the end of the build, Cargo will create a HTML file with a chart of the build times and interdependencies, and print the path to it. Open that file and find which one is slow enough to merit further investigation. Then, force it to rebuild:

cargo clean -p <package name you noticed>
RUSTFLAGS="-Ztime-passes" cargo build --bin router

This should get you time-passes output only for the relevant crate (unless its package also has a build script, in which case you'll get two, with the build script coming first).

6 Likes

Wow this is a very useful tip. Thanks