rust-lang / rust-lang/rust

`-Z time-passes` produces confusing output

Open
#142,523 6 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

A-CLI C-bug requires-nightly T-cargo T-compiler
Dominant language
Rust
Stars
119k
Forks
16.1k
PR merge metrics
PR metrics pending

Description

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

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Reproduce the output with cargo +nightly rustc -- -Z time-passes and compare the reported pass times with the total line. Trace how -Z time-passes formats compiler pass timings, then make the relationship between nested or overlapping passes and total time understandable, with coverage for the resulting output.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
compilers, tooling
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
28/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.