Rollup merge of #107718 - Zoxc:z-time, r=nnethercote

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

This adds back the `-Z time` option as that is useful for [my rustc benchmark tool](https://github.com/Zoxc/rcb), reverting #102725. It now uses nanoseconds and bytes as the units so it is renamed to `time-precise`.

Author: matthiaskrgr

Cargo.lock

@@ -4523,6 +4523,7 @@ dependencies = [
  "rustc_index",
  "rustc_macros",
  "rustc_serialize",
+ "serde_json",
  "smallvec",
  "stable_deref_trait",
  "stacker",

compiler/rustc_codegen_llvm/src/lib.rs

@@ -361,12 +361,12 @@ impl CodegenBackend for LlvmCodegenBackend {
             .expect("Expected LlvmCodegenBackend's OngoingCodegen, found Box<Any>")
             .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))
     }

compiler/rustc_codegen_ssa/src/base.rs

@@ -786,6 +786,7 @@ pub fn codegen_crate<B: ExtraBackendMethods>(
             total_codegen_time,
             start_rss.unwrap(),
             end_rss,
+            tcx.sess.opts.unstable_opts.time_passes_format,
         );
     }
 

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",

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]);
 }
 

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]

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<TimePassesFormat>,
 }
 
 impl SelfProfilerRef {
     pub fn new(
         profiler: Option<Arc<SelfProfiler>>,
-        print_verbose_generic_activities: bool,
+        print_verbose_generic_activities: Option<TimePassesFormat>,
     ) -> 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<str> + Into<String>,
     {
-        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<usize>,
+    message: String,
+    format: TimePassesFormat,
+}
+
 #[must_use]
 pub struct VerboseTimingGuard<'a> {
-    start_and_message: Option<(Instant, Option<usize>, String)>,
+    info: Option<VerboseInfo>,
     _guard: TimingGuard<'a>,
 }
 
 impl<'a> VerboseTimingGuard<'a> {
-    pub fn start(message: Option<String>, _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<usize>,
     end_rss: Option<usize>,
+    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 = || {

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<TimePassesFormat>,
 }
 
 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)

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);

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);