`-Z time-passes` produces confusing output

[JohnScience]

I tried to build my project with these lines:

cargo +nightly rustc -- -Z time-passes

I expected to see one of the following:

• flat non-overlapping list of passes OR
• tree-like output for passes in a hierarchical relationship OR
• something like the output of cargo build -timings

Instead, this happened: the times of passes add up to a number greater than the total and the reason is not clear (Are they happening in parallel? Is there a hierarchical structure?).

Output

time:   0.022; rss:   22MB ->   23MB (   +1MB)  parse_crate
time:   0.366; rss:   23MB ->   23MB (   +0MB)  incr_comp_prepare_session_directory
time:   0.003; rss:  327MB ->  327MB (   +0MB)  incr_comp_garbage_collect_session_directories
time:   0.001; rss:  369MB ->  369MB (   +0MB)  crate_injection
time:   8.311; rss:  369MB ->  583MB ( +214MB)  expand_crate
time:   8.312; rss:  369MB ->  583MB ( +214MB)  macro_expand_crate
time:   0.052; rss:  583MB ->  584MB (   +0MB)  AST_validation
time:   0.287; rss:  584MB ->  584MB (   +0MB)  finalize_imports
time:   0.008; rss:  584MB ->  584MB (   +0MB)  compute_effective_visibilities
time:   0.001; rss:  584MB ->  584MB (   +0MB)  check_hidden_glob_reexports
time:   0.074; rss:  584MB ->  584MB (   +1MB)  finalize_macro_resolutions
time:   7.261; rss:  584MB ->  622MB (  +38MB)  late_resolve_crate
time:   0.039; rss:  622MB ->  623MB (   +1MB)  resolve_check_unused
time:   0.044; rss:  623MB ->  623MB (   +0MB)  resolve_postprocess
time:   7.716; rss:  584MB ->  623MB (  +39MB)  resolve_crate
time:   0.033; rss:  618MB ->  618MB (   +0MB)  write_dep_info
time:   0.028; rss:  618MB ->  618MB (   +0MB)  complete_gated_feature_checking
time:   0.098; rss:  707MB ->  670MB (  -37MB)  drop_ast
time:   1.517; rss:  618MB ->  653MB (  +35MB)  looking_for_entry_point
time:   0.001; rss:  653MB ->  653MB (   +0MB)  looking_for_derive_registrar
time:   0.001; rss:  654MB ->  654MB (   +0MB)  unused_lib_feature_checking
time:   1.613; rss:  618MB ->  654MB (  +36MB)  misc_checking_1
time:   0.733; rss:  654MB ->  676MB (  +22MB)  coherence_checking
time:   0.808; rss:  654MB ->  676MB (  +22MB)  type_check_crate
time:   0.013; rss:  676MB ->  677MB (   +0MB)  MIR_coroutine_by_move_body
time:   0.119; rss:  677MB ->  677MB (   +0MB)  MIR_borrow_checking
time:   0.052; rss:  677MB ->  677MB (   +0MB)  MIR_effect_checking
time:   0.052; rss:  677MB ->  678MB (   +2MB)  coroutine_obligations
time:   0.001; rss:  678MB ->  678MB (   +0MB)  abi_testing
time:   0.026; rss:  682MB ->  682MB (   +0MB)  module_lints
time:   0.027; rss:  682MB ->  682MB (   +0MB)  lint_checking
time:   0.008; rss:  682MB ->  682MB (   +0MB)  privacy_checking_modules
time:   0.107; rss:  682MB ->  685MB (   +3MB)  check_lint_expectations
time:   0.272; rss:  678MB ->  685MB (   +7MB)  misc_checking_3
time:   0.158; rss:  685MB ->  694MB (   +9MB)  monomorphization_collector_root_collections
time:   3.579; rss:  694MB ->  895MB ( +201MB)  monomorphization_collector_graph_walk
time:   1.434; rss:  893MB ->  952MB (  +58MB)  partition_and_assert_distinct_symbols
time:   0.015; rss:  935MB ->  936MB (   +0MB)  write_allocator_module
time:   0.156; rss:  936MB ->  939MB (   +3MB)  find_cgu_reuse
time:   0.000; rss:  939MB ->  939MB (   +0MB)  codegen_to_LLVM_IR
time:   5.772; rss:  685MB ->  939MB ( +254MB)  codegen_crate
time:   0.329; rss:  939MB ->  939MB (   +0MB)  LLVM_passes
time:   0.006; rss:  939MB ->  939MB (   +0MB)  incr_comp_persist_dep_graph
time:   0.664; rss: 1031MB -> 1043MB (  +13MB)  encode_query_results
time:   0.728; rss: 1030MB -> 1035MB (   +5MB)  incr_comp_serialize_result_cache
time:   2.546; rss:  939MB -> 1035MB (  +96MB)  incr_comp_persist_result_cache
time:   2.555; rss:  939MB -> 1035MB (  +96MB)  serialize_dep_graph
time:   0.000; rss:  501MB ->  501MB (   +0MB)  join_worker_thread
time:   0.004; rss:  501MB ->  501MB (   +0MB)  copy_all_cgu_workproducts_to_incr_comp_cache_dir
time:   0.004; rss:  501MB ->  501MB (   +0MB)  finish_ongoing_codegen
time:   0.002; rss:  501MB ->  501MB (   +0MB)  serialize_work_products
time:   0.124; rss:  178MB ->  178MB (   +0MB)  incr_comp_finalize_session_directory
time:   0.028; rss:  178MB ->  178MB (   +0MB)  link_binary_check_files_are_writeable
time:  47.771; rss:  180MB ->    2MB ( -178MB)  run_linker
time:   0.120; rss:    3MB ->    3MB (   +0MB)  link_binary_remove_temps
time:  48.108; rss:  178MB ->    3MB ( -175MB)  link_binary
time:  48.157; rss:  178MB ->    6MB ( -172MB)  link_crate
time:  48.335; rss:  501MB ->    6MB ( -495MB)  link
time:  78.231; rss:   14MB ->    9MB (   -5MB)  total

Meta

N/A

[workingjubilee]

Are they happening in parallel?

strictly speaking no not parallel but they are also not strictly linear events, as a query can kick off a query can kick off a query etc., the architecture is deliberately somewhat lazy once we clear the eager phase of parse, expansion, and resolution.

Is there a hierarchical structure?

sssorta?

[JohnScience]

@workingjubilee So we'll need an output similar to cargo build -timings in order to make sense of the timings?

[saethlin]

Yes. It is normal that Cargo needs to do something to make a rustc flag behave well when rustc is being invoked by Cargo.

[saethlin]

You can pass -j1 to Cargo as a hack to prevent the problematic interleaving.

[JohnScience]

@saethlin rustc's -Z time-passes and cargo's --timings are showing quite different data. I bring up --timing because the graph there shows the data of similar nature.

[bjorn3]

-Ztime-passes used to have indentation to show the hierarchy, but I believe this was removed in #67777 as it doesn't work well with multi-threading.