From eea06de0c894921deab541ad03c5ab728d4c449b Mon Sep 17 00:00:00 2001 From: Nicholas Nethercote Date: Thu, 6 Oct 2022 14:13:12 +1100 Subject: [PATCH 1/3] Fix some comments. - It's `--print`, not `--prints`. - `-Ztime` and `-Ztime-passes` print to stderr, not stdout. --- compiler/rustc_data_structures/src/profiling.rs | 8 ++++---- compiler/rustc_driver/src/lib.rs | 4 ++-- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/compiler/rustc_data_structures/src/profiling.rs b/compiler/rustc_data_structures/src/profiling.rs index d8b26f9840b63..3e74032d8516d 100644 --- a/compiler/rustc_data_structures/src/profiling.rs +++ b/compiler/rustc_data_structures/src/profiling.rs @@ -158,10 +158,10 @@ pub struct SelfProfilerRef { // actually enabled. event_filter_mask: EventFilter, - // Print verbose generic activities to stdout + // Print verbose generic activities to stderr. print_verbose_generic_activities: bool, - // Print extra verbose generic activities to stdout + // Print extra verbose generic activities to stderr. print_extra_verbose_generic_activities: bool, } @@ -214,7 +214,7 @@ impl SelfProfilerRef { /// Start profiling a verbose generic activity. Profiling continues until the /// VerboseTimingGuard returned from this call is dropped. In addition to recording /// a measureme event, "verbose" generic activities also print a timing entry to - /// stdout if the compiler is invoked with -Ztime or -Ztime-passes. + /// stderr if the compiler is invoked with -Ztime or -Ztime-passes. pub fn verbose_generic_activity<'a>( &'a self, event_label: &'static str, @@ -228,7 +228,7 @@ impl SelfProfilerRef { /// 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 - /// stdout if the compiler is invoked with -Ztime-passes. + /// stderr if the compiler is invoked with -Ztime-passes. pub fn extra_verbose_generic_activity<'a, A>( &'a self, event_label: &'static str, diff --git a/compiler/rustc_driver/src/lib.rs b/compiler/rustc_driver/src/lib.rs index fcd49f5d01567..97657767f5618 100644 --- a/compiler/rustc_driver/src/lib.rs +++ b/compiler/rustc_driver/src/lib.rs @@ -128,8 +128,8 @@ pub struct TimePassesCallbacks { impl Callbacks for TimePassesCallbacks { fn config(&mut self, config: &mut interface::Config) { - // If a --prints=... option has been given, we don't print the "total" - // time because it will mess up the --prints output. See #64339. + // If a --print=... option has been given, we don't print the "total" + // time because it will mess up the --print output. See #64339. self.time_passes = config.opts.prints.is_empty() && config.opts.time_passes(); config.opts.trimmed_def_paths = TrimmedDefPaths::GoodPath; } From 9110d925d0b3e4842376e830f4404a28e1aa2658 Mon Sep 17 00:00:00 2001 From: Nicholas Nethercote Date: Thu, 6 Oct 2022 14:51:45 +1100 Subject: [PATCH 2/3] Remove `-Ztime` option. The compiler currently has `-Ztime` and `-Ztime-passes`. I've used `-Ztime-passes` for years but only recently learned about `-Ztime`. What's the difference? Let's look at the `-Zhelp` output: ``` -Z time=val -- measure time of rustc processes (default: no) -Z time-passes=val -- measure time of each rustc pass (default: no) ``` The `-Ztime-passes` description is clear, but the `-Ztime` one is less so. Sounds like it measures the time for the entire process? No. The real difference is that `-Ztime-passes` prints out info about passes, and `-Ztime` does the same, but only for a subset of those passes. More specifically, there is a distinction in the profiling code between a "verbose generic activity" and an "extra verbose generic activity". `-Ztime-passes` prints both kinds, while `-Ztime` only prints the first one. (It took me a close reading of the source code to determine this difference.) In practice this distinction has low value. Perhaps in the past the "extra verbose" output was more voluminous, but now that we only print stats for a pass if it exceeds 5ms or alters the RSS, `-Ztime-passes` is less spammy. Also, a lot of the "extra verbose" cases are for individual lint passes, and you need to also use `-Zno-interleave-lints` to see those anyway. Therefore, this commit removes `-Ztime` and the associated machinery. One thing to note is that the existing "extra verbose" activities all have an extra string argument, so the commit adds the ability to accept an extra argument to the "verbose" activities. --- compiler/rustc_codegen_llvm/src/back/lto.rs | 2 +- compiler/rustc_codegen_ssa/src/back/write.rs | 2 +- .../rustc_data_structures/src/profiling.rs | 24 +++++-------------- compiler/rustc_driver/src/lib.rs | 5 +++- compiler/rustc_interface/src/tests.rs | 1 - compiler/rustc_lint/src/early.rs | 2 +- compiler/rustc_lint/src/late.rs | 17 +++++++------ .../rustc_query_impl/src/on_disk_cache.rs | 2 +- compiler/rustc_session/src/options.rs | 11 --------- compiler/rustc_session/src/session.rs | 11 ++++----- src/bootstrap/bin/rustc.rs | 2 +- src/doc/rustc/src/command-line-arguments.md | 2 +- src/librustdoc/formats/renderer.rs | 4 ++-- src/test/rustdoc-ui/z-help.stdout | 1 - 14 files changed, 33 insertions(+), 53 deletions(-) diff --git a/compiler/rustc_codegen_llvm/src/back/lto.rs b/compiler/rustc_codegen_llvm/src/back/lto.rs index 2049422b79a30..cef7bf1e8034d 100644 --- a/compiler/rustc_codegen_llvm/src/back/lto.rs +++ b/compiler/rustc_codegen_llvm/src/back/lto.rs @@ -573,7 +573,7 @@ pub(crate) fn run_pass_manager( module: &mut ModuleCodegen, thin: bool, ) -> Result<(), FatalError> { - let _timer = cgcx.prof.extra_verbose_generic_activity("LLVM_lto_optimize", &*module.name); + let _timer = cgcx.prof.verbose_generic_activity_with_arg("LLVM_lto_optimize", &*module.name); let config = cgcx.config(module.kind); // Now we have one massive module inside of llmod. Time to run the diff --git a/compiler/rustc_codegen_ssa/src/back/write.rs b/compiler/rustc_codegen_ssa/src/back/write.rs index 680b9b642d9b2..6188094bbbdd4 100644 --- a/compiler/rustc_codegen_ssa/src/back/write.rs +++ b/compiler/rustc_codegen_ssa/src/back/write.rs @@ -1637,7 +1637,7 @@ fn start_executing_work( llvm_start_time: &mut Option>, ) { if config.time_module && llvm_start_time.is_none() { - *llvm_start_time = Some(prof.extra_verbose_generic_activity("LLVM_passes", "crate")); + *llvm_start_time = Some(prof.verbose_generic_activity("LLVM_passes")); } } } diff --git a/compiler/rustc_data_structures/src/profiling.rs b/compiler/rustc_data_structures/src/profiling.rs index 3e74032d8516d..0980d36c36e86 100644 --- a/compiler/rustc_data_structures/src/profiling.rs +++ b/compiler/rustc_data_structures/src/profiling.rs @@ -158,30 +158,21 @@ pub struct SelfProfilerRef { // actually enabled. event_filter_mask: EventFilter, - // Print verbose generic activities to stderr. + // Print verbose generic activities to stderr? print_verbose_generic_activities: bool, - - // Print extra verbose generic activities to stderr. - print_extra_verbose_generic_activities: bool, } impl SelfProfilerRef { pub fn new( profiler: Option>, print_verbose_generic_activities: bool, - print_extra_verbose_generic_activities: bool, ) -> SelfProfilerRef { // If there is no SelfProfiler then the filter mask is set to NONE, // ensuring that nothing ever tries to actually access it. let event_filter_mask = profiler.as_ref().map_or(EventFilter::empty(), |p| p.event_filter_mask); - SelfProfilerRef { - profiler, - event_filter_mask, - print_verbose_generic_activities, - print_extra_verbose_generic_activities, - } + SelfProfilerRef { profiler, event_filter_mask, print_verbose_generic_activities } } /// This shim makes sure that calls only get executed if the filter mask @@ -214,7 +205,7 @@ impl SelfProfilerRef { /// Start profiling a verbose generic activity. Profiling continues until the /// VerboseTimingGuard returned from this call is dropped. In addition to recording /// a measureme event, "verbose" generic activities also print a timing entry to - /// stderr if the compiler is invoked with -Ztime or -Ztime-passes. + /// stderr if the compiler is invoked with -Ztime-passes. pub fn verbose_generic_activity<'a>( &'a self, event_label: &'static str, @@ -225,11 +216,8 @@ impl SelfProfilerRef { VerboseTimingGuard::start(message, self.generic_activity(event_label)) } - /// 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 - /// stderr if the compiler is invoked with -Ztime-passes. - pub fn extra_verbose_generic_activity<'a, A>( + /// Like `verbose_generic_activity`, but with an extra arg. + pub fn verbose_generic_activity_with_arg<'a, A>( &'a self, event_label: &'static str, event_arg: A, @@ -237,7 +225,7 @@ impl SelfProfilerRef { where A: Borrow + Into, { - let message = if self.print_extra_verbose_generic_activities { + let message = if self.print_verbose_generic_activities { Some(format!("{}({})", event_label, event_arg.borrow())) } else { None diff --git a/compiler/rustc_driver/src/lib.rs b/compiler/rustc_driver/src/lib.rs index 97657767f5618..7d5604fcabcc9 100644 --- a/compiler/rustc_driver/src/lib.rs +++ b/compiler/rustc_driver/src/lib.rs @@ -127,10 +127,13 @@ pub struct TimePassesCallbacks { } impl Callbacks for TimePassesCallbacks { + // JUSTIFICATION: the session doesn't exist at this point. + #[allow(rustc::bad_opt_access)] fn config(&mut self, config: &mut interface::Config) { // If a --print=... option has been given, we don't print the "total" // time because it will mess up the --print output. See #64339. - self.time_passes = config.opts.prints.is_empty() && config.opts.time_passes(); + // + self.time_passes = config.opts.prints.is_empty() && config.opts.unstable_opts.time_passes; config.opts.trimmed_def_paths = TrimmedDefPaths::GoodPath; } } diff --git a/compiler/rustc_interface/src/tests.rs b/compiler/rustc_interface/src/tests.rs index 2cd959689e6cf..98eeaad976fe1 100644 --- a/compiler/rustc_interface/src/tests.rs +++ b/compiler/rustc_interface/src/tests.rs @@ -692,7 +692,6 @@ fn test_unstable_options_tracking_hash() { untracked!(span_free_formats, true); untracked!(temps_dir, Some(String::from("abc"))); untracked!(threads, 99); - untracked!(time, true); untracked!(time_llvm_passes, true); untracked!(time_passes, true); untracked!(trace_macros, true); diff --git a/compiler/rustc_lint/src/early.rs b/compiler/rustc_lint/src/early.rs index f7759bec908b4..aee870dd29d65 100644 --- a/compiler/rustc_lint/src/early.rs +++ b/compiler/rustc_lint/src/early.rs @@ -409,7 +409,7 @@ pub fn check_ast_node<'a>( if sess.opts.unstable_opts.no_interleave_lints { for (i, pass) in passes.iter_mut().enumerate() { buffered = - sess.prof.extra_verbose_generic_activity("run_lint", pass.name()).run(|| { + sess.prof.verbose_generic_activity_with_arg("run_lint", pass.name()).run(|| { early_lint_node( sess, !pre_expansion && i == 0, diff --git a/compiler/rustc_lint/src/late.rs b/compiler/rustc_lint/src/late.rs index da6f1c5eeccfd..d4e19ef6b223f 100644 --- a/compiler/rustc_lint/src/late.rs +++ b/compiler/rustc_lint/src/late.rs @@ -425,20 +425,23 @@ fn late_lint_crate<'tcx, T: LateLintPass<'tcx>>(tcx: TyCtxt<'tcx>, builtin_lints late_lint_pass_crate(tcx, builtin_lints); } else { for pass in &mut passes { - tcx.sess.prof.extra_verbose_generic_activity("run_late_lint", pass.name()).run(|| { - late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) }); - }); + tcx.sess.prof.verbose_generic_activity_with_arg("run_late_lint", pass.name()).run( + || { + late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) }); + }, + ); } let mut passes: Vec<_> = unerased_lint_store(tcx).late_module_passes.iter().map(|pass| (pass)(tcx)).collect(); for pass in &mut passes { - tcx.sess.prof.extra_verbose_generic_activity("run_late_module_lint", pass.name()).run( - || { + tcx.sess + .prof + .verbose_generic_activity_with_arg("run_late_module_lint", pass.name()) + .run(|| { late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) }); - }, - ); + }); } } } diff --git a/compiler/rustc_query_impl/src/on_disk_cache.rs b/compiler/rustc_query_impl/src/on_disk_cache.rs index 0e93f3ce1d646..e96ea682caece 100644 --- a/compiler/rustc_query_impl/src/on_disk_cache.rs +++ b/compiler/rustc_query_impl/src/on_disk_cache.rs @@ -1067,7 +1067,7 @@ pub fn encode_query_results<'a, 'tcx, CTX, Q>( let _timer = tcx .dep_context() .profiler() - .extra_verbose_generic_activity("encode_query_results_for", std::any::type_name::()); + .verbose_generic_activity_with_arg("encode_query_results_for", std::any::type_name::()); assert!(Q::query_state(tcx).all_inactive()); let cache = Q::query_cache(tcx); diff --git a/compiler/rustc_session/src/options.rs b/compiler/rustc_session/src/options.rs index 486c514a4f5c2..8d527c05122d1 100644 --- a/compiler/rustc_session/src/options.rs +++ b/compiler/rustc_session/src/options.rs @@ -280,14 +280,6 @@ macro_rules! options { ) } -impl Options { - // JUSTIFICATION: defn of the suggested wrapper fn - #[allow(rustc::bad_opt_access)] - pub fn time_passes(&self) -> bool { - self.unstable_opts.time_passes || self.unstable_opts.time - } -} - impl CodegenOptions { // JUSTIFICATION: defn of the suggested wrapper fn #[allow(rustc::bad_opt_access)] @@ -1596,9 +1588,6 @@ options! { #[rustc_lint_opt_deny_field_access("use `Session::threads` instead of this field")] threads: usize = (1, parse_threads, [UNTRACKED], "use a thread pool with N threads"), - #[rustc_lint_opt_deny_field_access("use `Session::time_passes` instead of this field")] - time: bool = (false, parse_bool, [UNTRACKED], - "measure time of rustc processes (default: no)"), #[rustc_lint_opt_deny_field_access("use `Session::time_llvm_passes` instead of this field")] time_llvm_passes: bool = (false, parse_bool, [UNTRACKED], "measure time of each LLVM pass (default: no)"), diff --git a/compiler/rustc_session/src/session.rs b/compiler/rustc_session/src/session.rs index 59b544ce9eb83..5926cdc9dad9a 100644 --- a/compiler/rustc_session/src/session.rs +++ b/compiler/rustc_session/src/session.rs @@ -606,10 +606,6 @@ impl Session { self.parse_sess.source_map() } - pub fn time_passes(&self) -> bool { - self.opts.time_passes() - } - /// Returns `true` if internal lints should be added to the lint store - i.e. if /// `-Zunstable-options` is provided and this isn't rustdoc (internal lints can trigger errors /// to be emitted under rustdoc). @@ -927,6 +923,10 @@ impl Session { self.opts.unstable_opts.instrument_mcount } + pub fn time_passes(&self) -> bool { + self.opts.unstable_opts.time_passes + } + pub fn time_llvm_passes(&self) -> bool { self.opts.unstable_opts.time_llvm_passes } @@ -1403,8 +1403,7 @@ pub fn build_session( CguReuseTracker::new_disabled() }; - let prof = - SelfProfilerRef::new(self_profiler, sopts.time_passes(), sopts.unstable_opts.time_passes); + let prof = SelfProfilerRef::new(self_profiler, sopts.unstable_opts.time_passes); let ctfe_backtrace = Lock::new(match env::var("RUSTC_CTFE_BACKTRACE") { Ok(ref val) if val == "immediate" => CtfeBacktrace::Immediate, diff --git a/src/bootstrap/bin/rustc.rs b/src/bootstrap/bin/rustc.rs index e96f8b0d3125f..776d73b98c4f1 100644 --- a/src/bootstrap/bin/rustc.rs +++ b/src/bootstrap/bin/rustc.rs @@ -67,7 +67,7 @@ fn main() { if target == "all" || target.into_string().unwrap().split(',').any(|c| c.trim() == crate_name) { - cmd.arg("-Ztime"); + cmd.arg("-Ztime-passes"); } } } diff --git a/src/doc/rustc/src/command-line-arguments.md b/src/doc/rustc/src/command-line-arguments.md index 79cdfb82e417e..2d12cf382b160 100644 --- a/src/doc/rustc/src/command-line-arguments.md +++ b/src/doc/rustc/src/command-line-arguments.md @@ -300,7 +300,7 @@ _Note:_ The order of these lint level arguments is taken into account, see [lint ## `-Z`: set unstable options This flag will allow you to set unstable options of rustc. In order to set multiple options, -the -Z flag can be used multiple times. For example: `rustc -Z verbose -Z time`. +the -Z flag can be used multiple times. For example: `rustc -Z verbose -Z time-passes`. Specifying options with -Z is only available on nightly. To view all available options run: `rustc -Z help`. diff --git a/src/librustdoc/formats/renderer.rs b/src/librustdoc/formats/renderer.rs index 62ba984acc961..6f9cc026675b6 100644 --- a/src/librustdoc/formats/renderer.rs +++ b/src/librustdoc/formats/renderer.rs @@ -58,7 +58,7 @@ pub(crate) fn run_format<'tcx, T: FormatRenderer<'tcx>>( let emit_crate = options.should_emit_crate(); let (mut format_renderer, krate) = prof - .extra_verbose_generic_activity("create_renderer", T::descr()) + .verbose_generic_activity_with_arg("create_renderer", T::descr()) .run(|| T::init(krate, options, cache, tcx))?; if !emit_crate { @@ -92,6 +92,6 @@ pub(crate) fn run_format<'tcx, T: FormatRenderer<'tcx>>( .run(|| cx.item(item))?; } } - prof.extra_verbose_generic_activity("renderer_after_krate", T::descr()) + prof.verbose_generic_activity_with_arg("renderer_after_krate", T::descr()) .run(|| format_renderer.after_krate()) } diff --git a/src/test/rustdoc-ui/z-help.stdout b/src/test/rustdoc-ui/z-help.stdout index 25d5c6e4ad2b9..65536cb3aa135 100644 --- a/src/test/rustdoc-ui/z-help.stdout +++ b/src/test/rustdoc-ui/z-help.stdout @@ -170,7 +170,6 @@ -Z thinlto=val -- enable ThinLTO when possible -Z thir-unsafeck=val -- use the THIR unsafety checker (default: no) -Z threads=val -- use a thread pool with N threads - -Z time=val -- measure time of rustc processes (default: no) -Z time-llvm-passes=val -- measure time of each LLVM pass (default: no) -Z time-passes=val -- measure time of each rustc pass (default: no) -Z tls-model=val -- choose the TLS model to use (`rustc --print tls-models` for details) From 4e8faff3a15968970a6810e0af0eafea14f9f7f1 Mon Sep 17 00:00:00 2001 From: Nicholas Nethercote Date: Thu, 6 Oct 2022 15:39:27 +1100 Subject: [PATCH 3/3] Be consistent about deciding whether to print pass data. `print_time_passes_entry` unconditionally prints data about a pass. The most commonly used call site, in `VerboseTimingGuard::drop`, guards it with a `should_print_passes` test. But there are a couple of other call sites that don't do that test. This commit moves the `should_print_passes` test within `print_time_passes_entry` so that all passes are treated equally. --- .../rustc_data_structures/src/profiling.rs | 40 ++++++++++--------- 1 file changed, 21 insertions(+), 19 deletions(-) diff --git a/compiler/rustc_data_structures/src/profiling.rs b/compiler/rustc_data_structures/src/profiling.rs index 0980d36c36e86..ba1960805d84b 100644 --- a/compiler/rustc_data_structures/src/profiling.rs +++ b/compiler/rustc_data_structures/src/profiling.rs @@ -733,27 +733,9 @@ impl Drop for VerboseTimingGuard<'_> { if let Some((start_time, start_rss, ref message)) = self.start_and_message { let end_rss = get_resident_set_size(); let dur = start_time.elapsed(); - - if should_print_passes(dur, start_rss, end_rss) { - print_time_passes_entry(&message, dur, start_rss, end_rss); - } - } - } -} - -fn should_print_passes(dur: Duration, start_rss: Option, end_rss: Option) -> bool { - if dur.as_millis() > 5 { - return true; - } - - if let (Some(start_rss), Some(end_rss)) = (start_rss, end_rss) { - let change_rss = end_rss.abs_diff(start_rss); - if change_rss > 0 { - return true; + print_time_passes_entry(&message, dur, start_rss, end_rss); } } - - false } pub fn print_time_passes_entry( @@ -762,6 +744,26 @@ pub fn print_time_passes_entry( start_rss: Option, end_rss: Option, ) { + // Print the pass if its duration is greater than 5 ms, or it changed the + // measured RSS. + let is_notable = || { + if dur.as_millis() > 5 { + return true; + } + + if let (Some(start_rss), Some(end_rss)) = (start_rss, end_rss) { + let change_rss = end_rss.abs_diff(start_rss); + if change_rss > 0 { + return true; + } + } + + false + }; + if !is_notable() { + return; + } + let rss_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as usize; let rss_change_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as i128;