Add `-Z time-passes-format` to allow specifying a JSON output for `-Z time-passes` by Zoxc · Pull Request #107718 · rust-lang/rust

Zoxc · 2023-02-06T07:58:06Z

This adds back the -Z time option as that is useful for my rustc benchmark tool, reverting #102725. It now uses nanoseconds and bytes as the units so it is renamed to time-precise.

rustbot · 2023-02-06T07:58:13Z

r? @jackh726

(rustbot has picked a reviewer for you, use r? to override)

jackh726 · 2023-02-06T15:32:33Z

I'm going too r? @nnethercote here, since they removed this originally. Also going to cc @davidtwco as previous reviewer.

lqd · 2023-02-06T18:27:52Z

compiler/rustc_hir_analysis/src/coherence/mod.rs

drive by question: why stop timing these ?

They're done per item and are not passes.

mcol · 2023-02-06T20:13:18Z

compiler/rustc_data_structures/src/profiling.rs

Suggested change

/// a measureme event, "extra verbose" generic activities also print a timing entry to

/// a measurement event, "extra verbose" generic activities also print a timing entry to

measureme is the profiling library ;)

nnethercote · 2023-02-06T22:13:46Z

The commit log from the removal has some important details on problems with the old -Ztime code. It was very unclear from both the user-facing documentation and the code itself what it did, and how it was different from -Ztime-passes. E.g. the distinction between "verbose" and "extra verbose" was unclear.

Also, to review this I need a better understanding of the motivation. Can you give examples of the new output, and how it compares with -Ztime-passes output?

Removing -Ztime was a code clarity improvement, and I don't want to just undo it without some care.

Zoxc · 2023-02-06T23:11:54Z

