Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add -Z time-passes-format to allow specifying a JSON output for -Z time-passes #107718

Merged
merged 3 commits into from
Mar 23, 2023

Conversation

Zoxc
Copy link
Contributor

@Zoxc Zoxc commented Feb 6, 2023

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
Copy link
Collaborator

rustbot commented Feb 6, 2023

r? @jackh726

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

@rustbot rustbot added A-query-system Area: The rustc query system (https://rustc-dev-guide.rust-lang.org/query.html) S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. T-rustdoc Relevant to the rustdoc team, which will review and decide on the PR/issue. labels Feb 6, 2023
@Zoxc Zoxc force-pushed the z-time branch 2 times, most recently from 4191f45 to 58afd39 Compare February 6, 2023 13:42
@jackh726
Copy link
Member

jackh726 commented Feb 6, 2023

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

Comment on lines +136 to +137
unsafety::check_item(tcx, impl_def_id);
tcx.ensure().orphan_check_impl(impl_def_id);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

drive by question: why stop timing these ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

They're done per item and are not passes.

pub fn verbose_generic_activity_with_arg<A>(
/// Start profiling an extra verbose generic activity. Profiling continues until the
/// VerboseTimingGuard returned from this call is dropped. In addition to recording
/// a measureme event, "extra verbose" generic activities also print a timing entry to
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

measureme is the profiling library ;)

@nnethercote
Copy link
Contributor

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
Copy link
Contributor Author

Zoxc commented Feb 6, 2023

-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 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
@nnethercote
Copy link
Contributor

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
Copy link
Contributor Author

Zoxc commented Feb 15, 2023

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
Copy link
Contributor

bors commented Feb 15, 2023

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

@nnethercote
Copy link
Contributor

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
Copy link
Contributor

bors commented Feb 16, 2023

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

@Zoxc
Copy link
Contributor Author

Zoxc commented Feb 22, 2023

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

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

rustbot commented Mar 14, 2023

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 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
Copy link
Contributor Author

Zoxc commented Mar 14, 2023

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.

Copy link
Contributor

@nnethercote nnethercote left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

)
}

/// Like `verbose_generic_activity`, but `event_label` must be unique for a rustc session.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@@ -705,15 +731,21 @@ impl<'a> TimingGuard<'a> {

#[must_use]
pub struct VerboseTimingGuard<'a> {
start_and_message: Option<(Instant, Option<usize>, String)>,
start_and_message: Option<(Instant, Option<usize>, String, TimePassesFormat, bool)>,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

) {
if format == TimePassesFormat::Json {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Contributor Author

Zoxc commented Mar 21, 2023

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.

@nnethercote
Copy link
Contributor

@bors r+

@bors
Copy link
Contributor

bors commented Mar 22, 2023

📌 Commit 6c57dda has been approved by nnethercote

It is now in the queue for this repository.

@bors 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
bors added a commit to rust-lang-ci/rust that referenced this pull request Mar 23, 2023
…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
@bors bors merged commit acd7f87 into rust-lang:master Mar 23, 2023
@rustbot rustbot added this to the 1.70.0 milestone Mar 23, 2023
@Zoxc Zoxc deleted the z-time branch March 24, 2023 00:04
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-CLI Area: Command-line interface (CLI) to the compiler A-query-system Area: The rustc query system (https://rustc-dev-guide.rust-lang.org/query.html) S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. T-rustdoc Relevant to the rustdoc team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants