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.
This commit is contained in:
Nicholas Nethercote 2022-10-06 14:51:45 +11:00
parent eea06de0c8
commit 9110d925d0
14 changed files with 33 additions and 53 deletions

View File

@ -573,7 +573,7 @@ pub(crate) fn run_pass_manager(
module: &mut ModuleCodegen<ModuleLlvm>, module: &mut ModuleCodegen<ModuleLlvm>,
thin: bool, thin: bool,
) -> Result<(), FatalError> { ) -> 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); let config = cgcx.config(module.kind);
// Now we have one massive module inside of llmod. Time to run the // Now we have one massive module inside of llmod. Time to run the

View File

@ -1637,7 +1637,7 @@ fn start_executing_work<B: ExtraBackendMethods>(
llvm_start_time: &mut Option<VerboseTimingGuard<'a>>, llvm_start_time: &mut Option<VerboseTimingGuard<'a>>,
) { ) {
if config.time_module && llvm_start_time.is_none() { 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"));
} }
} }
} }

View File

@ -158,30 +158,21 @@ pub struct SelfProfilerRef {
// actually enabled. // actually enabled.
event_filter_mask: EventFilter, event_filter_mask: EventFilter,
// Print verbose generic activities to stderr. // Print verbose generic activities to stderr?
print_verbose_generic_activities: bool, print_verbose_generic_activities: bool,
// Print extra verbose generic activities to stderr.
print_extra_verbose_generic_activities: bool,
} }
impl SelfProfilerRef { impl SelfProfilerRef {
pub fn new( pub fn new(
profiler: Option<Arc<SelfProfiler>>, profiler: Option<Arc<SelfProfiler>>,
print_verbose_generic_activities: bool, print_verbose_generic_activities: bool,
print_extra_verbose_generic_activities: bool,
) -> SelfProfilerRef { ) -> SelfProfilerRef {
// If there is no SelfProfiler then the filter mask is set to NONE, // If there is no SelfProfiler then the filter mask is set to NONE,
// ensuring that nothing ever tries to actually access it. // ensuring that nothing ever tries to actually access it.
let event_filter_mask = let event_filter_mask =
profiler.as_ref().map_or(EventFilter::empty(), |p| p.event_filter_mask); profiler.as_ref().map_or(EventFilter::empty(), |p| p.event_filter_mask);
SelfProfilerRef { SelfProfilerRef { profiler, event_filter_mask, print_verbose_generic_activities }
profiler,
event_filter_mask,
print_verbose_generic_activities,
print_extra_verbose_generic_activities,
}
} }
/// This shim makes sure that calls only get executed if the filter mask /// 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 /// Start profiling a verbose generic activity. Profiling continues until the
/// VerboseTimingGuard returned from this call is dropped. In addition to recording /// VerboseTimingGuard returned from this call is dropped. In addition to recording
/// a measureme event, "verbose" generic activities also print a timing entry to /// 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>( pub fn verbose_generic_activity<'a>(
&'a self, &'a self,
event_label: &'static str, event_label: &'static str,
@ -225,11 +216,8 @@ impl SelfProfilerRef {
VerboseTimingGuard::start(message, self.generic_activity(event_label)) VerboseTimingGuard::start(message, self.generic_activity(event_label))
} }
/// Start profiling an extra verbose generic activity. Profiling continues until the /// Like `verbose_generic_activity`, but with an extra arg.
/// VerboseTimingGuard returned from this call is dropped. In addition to recording pub fn verbose_generic_activity_with_arg<'a, A>(
/// 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>(
&'a self, &'a self,
event_label: &'static str, event_label: &'static str,
event_arg: A, event_arg: A,
@ -237,7 +225,7 @@ impl SelfProfilerRef {
where where
A: Borrow<str> + Into<String>, A: Borrow<str> + Into<String>,
{ {
let message = if self.print_extra_verbose_generic_activities { let message = if self.print_verbose_generic_activities {
Some(format!("{}({})", event_label, event_arg.borrow())) Some(format!("{}({})", event_label, event_arg.borrow()))
} else { } else {
None None

View File

@ -127,10 +127,13 @@ pub struct TimePassesCallbacks {
} }
impl Callbacks for 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) { fn config(&mut self, config: &mut interface::Config) {
// If a --print=... option has been given, we don't print the "total" // If a --print=... option has been given, we don't print the "total"
// time because it will mess up the --print output. See #64339. // 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; config.opts.trimmed_def_paths = TrimmedDefPaths::GoodPath;
} }
} }

View File

@ -692,7 +692,6 @@ fn test_unstable_options_tracking_hash() {
untracked!(span_free_formats, true); untracked!(span_free_formats, true);
untracked!(temps_dir, Some(String::from("abc"))); untracked!(temps_dir, Some(String::from("abc")));
untracked!(threads, 99); untracked!(threads, 99);
untracked!(time, true);
untracked!(time_llvm_passes, true); untracked!(time_llvm_passes, true);
untracked!(time_passes, true); untracked!(time_passes, true);
untracked!(trace_macros, true); untracked!(trace_macros, true);

View File

@ -409,7 +409,7 @@ pub fn check_ast_node<'a>(
if sess.opts.unstable_opts.no_interleave_lints { if sess.opts.unstable_opts.no_interleave_lints {
for (i, pass) in passes.iter_mut().enumerate() { for (i, pass) in passes.iter_mut().enumerate() {
buffered = 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( early_lint_node(
sess, sess,
!pre_expansion && i == 0, !pre_expansion && i == 0,

View File

@ -425,20 +425,23 @@ fn late_lint_crate<'tcx, T: LateLintPass<'tcx>>(tcx: TyCtxt<'tcx>, builtin_lints
late_lint_pass_crate(tcx, builtin_lints); late_lint_pass_crate(tcx, builtin_lints);
} else { } else {
for pass in &mut passes { for pass in &mut passes {
tcx.sess.prof.extra_verbose_generic_activity("run_late_lint", pass.name()).run(|| { 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) }); late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) });
}); },
);
} }
let mut passes: Vec<_> = let mut passes: Vec<_> =
unerased_lint_store(tcx).late_module_passes.iter().map(|pass| (pass)(tcx)).collect(); unerased_lint_store(tcx).late_module_passes.iter().map(|pass| (pass)(tcx)).collect();
for pass in &mut passes { 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) }); late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) });
}, });
);
} }
} }
} }