-Z time used to strictly print passes (as in there's a 1:1 correspondence between source code sess.time calls and output lines). That correspondence is useful for rcb to ensure it's comparing apples to apples. -Z time-passes has additional non-pass entries (not the best naming). I'm kind of in favor of moving the non-pass outputs to -Z self-profile only, but I don't know if anyone finds them useful.

My currently use case is mostly as output to rcb. It needs higher precision units and the inclusion of non-notable lines. I want to be able to measure passes below 5 ms. It can't make use of -Z self-profile as I need control over if the profile path is taken or not.

Here's -Z time-precise for hello world:

time:            350900ns; rss:         12939264B ->         13418496B (          479232B)      parse_crate
time:              3900ns; rss:         13455360B ->         13463552B (            8192B)      attributes_injection
time:              3500ns; rss:         13762560B ->         13766656B (            4096B)      plugin_loading
time:              2200ns; rss:         13770752B ->         13770752B (               0B)      plugin_registration
time:             53900ns; rss:         14041088B ->         14168064B (          126976B)      crate_injection
time:           5047100ns; rss:         14200832B ->         17805312B (         3604480B)      expand_crate
time:              3700ns; rss:         17805312B ->         17809408B (            4096B)      check_unused_macros
time:           5557300ns; rss:         14172160B ->         17829888B (         3657728B)      macro_expand_crate
time:              1200ns; rss:         17833984B ->         17833984B (               0B)      maybe_building_test_harness
time:             35900ns; rss:         17833984B ->         17928192B (           94208B)      AST_validation
time:              5200ns; rss:         17928192B ->         17936384B (            8192B)      maybe_create_a_macro_crate
time:             18000ns; rss:         17940480B ->         17973248B (           32768B)      finalize_imports
time:             12500ns; rss:         17973248B ->         17997824B (           24576B)      compute_effective_visibilities
time:            244000ns; rss:         17997824B ->         18386944B (          389120B)      finalize_macro_resolutions
time:            349600ns; rss:         18386944B ->         18960384B (          573440B)      late_resolve_crate
time:              3200ns; rss:         18960384B ->         18964480B (            4096B)      resolve_main
time:              5600ns; rss:         18964480B ->         18972672B (            8192B)      resolve_check_unused
time:              5100ns; rss:         18972672B ->         18984960B (           12288B)      resolve_report_errors
time:             21700ns; rss:         18984960B ->         19025920B (           40960B)      resolve_postprocess
time:           1307900ns; rss:         17936384B ->         19025920B (         1089536B)      resolve_crate
time:             13400ns; rss:         19025920B ->         19054592B (           28672B)      complete_gated_feature_checking
time:             49000ns; rss:         19066880B ->         19165184B (           98304B)      early_lint_checks
time:           7671300ns; rss:         13774848B ->         19165184B (         5390336B)      configure_and_expand
time:             75600ns; rss:         19238912B ->         19382272B (          143360B)      setup_global_ctxt
time:            553700ns; rss:         19456000B ->         19558400B (          102400B)      prepare_outputs
time:             21200ns; rss:         20049920B ->         20103168B (           53248B)      drop_ast
time:            417900ns; rss:         19582976B ->         20320256B (          737280B)      looking_for_entry_point
time:             11300ns; rss:         20324352B ->         20340736B (           16384B)      looking_for_derive_registrar
time:             40900ns; rss:         20774912B ->         20873216B (           98304B)      unused_lib_feature_checking
time:            889400ns; rss:         19582976B ->         20889600B (         1306624B)      misc_checking_1
time:            285200ns; rss:         20901888B ->         21581824B (          679936B)      type_collecting
time:              9800ns; rss:         21581824B ->         21602304B (           20480B)      impl_wf_inference
time:             34200ns; rss:         21602304B ->         21680128B (           77824B)      coherence_checking
time:            233400ns; rss:         21684224B ->         22315008B (          630784B)      wf_checking
time:             11300ns; rss:         22319104B ->         22347776B (           28672B)      item_types_checking
time:           1420100ns; rss:         22347776B ->         25001984B (         2654208B)      item_bodies_checking
time:           2568000ns; rss:         20893696B ->         25108480B (         4214784B)      type_check_crate
time:             15700ns; rss:         25112576B ->         25145344B (           32768B)      match_checking
time:             71300ns; rss:         25145344B ->         25255936B (          110592B)      liveness_checking
time:            239900ns; rss:         25112576B ->         25255936B (          143360B)      misc_checking_2
time:           2213500ns; rss:         25260032B ->         29085696B (         3825664B)      MIR_borrow_checking
time:              4600ns; rss:         29085696B ->         29089792B (            4096B)      MIR_effect_checking
time:              2700ns; rss:         29093888B ->         29097984B (            4096B)      layout_testing
time:             58600ns; rss:         29368320B ->         29458432B (           90112B)      crate_lints
time:             68800ns; rss:         29458432B ->         29614080B (          155648B)      module_lints
time:            279900ns; rss:         29368320B ->         29614080B (          245760B)      lint_checking
time:             25500ns; rss:         29614080B ->         29655040B (           40960B)      privacy_checking_modules
time:             10100ns; rss:         29655040B ->         29675520B (           20480B)      check_lint_expectations
time:            664800ns; rss:         29097984B ->         29675520B (          577536B)      misc_checking_3
time:           1741100ns; rss:         29761536B ->         30261248B (          499712B)      codegen_crate
time:              7300ns; rss:         30392320B ->         30400512B (            8192B)      serialize_dep_graph
time:           1181700ns; rss:         30400512B ->         26886144B (        -3514368B)      free_global_ctxt
time:             14700ns; rss:         26894336B ->         26914816B (           20480B)      join_worker_thread
time:             96200ns; rss:         26890240B ->         26927104B (           36864B)      finish_ongoing_codegen
time:              1200ns; rss:         26939392B ->         26939392B (               0B)      serialize_work_products
time:               700ns; rss:         26959872B ->         26959872B (               0B)      link_binary_check_files_are_writeable
time:               800ns; rss:         26959872B ->         26959872B (               0B)      link_binary_remove_temps
time:            101600ns; rss:         26951680B ->         26959872B (            8192B)      link_binary
time:            159800ns; rss:         26947584B ->         26972160B (           24576B)      link_crate
time:            411000ns; rss:         26886144B ->         26980352B (           94208B)      link
time:          25857800ns; rss:          9707520B ->         26435584B (        16728064B)      total

Here's -Z time-passes for hello world:

time:   0.000; rss:   13MB ->   13MB (    0MB)  parse_crate
time:   0.000; rss:   14MB ->   14MB (    0MB)  attributes_injection
time:   0.000; rss:   14MB ->   14MB (    0MB)  plugin_loading
time:   0.000; rss:   14MB ->   14MB (    0MB)  crate_injection
time:   0.005; rss:   14MB ->   18MB (    4MB)  expand_crate
time:   0.000; rss:   18MB ->   18MB (    0MB)  check_unused_macros
time:   0.005; rss:   14MB ->   18MB (    4MB)  macro_expand_crate
time:   0.000; rss:   18MB ->   18MB (    0MB)  AST_validation
time:   0.000; rss:   18MB ->   18MB (    0MB)  maybe_create_a_macro_crate
time:   0.000; rss:   18MB ->   18MB (    0MB)  finalize_imports
time:   0.000; rss:   18MB ->   18MB (    0MB)  compute_effective_visibilities
time:   0.000; rss:   18MB ->   18MB (    0MB)  finalize_macro_resolutions
time:   0.000; rss:   18MB ->   19MB (    1MB)  late_resolve_crate
time:   0.000; rss:   19MB ->   19MB (    0MB)  resolve_main
time:   0.000; rss:   19MB ->   19MB (    0MB)  resolve_check_unused
time:   0.000; rss:   19MB ->   19MB (    0MB)  resolve_report_errors
time:   0.000; rss:   19MB ->   19MB (    0MB)  resolve_postprocess
time:   0.001; rss:   18MB ->   19MB (    1MB)  resolve_crate
time:   0.000; rss:   19MB ->   19MB (    0MB)  complete_gated_feature_checking
time:   0.000; rss:   19MB ->   19MB (    0MB)  early_lint_checks
time:   0.007; rss:   14MB ->   19MB (    5MB)  configure_and_expand
time:   0.000; rss:   19MB ->   20MB (    0MB)  setup_global_ctxt
time:   0.001; rss:   20MB ->   20MB (    0MB)  prepare_outputs
time:   0.000; rss:   20MB ->   20MB (    0MB)  drop_ast
time:   0.000; rss:   20MB ->   20MB (    1MB)  looking_for_entry_point
time:   0.000; rss:   20MB ->   20MB (    0MB)  looking_for_derive_registrar
time:   0.000; rss:   21MB ->   21MB (    0MB)  unused_lib_feature_checking
time:   0.001; rss:   20MB ->   21MB (    1MB)  misc_checking_1
time:   0.000; rss:   21MB ->   22MB (    1MB)  type_collecting
time:   0.000; rss:   22MB ->   22MB (    0MB)  impl_wf_inference
time:   0.000; rss:   22MB ->   22MB (    0MB)  coherence_checking
time:   0.000; rss:   22MB ->   22MB (    1MB)  wf_checking
time:   0.000; rss:   22MB ->   22MB (    0MB)  item_types_checking
time:   0.001; rss:   22MB ->   25MB (    3MB)  item_bodies_checking
time:   0.002; rss:   21MB ->   25MB (    4MB)  type_check_crate
time:   0.000; rss:   25MB ->   25MB (    0MB)  match_checking
time:   0.000; rss:   25MB ->   25MB (    0MB)  liveness_checking
time:   0.000; rss:   25MB ->   25MB (    0MB)  misc_checking_2
time:   0.002; rss:   25MB ->   29MB (    4MB)  MIR_borrow_checking
time:   0.000; rss:   29MB ->   29MB (    0MB)  MIR_effect_checking
time:   0.000; rss:   29MB ->   29MB (    0MB)  layout_testing
time:   0.000; rss:   29MB ->   29MB (    0MB)  crate_lints
time:   0.000; rss:   29MB ->   30MB (    0MB)  module_lints
time:   0.000; rss:   29MB ->   30MB (    0MB)  lint_checking
time:   0.000; rss:   30MB ->   30MB (    0MB)  privacy_checking_modules
time:   0.000; rss:   30MB ->   30MB (    0MB)  check_lint_expectations
time:   0.000; rss:   29MB ->   30MB (    1MB)  misc_checking_3
time:   0.001; rss:   30MB ->   30MB (    1MB)  codegen_crate
time:   0.000; rss:   30MB ->   30MB (    0MB)  serialize_dep_graph
time:   0.001; rss:   30MB ->   27MB (   -4MB)  free_global_ctxt
time:   0.000; rss:   27MB ->   27MB (    0MB)  join_worker_thread
time:   0.000; rss:   27MB ->   27MB (    0MB)  finish_ongoing_codegen
time:   0.000; rss:   27MB ->   27MB (    0MB)  link_binary
time:   0.000; rss:   27MB ->   27MB (    0MB)  link_crate
time:   0.000; rss:   27MB ->   27MB (    0MB)  link
time:   0.022; rss:   10MB ->   26MB (   17MB)  total

nnethercote · 2023-02-13T04:00:17Z

I think changing -Ztime-passes to take an argument to allow different modes (e.g. normal vs precise) would go a long way to addressing the lack of code clarity I mentioned above.

Zoxc · 2023-02-15T14:22:20Z

Maybe -Ztime-passes= to get the current behavior and -Ztime-passes=unfiltered,precise,strict for the behavior I'm looking for? precise changes to precise units. unfiltered removes the 5ms filter. strict removes the extra non-pass entries.

bors · 2023-02-15T16:06:51Z

☔ The latest upstream changes (presumably #108079) made this pull request unmergeable. Please resolve the merge conflicts.

nnethercote · 2023-02-16T03:37:09Z

Previously the output of -Ztime-passes has been intended for humans. But now you want it to serve as the input for another program. Is plain text a bad idea for this? JSON might be better. E.g. I see that -Zdump-mono-stats has the accompanying -Zdump-mono-stats-format which accepts markdown (the default) or json.

bors · 2023-02-16T22:53:24Z

☔ The latest upstream changes (presumably #108127) made this pull request unmergeable. Please resolve the merge conflicts.

Zoxc · 2023-02-22T21:03:49Z

JSON would make sense. It might need the time: prefix to avoid getting picked up by cargo, not sure.

rustbot · 2023-03-14T13:28:17Z

These commits modify the Cargo.lock file. Random changes to Cargo.lock can be introduced when switching branches and rebasing PRs.
This was probably unintentional and should be reverted before this PR is merged.

If this was intentional then you can ignore this comment.

Zoxc · 2023-03-14T14:22:18Z

I've changed this to add a -Z time-passes-format option which can take a json value, which will cause -Z time-passes to output in JSON.

nnethercote

This is looking much better, thanks for doing it as JSON. A few minor suggestions below. My main other concern is that I don't know what the unique field is for. It seems to always be true. What does it mean? Is it necessary?

compiler/rustc_data_structures/src/graph/scc/tests.rs

nnethercote · 2023-03-20T22:10:59Z

compiler/rustc_data_structures/src/profiling.rs

More detail in this comment would be good. How is uniqueness ensured -- must the caller guarantee it? What happens if it's not unique?

nnethercote · 2023-03-20T22:12:43Z

compiler/rustc_data_structures/src/profiling.rs

With five elements, I think this tuple is now big enough that it should have its own type. That would allow some comments, particularly for the bool field. I see it's called unique, but at this point in the review it's not clear to me what that means.

Also, is_unique might be a better name? Or a whole new 2-value enum might be nicer than just bool.

nnethercote · 2023-03-20T22:16:10Z

compiler/rustc_data_structures/src/profiling.rs

It would be nice to have protection here against the addition of other formats. Either by adding assert_eq!(format, TimePassesFormat::Text) after the return, or by having a match here, which could fall through to the code below in the Text case.

Zoxc · 2023-03-21T17:04:22Z

Unique is false for verbose_generic_activity which gets multiple calls with the same name. I think I can just merge duplicate entries in rcb and remove the unique logic however.

… time-passes`

nnethercote · 2023-03-22T02:26:45Z

@bors r+

bors · 2023-03-22T02:26:47Z

📌 Commit 6c57dda has been approved by nnethercote

It is now in the queue for this repository.

…iaskrgr Rollup of 8 pull requests Successful merges: - rust-lang#106964 (Clarify `Error::last_os_error` can be weird) - rust-lang#107718 (Add `-Z time-passes-format` to allow specifying a JSON output for `-Z time-passes`) - rust-lang#107880 (Lint ambiguous glob re-exports) - rust-lang#108549 (Remove issue number for `link_cfg`) - rust-lang#108588 (Fix the ffi_unwind_calls lint documentation) - rust-lang#109231 (Add `try_canonicalize` to `rustc_fs_util` and use it over `fs::canonicalize`) - rust-lang#109472 (Add parentheses properly for method calls) - rust-lang#109487 (Move useless_anynous_reexport lint into unused_imports) Failed merges: r? `@ghost` `@rustbot` modify labels: rollup

rustbot assigned jackh726 Feb 6, 2023

Zoxc force-pushed the z-time branch 2 times, most recently from 4191f45 to 58afd39 Compare February 6, 2023 13:42

rustbot assigned nnethercote and unassigned jackh726 Feb 6, 2023

Zoxc force-pushed the z-time branch from 58afd39 to fbb704a Compare February 6, 2023 15:48

lqd reviewed Feb 6, 2023

View reviewed changes

mcol reviewed Feb 6, 2023

View reviewed changes

nnethercote added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Feb 13, 2023

workingjubilee added the A-CLI Area: Command-line interface (CLI) to the compiler label Mar 5, 2023

Zoxc force-pushed the z-time branch from fbb704a to 648f391 Compare March 14, 2023 13:28

Zoxc force-pushed the z-time branch from 648f391 to 344b2cc Compare March 14, 2023 13:59

Zoxc changed the title ~~Revive -Z time as -Z time-precise~~ Add -Z time-passes-format to allow specifying a JSON output for -Z time-passes Mar 14, 2023

Zoxc force-pushed the z-time branch from 344b2cc to ffe2e3d Compare March 14, 2023 14:15

nnethercote reviewed Mar 20, 2023

View reviewed changes

Zoxc added 3 commits March 21, 2023 18:18

Reduce output spam

b0dc15c

Add -Z time-passes-format to allow specifying a JSON output for `-Z…

f60d2eb

… time-passes`

Remove unique and move VerboseTimingGuard fields into a new struct

6c57dda

Zoxc force-pushed the z-time branch from ffe2e3d to 6c57dda Compare March 21, 2023 17:43

bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Mar 22, 2023

matthiaskrgr mentioned this pull request Mar 23, 2023

Rollup of 8 pull requests #109538

Merged

bors merged commit acd7f87 into rust-lang:master Mar 23, 2023

rustbot added this to the 1.70.0 milestone Mar 23, 2023

Zoxc deleted the z-time branch March 24, 2023 00:04

	/// a measureme event, "extra verbose" generic activities also print a timing entry to
	/// a measurement event, "extra verbose" generic activities also print a timing entry to

Uh oh!

Conversation

Zoxc commented Feb 6, 2023

Uh oh!

rustbot commented Feb 6, 2023

Uh oh!

jackh726 commented Feb 6, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nnethercote commented Feb 6, 2023

Uh oh!

Zoxc commented Feb 6, 2023

Uh oh!

nnethercote commented Feb 13, 2023

Uh oh!

Zoxc commented Feb 15, 2023

Uh oh!

bors commented Feb 15, 2023

Uh oh!

nnethercote commented Feb 16, 2023

Uh oh!

bors commented Feb 16, 2023

Uh oh!

Zoxc commented Feb 22, 2023

Uh oh!

rustbot commented Mar 14, 2023

Uh oh!

Zoxc commented Mar 14, 2023

Uh oh!

nnethercote left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Zoxc commented Mar 21, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nnethercote commented Mar 22, 2023

Uh oh!

bors commented Mar 22, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

8 participants

Zoxc commented Mar 21, 2023 •

edited

Loading