diff --git a/Cargo.lock b/Cargo.lock index 3495f4d51afdb..3ca784032e133 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_llvm/src/lib.rs b/compiler/rustc_codegen_llvm/src/lib.rs index 8dafe1b750b33..e5bae009ed64b 100644 --- a/compiler/rustc_codegen_llvm/src/lib.rs +++ b/compiler/rustc_codegen_llvm/src/lib.rs @@ -361,12 +361,12 @@ impl CodegenBackend for LlvmCodegenBackend { .expect("Expected LlvmCodegenBackend's OngoingCodegen, found Box") .join(sess); - sess.time("llvm_dump_timing_file", || { - if sess.opts.unstable_opts.llvm_time_trace { + if sess.opts.unstable_opts.llvm_time_trace { + sess.time("llvm_dump_timing_file", || { let file_name = outputs.with_extension("llvm_timings.json"); llvm_util::time_trace_profiler_finish(&file_name); - } - }); + }); + } Ok((codegen_results, work_products)) } diff --git a/compiler/rustc_codegen_ssa/src/base.rs b/compiler/rustc_codegen_ssa/src/base.rs index 4d34b3da5f501..c3c8649dbff47 100644 --- a/compiler/rustc_codegen_ssa/src/base.rs +++ b/compiler/rustc_codegen_ssa/src/base.rs @@ -786,6 +786,7 @@ pub fn codegen_crate( total_codegen_time, start_rss.unwrap(), end_rss, + tcx.sess.opts.unstable_opts.time_passes_format, ); } diff --git a/compiler/rustc_data_structures/Cargo.toml b/compiler/rustc_data_structures/Cargo.toml index 24cf9812a25a1..056ee1f63be03 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 820a70fc8e446..513df666d0da1 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 c8f979267170f..7c866da60090f 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 3d9c7f6eae276..58a0609e29655 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)) } /// Like `verbose_generic_activity`, but with an extra arg. @@ -221,11 +232,14 @@ 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), + ) } /// Start profiling a generic activity. Profiling continues until the @@ -703,17 +717,32 @@ impl<'a> TimingGuard<'a> { } } +struct VerboseInfo { + start_time: Instant, + start_rss: Option, + message: String, + format: TimePassesFormat, +} + #[must_use] pub struct VerboseTimingGuard<'a> { - start_and_message: Option<(Instant, Option, String)>, + info: Option, _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>, + ) -> Self { VerboseTimingGuard { _guard, - start_and_message: message.map(|msg| (Instant::now(), get_resident_set_size(), msg)), + info: message_and_format.map(|(message, format)| VerboseInfo { + start_time: Instant::now(), + start_rss: get_resident_set_size(), + message, + format, + }), } } @@ -726,10 +755,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(info) = &self.info { let end_rss = get_resident_set_size(); - let dur = start_time.elapsed(); - print_time_passes_entry(message, dur, start_rss, end_rss); + let dur = info.start_time.elapsed(); + print_time_passes_entry(&info.message, dur, info.start_rss, end_rss, info.format); } } } @@ -739,7 +768,22 @@ pub fn print_time_passes_entry( dur: Duration, start_rss: Option, end_rss: Option, + format: TimePassesFormat, ) { + match format { + TimePassesFormat::Json => { + let json = json!({ + "pass": what, + "time": dur.as_secs_f64(), + "rss_start": start_rss, + "rss_end": end_rss, + }); + eprintln!("time: {}", json.to_string()); + return; + } + TimePassesFormat::Text => (), + } + // 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 14d6569271eeb..1e835f6065a63 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); } process::exit(exit_code) diff --git a/compiler/rustc_hir_analysis/src/coherence/mod.rs b/compiler/rustc_hir_analysis/src/coherence/mod.rs index 23490bc091c1c..465e787c92ae6 100644 --- a/compiler/rustc_hir_analysis/src/coherence/mod.rs +++ b/compiler/rustc_hir_analysis/src/coherence/mod.rs @@ -133,8 +133,8 @@ fn coherent_trait(tcx: TyCtxt<'_>, def_id: DefId) { check_impl(tcx, impl_def_id, trait_ref); check_object_overlap(tcx, impl_def_id, trait_ref); - tcx.sess.time("unsafety_checking", || unsafety::check_item(tcx, impl_def_id)); - tcx.sess.time("orphan_checking", || tcx.ensure().orphan_check_impl(impl_def_id)); + unsafety::check_item(tcx, impl_def_id); + tcx.ensure().orphan_check_impl(impl_def_id); } builtin::check_trait(tcx, def_id); diff --git a/compiler/rustc_interface/src/tests.rs b/compiler/rustc_interface/src/tests.rs index 014810dba9cce..eb5990507fb6d 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 0548379dc2fc1..c75af48e80af4 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 700a059c368ba..5730df9d5c6b9 100644 --- a/compiler/rustc_session/src/session.rs +++ b/compiler/rustc_session/src/session.rs @@ -1453,7 +1453,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/tests/rustdoc-ui/z-help.stdout b/tests/rustdoc-ui/z-help.stdout index 5ad38e4fd9821..72f5f933d8db4 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)