View File

@ -1067,7 +1067,7 @@ pub fn encode_query_results<'a, 'tcx, CTX, Q>(
let _timer = tcx let _timer = tcx
.dep_context() .dep_context()
.profiler() .profiler()
.extra_verbose_generic_activity("encode_query_results_for", std::any::type_name::<Q>()); .verbose_generic_activity_with_arg("encode_query_results_for", std::any::type_name::<Q>());
assert!(Q::query_state(tcx).all_inactive()); assert!(Q::query_state(tcx).all_inactive());
let cache = Q::query_cache(tcx); let cache = Q::query_cache(tcx);

View File

@ -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 { impl CodegenOptions {
// JUSTIFICATION: defn of the suggested wrapper fn // JUSTIFICATION: defn of the suggested wrapper fn
#[allow(rustc::bad_opt_access)] #[allow(rustc::bad_opt_access)]
@ -1596,9 +1588,6 @@ options! {
#[rustc_lint_opt_deny_field_access("use `Session::threads` instead of this field")] #[rustc_lint_opt_deny_field_access("use `Session::threads` instead of this field")]
threads: usize = (1, parse_threads, [UNTRACKED], threads: usize = (1, parse_threads, [UNTRACKED],
"use a thread pool with N threads"), "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")] #[rustc_lint_opt_deny_field_access("use `Session::time_llvm_passes` instead of this field")]
time_llvm_passes: bool = (false, parse_bool, [UNTRACKED], time_llvm_passes: bool = (false, parse_bool, [UNTRACKED],
"measure time of each LLVM pass (default: no)"), "measure time of each LLVM pass (default: no)"),

View File

@ -606,10 +606,6 @@ impl Session {
self.parse_sess.source_map() 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 /// 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 /// `-Zunstable-options` is provided and this isn't rustdoc (internal lints can trigger errors
/// to be emitted under rustdoc). /// to be emitted under rustdoc).
@ -927,6 +923,10 @@ impl Session {
self.opts.unstable_opts.instrument_mcount 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 { pub fn time_llvm_passes(&self) -> bool {
self.opts.unstable_opts.time_llvm_passes self.opts.unstable_opts.time_llvm_passes
} }
@ -1403,8 +1403,7 @@ pub fn build_session(
CguReuseTracker::new_disabled() CguReuseTracker::new_disabled()
}; };
let prof = let prof = SelfProfilerRef::new(self_profiler, sopts.unstable_opts.time_passes);
SelfProfilerRef::new(self_profiler, sopts.time_passes(), sopts.unstable_opts.time_passes);
let ctfe_backtrace = Lock::new(match env::var("RUSTC_CTFE_BACKTRACE") { let ctfe_backtrace = Lock::new(match env::var("RUSTC_CTFE_BACKTRACE") {
Ok(ref val) if val == "immediate" => CtfeBacktrace::Immediate, Ok(ref val) if val == "immediate" => CtfeBacktrace::Immediate,

View File

@ -67,7 +67,7 @@ fn main() {
if target == "all" if target == "all"
|| target.into_string().unwrap().split(',').any(|c| c.trim() == crate_name) || target.into_string().unwrap().split(',').any(|c| c.trim() == crate_name)
{ {
cmd.arg("-Ztime"); cmd.arg("-Ztime-passes");
} }
} }
} }

View File

@ -300,7 +300,7 @@ _Note:_ The order of these lint level arguments is taken into account, see [lint
## `-Z`: set unstable options ## `-Z`: set unstable options
This flag will allow you to set unstable options of rustc. In order to set multiple 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 Specifying options with -Z is only available on nightly. To view all available options
run: `rustc -Z help`. run: `rustc -Z help`.

View File

@ -58,7 +58,7 @@ pub(crate) fn run_format<'tcx, T: FormatRenderer<'tcx>>(
let emit_crate = options.should_emit_crate(); let emit_crate = options.should_emit_crate();
let (mut format_renderer, krate) = prof 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))?; .run(|| T::init(krate, options, cache, tcx))?;
if !emit_crate { if !emit_crate {
@ -92,6 +92,6 @@ pub(crate) fn run_format<'tcx, T: FormatRenderer<'tcx>>(
.run(|| cx.item(item))?; .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()) .run(|| format_renderer.after_krate())
} }

View File

@ -170,7 +170,6 @@
-Z thinlto=val -- enable ThinLTO when possible -Z thinlto=val -- enable ThinLTO when possible
-Z thir-unsafeck=val -- use the THIR unsafety checker (default: no) -Z thir-unsafeck=val -- use the THIR unsafety checker (default: no)
-Z threads=val -- use a thread pool with N threads -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-llvm-passes=val -- measure time of each LLVM pass (default: no)
-Z time-passes=val -- measure time of each rustc 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) -Z tls-model=val -- choose the TLS model to use (`rustc --print tls-models` for details)