From f60d2eb6c19751154a2c752d1c916420c0bb60e6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?John=20K=C3=A5re=20Alsaker?= Date: Mon, 6 Feb 2023 06:32:34 +0100 Subject: [PATCH] Add `-Z time-passes-format` to allow specifying a JSON output for `-Z time-passes` --- Cargo.lock | 1 + compiler/rustc_codegen_ssa/src/base.rs | 2 + compiler/rustc_data_structures/Cargo.toml | 1 + .../src/graph/scc/tests.rs | 6 +- .../src/graph/vec_graph/tests.rs | 6 +- .../rustc_data_structures/src/profiling.rs | 72 +++++++++++++++---- compiler/rustc_driver_impl/src/lib.rs | 13 ++-- compiler/rustc_interface/src/tests.rs | 2 + compiler/rustc_session/src/options.rs | 19 +++++ compiler/rustc_session/src/session.rs | 5 +- compiler/rustc_session/src/utils.rs | 4 +- tests/rustdoc-ui/z-help.stdout | 1 + 12 files changed, 105 insertions(+), 27 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 61f2cfb9e22..e5eae1a83c1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4523,6 +4523,7 @@ dependencies = [ "rustc_index", "rustc_macros", "rustc_serialize", + "serde_json", "smallvec", "stable_deref_trait", "stacker", diff --git a/compiler/rustc_codegen_ssa/src/base.rs b/compiler/rustc_codegen_ssa/src/base.rs index abc510e360d..a109633520a 100644 --- a/compiler/rustc_codegen_ssa/src/base.rs +++ b/compiler/rustc_codegen_ssa/src/base.rs @@ -786,6 +786,8 @@ pub fn codegen_crate( total_codegen_time, start_rss.unwrap(), end_rss, + tcx.sess.opts.unstable_opts.time_passes_format, + true, ); } diff --git a/compiler/rustc_data_structures/Cargo.toml b/compiler/rustc_data_structures/Cargo.toml index 24cf9812a25..056ee1f63be 100644 --- a/compiler/rustc_data_structures/Cargo.toml +++ b/compiler/rustc_data_structures/Cargo.toml @@ -21,6 +21,7 @@ rustc-hash = "1.1.0" rustc_index = { path = "../rustc_index", package = "rustc_index" } rustc_macros = { path = "../rustc_macros" } rustc_serialize = { path = "../rustc_serialize" } +serde_json = "1.0.59" smallvec = { version = "1.8.1", features = [ "const_generics", "union", diff --git a/compiler/rustc_data_structures/src/graph/scc/tests.rs b/compiler/rustc_data_structures/src/graph/scc/tests.rs index 820a70fc8e4..513df666d0d 100644 --- a/compiler/rustc_data_structures/src/graph/scc/tests.rs +++ b/compiler/rustc_data_structures/src/graph/scc/tests.rs @@ -56,7 +56,7 @@ fn test_three_sccs() { assert_eq!(sccs.scc(1), 0); assert_eq!(sccs.scc(2), 0); assert_eq!(sccs.scc(3), 2); - assert_eq!(sccs.successors(0), &[]); + assert_eq!(sccs.successors(0), &[] as &[usize]); assert_eq!(sccs.successors(1), &[0]); assert_eq!(sccs.successors(2), &[0]); } @@ -113,7 +113,7 @@ fn test_find_state_2() { assert_eq!(sccs.scc(2), 0); assert_eq!(sccs.scc(3), 0); assert_eq!(sccs.scc(4), 0); - assert_eq!(sccs.successors(0), &[]); + assert_eq!(sccs.successors(0), &[] as &[usize]); } #[test] @@ -138,7 +138,7 @@ fn test_find_state_3() { assert_eq!(sccs.scc(3), 0); assert_eq!(sccs.scc(4), 0); assert_eq!(sccs.scc(5), 1); - assert_eq!(sccs.successors(0), &[]); + assert_eq!(sccs.successors(0), &[] as &[usize]); assert_eq!(sccs.successors(1), &[0]); } diff --git a/compiler/rustc_data_structures/src/graph/vec_graph/tests.rs b/compiler/rustc_data_structures/src/graph/vec_graph/tests.rs index c8f97926717..7c866da6009 100644 --- a/compiler/rustc_data_structures/src/graph/vec_graph/tests.rs +++ b/compiler/rustc_data_structures/src/graph/vec_graph/tests.rs @@ -27,11 +27,11 @@ fn successors() { let graph = create_graph(); assert_eq!(graph.successors(0), &[1]); assert_eq!(graph.successors(1), &[2, 3]); - assert_eq!(graph.successors(2), &[]); + assert_eq!(graph.successors(2), &[] as &[usize]); assert_eq!(graph.successors(3), &[4]); - assert_eq!(graph.successors(4), &[]); + assert_eq!(graph.successors(4), &[] as &[usize]); assert_eq!(graph.successors(5), &[1]); - assert_eq!(graph.successors(6), &[]); + assert_eq!(graph.successors(6), &[] as &[usize]); } #[test] diff --git a/compiler/rustc_data_structures/src/profiling.rs b/compiler/rustc_data_structures/src/profiling.rs index 3d9c7f6eae2..87b74903d51 100644 --- a/compiler/rustc_data_structures/src/profiling.rs +++ b/compiler/rustc_data_structures/src/profiling.rs @@ -97,6 +97,7 @@ use std::time::{Duration, Instant}; pub use measureme::EventId; use measureme::{EventIdBuilder, Profiler, SerializableString, StringId}; use parking_lot::RwLock; +use serde_json::json; use smallvec::SmallVec; bitflags::bitflags! { @@ -145,6 +146,15 @@ const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[ /// Something that uniquely identifies a query invocation. pub struct QueryInvocationId(pub u32); +/// Which format to use for `-Z time-passes` +#[derive(Clone, Copy, PartialEq, Hash, Debug)] +pub enum TimePassesFormat { + /// Emit human readable text + Text, + /// Emit structured JSON + Json, +} + /// A reference to the SelfProfiler. It can be cloned and sent across thread /// boundaries at will. #[derive(Clone)] @@ -158,14 +168,14 @@ pub struct SelfProfilerRef { // actually enabled. event_filter_mask: EventFilter, - // Print verbose generic activities to stderr? - print_verbose_generic_activities: bool, + // Print verbose generic activities to stderr. + print_verbose_generic_activities: Option, } impl SelfProfilerRef { pub fn new( profiler: Option>, - print_verbose_generic_activities: bool, + print_verbose_generic_activities: Option, ) -> SelfProfilerRef { // If there is no SelfProfiler then the filter mask is set to NONE, // ensuring that nothing ever tries to actually access it. @@ -207,9 +217,10 @@ impl SelfProfilerRef { /// a measureme event, "verbose" generic activities also print a timing entry to /// stderr if the compiler is invoked with -Ztime-passes. pub fn verbose_generic_activity(&self, event_label: &'static str) -> VerboseTimingGuard<'_> { - let message = self.print_verbose_generic_activities.then(|| event_label.to_owned()); + let message_and_format = + self.print_verbose_generic_activities.map(|format| (event_label.to_owned(), format)); - VerboseTimingGuard::start(message, self.generic_activity(event_label)) + VerboseTimingGuard::start(message_and_format, self.generic_activity(event_label), false) } /// Like `verbose_generic_activity`, but with an extra arg. @@ -221,11 +232,26 @@ impl SelfProfilerRef { where A: Borrow + Into, { - let message = self + let message_and_format = self .print_verbose_generic_activities - .then(|| format!("{}({})", event_label, event_arg.borrow())); + .map(|format| (format!("{}({})", event_label, event_arg.borrow()), format)); - VerboseTimingGuard::start(message, self.generic_activity_with_arg(event_label, event_arg)) + VerboseTimingGuard::start( + message_and_format, + self.generic_activity_with_arg(event_label, event_arg), + false, + ) + } + + /// Like `verbose_generic_activity`, but `event_label` must be unique for a rustc session. + pub fn unique_verbose_generic_activity( + &self, + event_label: &'static str, + ) -> VerboseTimingGuard<'_> { + let message_and_format = + self.print_verbose_generic_activities.map(|format| (event_label.to_owned(), format)); + + VerboseTimingGuard::start(message_and_format, self.generic_activity(event_label), true) } /// Start profiling a generic activity. Profiling continues until the @@ -705,15 +731,21 @@ impl<'a> TimingGuard<'a> { #[must_use] pub struct VerboseTimingGuard<'a> { - start_and_message: Option<(Instant, Option, String)>, + start_and_message: Option<(Instant, Option, String, TimePassesFormat, bool)>, _guard: TimingGuard<'a>, } impl<'a> VerboseTimingGuard<'a> { - pub fn start(message: Option, _guard: TimingGuard<'a>) -> Self { + pub fn start( + message_and_format: Option<(String, TimePassesFormat)>, + _guard: TimingGuard<'a>, + unique: bool, + ) -> Self { VerboseTimingGuard { _guard, - start_and_message: message.map(|msg| (Instant::now(), get_resident_set_size(), msg)), + start_and_message: message_and_format.map(|(msg, format)| { + (Instant::now(), get_resident_set_size(), msg, format, unique) + }), } } @@ -726,10 +758,10 @@ impl<'a> VerboseTimingGuard<'a> { impl Drop for VerboseTimingGuard<'_> { fn drop(&mut self) { - if let Some((start_time, start_rss, ref message)) = self.start_and_message { + if let Some((start_time, start_rss, ref message, format, unique)) = self.start_and_message { let end_rss = get_resident_set_size(); let dur = start_time.elapsed(); - print_time_passes_entry(message, dur, start_rss, end_rss); + print_time_passes_entry(message, dur, start_rss, end_rss, format, unique); } } } @@ -739,7 +771,21 @@ pub fn print_time_passes_entry( dur: Duration, start_rss: Option, end_rss: Option, + format: TimePassesFormat, + unique: bool, ) { + if format == TimePassesFormat::Json { + let json = json!({ + "pass": what, + "time": dur.as_secs_f64(), + "rss_start": start_rss, + "rss_end": end_rss, + "unique": unique, + }); + eprintln!("time: {}", json.to_string()); + return; + } + // Print the pass if its duration is greater than 5 ms, or it changed the // measured RSS. let is_notable = || { diff --git a/compiler/rustc_driver_impl/src/lib.rs b/compiler/rustc_driver_impl/src/lib.rs index 8634c644176..d44bd7fdb18 100644 --- a/compiler/rustc_driver_impl/src/lib.rs +++ b/compiler/rustc_driver_impl/src/lib.rs @@ -20,7 +20,9 @@ pub extern crate rustc_plugin_impl as plugin; use rustc_ast as ast; use rustc_codegen_ssa::{traits::CodegenBackend, CodegenErrors, CodegenResults}; -use rustc_data_structures::profiling::{get_resident_set_size, print_time_passes_entry}; +use rustc_data_structures::profiling::{ + get_resident_set_size, print_time_passes_entry, TimePassesFormat, +}; use rustc_data_structures::sync::SeqCst; use rustc_errors::registry::{InvalidErrorCode, Registry}; use rustc_errors::{ @@ -161,7 +163,7 @@ pub trait Callbacks { #[derive(Default)] pub struct TimePassesCallbacks { - time_passes: bool, + time_passes: Option, } impl Callbacks for TimePassesCallbacks { @@ -171,7 +173,8 @@ impl Callbacks for TimePassesCallbacks { // 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.unstable_opts.time_passes; + self.time_passes = (config.opts.prints.is_empty() && config.opts.unstable_opts.time_passes) + .then(|| config.opts.unstable_opts.time_passes_format); config.opts.trimmed_def_paths = TrimmedDefPaths::GoodPath; } } @@ -1354,9 +1357,9 @@ pub fn main() -> ! { RunCompiler::new(&args, &mut callbacks).run() }); - if callbacks.time_passes { + if let Some(format) = callbacks.time_passes { let end_rss = get_resident_set_size(); - print_time_passes_entry("total", start_time.elapsed(), start_rss, end_rss); + print_time_passes_entry("total", start_time.elapsed(), start_rss, end_rss, format, true); } process::exit(exit_code) diff --git a/compiler/rustc_interface/src/tests.rs b/compiler/rustc_interface/src/tests.rs index 014810dba9c..eb5990507fb 100644 --- a/compiler/rustc_interface/src/tests.rs +++ b/compiler/rustc_interface/src/tests.rs @@ -2,6 +2,7 @@ use crate::interface::parse_cfgspecs; use rustc_data_structures::fx::FxHashSet; +use rustc_data_structures::profiling::TimePassesFormat; use rustc_errors::{emitter::HumanReadableErrorType, registry, ColorConfig}; use rustc_session::config::rustc_optgroups; use rustc_session::config::Input; @@ -699,6 +700,7 @@ fn test_unstable_options_tracking_hash() { untracked!(threads, 99); untracked!(time_llvm_passes, true); untracked!(time_passes, true); + untracked!(time_passes_format, TimePassesFormat::Json); untracked!(trace_macros, true); untracked!(track_diagnostics, true); untracked!(trim_diagnostic_paths, false); diff --git a/compiler/rustc_session/src/options.rs b/compiler/rustc_session/src/options.rs index 0548379dc2f..c75af48e80a 100644 --- a/compiler/rustc_session/src/options.rs +++ b/compiler/rustc_session/src/options.rs @@ -4,6 +4,7 @@ use crate::early_error; use crate::lint; use crate::search_paths::SearchPath; use crate::utils::NativeLib; +use rustc_data_structures::profiling::TimePassesFormat; use rustc_errors::{LanguageIdentifier, TerminalUrl}; use rustc_target::spec::{CodeModel, LinkerFlavorCli, MergeFunctions, PanicStrategy, SanitizerSet}; use rustc_target::spec::{ @@ -365,6 +366,7 @@ mod desc { pub const parse_number: &str = "a number"; pub const parse_opt_number: &str = parse_number; pub const parse_threads: &str = parse_number; + pub const parse_time_passes_format: &str = "`text` (default) or `json`"; pub const parse_passes: &str = "a space-separated list of passes, or `all`"; pub const parse_panic_strategy: &str = "either `unwind` or `abort`"; pub const parse_opt_panic_strategy: &str = parse_panic_strategy; @@ -829,6 +831,21 @@ mod parse { true } + pub(crate) fn parse_time_passes_format(slot: &mut TimePassesFormat, v: Option<&str>) -> bool { + match v { + None => true, + Some("json") => { + *slot = TimePassesFormat::Json; + true + } + Some("text") => { + *slot = TimePassesFormat::Text; + true + } + Some(_) => false, + } + } + pub(crate) fn parse_dump_mono_stats(slot: &mut DumpMonoStatsFormat, v: Option<&str>) -> bool { match v { None => true, @@ -1709,6 +1726,8 @@ options! { "measure time of each LLVM pass (default: no)"), time_passes: bool = (false, parse_bool, [UNTRACKED], "measure time of each rustc pass (default: no)"), + time_passes_format: TimePassesFormat = (TimePassesFormat::Text, parse_time_passes_format, [UNTRACKED], + "the format to use for -Z time-passes (`text` (default) or `json`)"), tiny_const_eval_limit: bool = (false, parse_bool, [TRACKED], "sets a tiny, non-configurable limit for const eval; useful for compiler tests"), #[rustc_lint_opt_deny_field_access("use `Session::tls_model` instead of this field")] diff --git a/compiler/rustc_session/src/session.rs b/compiler/rustc_session/src/session.rs index fdacf814dd6..1a3fdc7f437 100644 --- a/compiler/rustc_session/src/session.rs +++ b/compiler/rustc_session/src/session.rs @@ -1487,7 +1487,10 @@ pub fn build_session( CguReuseTracker::new_disabled() }; - let prof = SelfProfilerRef::new(self_profiler, sopts.unstable_opts.time_passes); + let prof = SelfProfilerRef::new( + self_profiler, + sopts.unstable_opts.time_passes.then(|| sopts.unstable_opts.time_passes_format), + ); let ctfe_backtrace = Lock::new(match env::var("RUSTC_CTFE_BACKTRACE") { Ok(ref val) if val == "immediate" => CtfeBacktrace::Immediate, diff --git a/compiler/rustc_session/src/utils.rs b/compiler/rustc_session/src/utils.rs index 3b3d4ca5d6b..a7feb2794c4 100644 --- a/compiler/rustc_session/src/utils.rs +++ b/compiler/rustc_session/src/utils.rs @@ -4,10 +4,10 @@ use std::path::{Path, PathBuf}; impl Session { pub fn timer(&self, what: &'static str) -> VerboseTimingGuard<'_> { - self.prof.verbose_generic_activity(what) + self.prof.unique_verbose_generic_activity(what) } pub fn time(&self, what: &'static str, f: impl FnOnce() -> R) -> R { - self.prof.verbose_generic_activity(what).run(f) + self.prof.unique_verbose_generic_activity(what).run(f) } } diff --git a/tests/rustdoc-ui/z-help.stdout b/tests/rustdoc-ui/z-help.stdout index 5ad38e4fd98..72f5f933d8d 100644 --- a/tests/rustdoc-ui/z-help.stdout +++ b/tests/rustdoc-ui/z-help.stdout @@ -183,6 +183,7 @@ -Z threads=val -- use a thread pool with N threads -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-format=val -- the format to use for -Z time-passes (`text` (default) or `json`) -Z tiny-const-eval-limit=val -- sets a tiny, non-configurable limit for const eval; useful for compiler tests -Z tls-model=val -- choose the TLS model to use (`rustc --print tls-models` for details) -Z trace-macros=val -- for every macro invocation, print its name and arguments (default: no)