`-Ztime-passes`: only print passes that take more than 5 milliseconds

[jyn514]

Right now, -Ztime-passes has very long output, most of which is completely useless for determining which part of your crate is slow:

time:   0.002; rss:   49MB ->   52MB (   +2MB)  parse_crate
time:   0.000; rss:   52MB ->   52MB (   +0MB)  attributes_injection
time:   0.000; rss:   52MB ->   52MB (   +0MB)  incr_comp_prepare_session_directory
time:   0.000; rss:   52MB ->   52MB (   +0MB)  incr_comp_garbage_collect_session_directories
time:   0.000; rss:   52MB ->   52MB (   +0MB)  plugin_loading
time:   0.000; rss:   52MB ->   52MB (   +0MB)  plugin_registration
time:   0.000; rss:   54MB ->   54MB (   +0MB)  crate_injection
time:   0.013; rss:   54MB ->   80MB (  +25MB)  expand_crate
time:   0.000; rss:   80MB ->   80MB (   +0MB)  check_unused_macros
time:   0.013; rss:   54MB ->   80MB (  +25MB)  macro_expand_crate
time:   0.000; rss:   80MB ->   80MB (   +0MB)  maybe_building_test_harness
time:   0.000; rss:   80MB ->   80MB (   +0MB)  AST_validation
time:   0.000; rss:   80MB ->   80MB (   +0MB)  maybe_create_a_macro_crate
time:   0.000; rss:   80MB ->   80MB (   +0MB)  finalize_imports
time:   0.000; rss:   80MB ->   80MB (   +0MB)  resolve_access_levels
time:   0.000; rss:   80MB ->   80MB (   +0MB)  finalize_macro_resolutions
time:   0.001; rss:   80MB ->   82MB (   +2MB)  late_resolve_crate
time:   0.000; rss:   82MB ->   82MB (   +0MB)  resolve_main
time:   0.000; rss:   82MB ->   82MB (   +0MB)  resolve_check_unused
time:   0.000; rss:   82MB ->   82MB (   +0MB)  resolve_report_errors
time:   0.000; rss:   82MB ->   82MB (   +0MB)  resolve_postprocess
time:   0.001; rss:   80MB ->   82MB (   +2MB)  resolve_crate
time:   0.000; rss:   82MB ->   82MB (   +0MB)  complete_gated_feature_checking
time:   0.015; rss:   52MB ->   82MB (  +30MB)  configure_and_expand
time:   0.000; rss:   82MB ->   82MB (   +0MB)  prepare_outputs
time:   0.000; rss:   82MB ->   82MB (   +0MB)  blocked_on_dep_graph_loading
time:   0.002; rss:   82MB ->   84MB (   +2MB)  hir_lowering
time:   0.000; rss:   84MB ->   84MB (   +0MB)  early_lint_checks
time:   0.000; rss:   84MB ->   84MB (   +0MB)  drop_ast
time:   0.000; rss:   84MB ->   84MB (   +0MB)  setup_global_ctxt
time:   0.000; rss:   87MB ->   87MB (   +0MB)  looking_for_entry_point
time:   0.000; rss:   87MB ->   87MB (   +0MB)  looking_for_derive_registrar
time:   0.000; rss:   90MB ->   90MB (   +0MB)  unused_lib_feature_checking
time:   0.002; rss:   87MB ->   90MB (   +4MB)  misc_checking_1
time:   0.002; rss:   90MB ->   94MB (   +4MB)  type_collecting
time:   0.000; rss:   94MB ->   94MB (   +0MB)  impl_wf_inference
time:   0.000; rss:   94MB ->   94MB (   +0MB)  unsafety_checking
time:   0.013; rss:   94MB ->  116MB (  +22MB)  coherence_checking
time:   0.004; rss:  116MB ->  118MB (   +2MB)  wf_checking
time:   0.007; rss:  118MB ->  124MB (   +6MB)  item_types_checking
time:   0.013; rss:  124MB ->  127MB (   +3MB)  item_bodies_checking
time:   0.041; rss:   90MB ->  127MB (  +37MB)  type_check_crate
time:   0.000; rss:  127MB ->  127MB (   +0MB)  match_checking
time:   0.001; rss:  127MB ->  127MB (   +0MB)  liveness_and_intrinsic_checking
time:   0.001; rss:  127MB ->  127MB (   +0MB)  misc_checking_2
time:   0.016; rss:  127MB ->  129MB (   +2MB)  MIR_borrow_checking
time:   0.000; rss:  129MB ->  129MB (   +0MB)  MIR_effect_checking
time:   0.000; rss:  129MB ->  129MB (   +0MB)  layout_testing
time:   0.005; rss:  129MB ->  130MB (   +1MB)  crate_lints
time:   0.000; rss:  130MB ->  130MB (   +0MB)  module_lints
time:   0.000; rss:  130MB ->  130MB (   +0MB)  check_lint_expectations
time:   0.006; rss:  129MB ->  130MB (   +1MB)  lint_checking
time:   0.001; rss:  130MB ->  130MB (   +0MB)  privacy_checking_modules
time:   0.008; rss:  129MB ->  130MB (   +1MB)  misc_checking_3
time:   0.000; rss:  132MB ->  132MB (   +0MB)  monomorphization_collector_root_collections
time:   0.024; rss:  132MB ->  140MB (   +8MB)  monomorphization_collector_graph_walk
time:   0.003; rss:  140MB ->  141MB (   +1MB)  partition_and_assert_distinct_symbols
time:   0.033; rss:  130MB ->  141MB (  +11MB)  generate_crate_metadata
time:   0.000; rss:  141MB ->  141MB (   +0MB)  find_cgu_reuse
time:   0.055; rss:  141MB ->  162MB (  +21MB)  codegen_to_LLVM_IR
time:   0.060; rss:  141MB ->  162MB (  +21MB)  codegen_crate
time:   0.000; rss:  161MB ->  161MB (   +0MB)  assert_dep_graph
time:   0.000; rss:  161MB ->  161MB (   +0MB)  check_dirty_clean
time:   0.000; rss:  161MB ->  161MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::type_of)
time:   0.000; rss:  161MB ->  162MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::generics_of)
time:   0.000; rss:  162MB ->  162MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::predicates_of)
time:   0.000; rss:  161MB ->  161MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::mir_const_qualif)
time:   0.000; rss:  161MB ->  161MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::mir_for_ctfe)
time:   0.000; rss:  161MB ->  161MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::optimized_mir)
time:   0.000; rss:  161MB ->  160MB (   -1MB)  encode_query_results_for(rustc_query_impl::queries::covered_code_regions)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::promoted_mir)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::adt_def)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::unsafety_check_result)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::thir_check_unsafety)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::typeck)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::diagnostic_only_typeck)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::used_trait_imports)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::mir_borrowck)
time:   0.000; rss:  160MB ->  160MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::eval_to_allocation_raw)
time:   0.000; rss:  160MB ->  159MB (   -1MB)  encode_query_results_for(rustc_query_impl::queries::eval_to_const_value_raw)
time:   0.000; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::check_match)
time:   0.000; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::symbol_name)
time:   0.000; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::codegen_fn_attrs)
time:   0.000; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::codegen_fulfill_obligation)
time:   0.001; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::specialization_graph_of)
time:   0.000; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::adt_drop_tys)
time:   0.000; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::adt_significant_drop_tys)
time:   0.000; rss:  159MB ->  159MB (   +0MB)  encode_query_results_for(rustc_query_impl::queries::unused_generic_params)
time:   0.003; rss:  161MB ->  159MB (   -3MB)  encode_query_results
time:   0.004; rss:  161MB ->  159MB (   -3MB)  incr_comp_serialize_result_cache
time:   0.004; rss:  161MB ->  159MB (   -3MB)  incr_comp_persist_result_cache
time:   0.000; rss:  159MB ->  159MB (   +0MB)  incr_comp_persist_dep_graph
time:   0.004; rss:  161MB ->  159MB (   -3MB)  serialize_dep_graph
time:   0.003; rss:  159MB ->  115MB (  -44MB)  free_global_ctxt
time:   0.061; rss:  146MB ->  115MB (  -30MB)  LLVM_passes(crate)
time:   0.000; rss:  114MB ->  114MB (   +0MB)  join_worker_thread
time:   0.001; rss:  114MB ->  114MB (   +0MB)  copy_all_cgu_workproducts_to_incr_comp_cache_dir
time:   0.002; rss:  115MB ->  114MB (   -1MB)  finish_ongoing_codegen
time:   0.000; rss:  114MB ->  114MB (   +0MB)  llvm_dump_timing_file
time:   0.000; rss:  114MB ->  114MB (   +0MB)  serialize_work_products
time:   0.000; rss:  114MB ->  114MB (   +0MB)  incr_comp_finalize_session_directory
time:   0.000; rss:  114MB ->  114MB (   +0MB)  link_binary_check_files_are_writeable
time:   0.002; rss:  114MB ->  114MB (   +0MB)  link_rlib
time:   0.000; rss:  114MB ->  114MB (   +0MB)  link_binary_remove_temps
time:   0.003; rss:  114MB ->  114MB (   +0MB)  link_binary
time:   0.003; rss:  114MB ->  114MB (   +0MB)  link_crate
time:   0.005; rss:  115MB ->  114MB (   +0MB)  link
time:   0.196; rss:   39MB ->   95MB (  +56MB)  total

It would be great to make self-profile smarter and only prints passes that take more than x milliseconds (.005 seconds seems like a reasonable cutoff). Then most lines would be trimmed but long running lints would still show up. It will still be possible to see the full information by running -Zself-profile, which is recommended for heavy-duty profiling anyway since it gives you more tools around the collected data.

Originally posted by @jyn514 in #79953 (comment)

[jyn514]

Mentoring instructions: Change

rust/compiler/rustc_data_structures/src/profiling.rs

Line 652 in 05d2221

print_time_passes_entry(&message, start_time.elapsed(), start_rss, end_rss);

to only call print_time_passes_entry if start_time.elapsed() is longer than 5 ms.

@rustbot label: +E-easy +E-mentor

[randomicon00]

@rustbot claim

[randomicon00]

Hello @jyn514!

This is the first time I contribute to the rust project. I think I understand what is required to do, basically filtering out the passes and only keep the ones that take more than 5 milliseconds. Should I just add an if condition to the print function, and should the condition be hardcoded or configurable?

[jyn514]

For now I think hardcoded is fine; eventually it would be nice to make it configurable, the same way it is for summarize.

cc @rylev , I think you've been doing a fair amount of performance work - do you have opinions?

[rylev]

I don't have strong opinions here, but I also don't use -Ztime-passes a lot.