Rollup merge of #142123 - Kobzol:timings, r=nnethercote

Implement initial support for timing sections (`--json=timings`)

This PR implements initial support for emitting high-level compilation section timings. The idea is to provide a very lightweight way of emitting durations of various compilation sections (frontend, backend, linker, or on a more granular level macro expansion, typeck, borrowck, etc.). The ultimate goal is to stabilize this output (in some form), make Cargo pass `--json=timings` and then display this information in the HTML output of `cargo build --timings`, to make it easier to quickly profile "what takes so long" during the compilation of a Cargo project. I would personally also like if Cargo printed some of this information in the interactive `cargo build` output, but the `build --timings` use-case is the main one.

Now, this information is already available with several other sources, but I don't think that we can just use them as they are, which is why I proposed a new way of outputting this data (`--json=timings`):
- This data is available under `-Zself-profile`, but that is very expensive and forever unstable. It's just a too big of a hammer to tell us the duration it took to run the linker.
- It could also be extracted with `-Ztime-passes`. That is pretty much "for free" in terms of performance, and it can be emitted in a structured form to JSON via `-Ztime-passes-format=json`. I guess that one alternative might be to stabilize this flag in some form, but that form might just be `--json=timings`? I guess what we could do in theory is take the already emitted time passes and reuse them for `--json=timings`. Happy to hear suggestions!

I'm sending this PR mostly for a vibeck, to see if the way I implemented it is passable. There are some things to figure out:
- How do we represent the sections? Originally I wanted to output `{ section, duration }`, but then I realized that it might be more useful to actually emit `start` and `end` events. Both because it enables to see the output incrementally (in case compilation takes a long time and you read the outputs directly, or Cargo decides to show this data in `cargo build` some day in the future), and because it makes it simpler to represent hierarchy (see below). The timestamps currently emit microseconds elapsed from a predetermined point in time (~start of rustc), but otherwise they are fully opaque, and should be only ever used to calculate the duration using `end - start`. We could also precompute the duration for the user in the `end` event, but that would require doing more work in rustc, which I would ideally like to avoid :P
- Do we want to have some form of hierarchy? I think that it would be nice to show some more granular sections rather than just frontend/backend/linker (e.g. macro expansion, typeck and borrowck as a part of the frontend). But for that we would need some way of representing hierarchy. A simple way would be something like `{ parent: "frontend" }`, but I realized that with start/end timestamps we get the hierarchy "for free", only the client will need to reconstruct it from the order of start/end events (e.g. `start A`, `start B` means that `B` is a child of `A`).
- What exactly do we want to stabilize? This is probably a question for later. I think that we should definitely stabilize the format of the emitted JSON objects, and *maybe* some specific section names (but we should also make it clear that they can be missing, e.g. you don't link everytime you invoke `rustc`).

The PR be tested e.g. with `rustc +stage1 src/main.rs --json=timings --error-format=json -Zunstable-options` on a crate without dependencies (it is not easy to use `--json` with stock Cargo, because it also passes this flag to `rustc`, so this will later need Cargo integration to be usable with it).

Zulip discussions: [#t-compiler > Outputting time spent in various compiler sections](https://rust-lang.zulipchat.com/#narrow/channel/131828-t-compiler/topic/Outputting.20time.20spent.20in.20various.20compiler.20sections/with/518850162)

MCP: https://github.com/rust-lang/compiler-team/issues/873

r? ``@nnethercote``

8 files changed, 156 insertions, 2 deletions

diff --git a/compiler/rustc_errors/src/emitter.rs b/compiler/rustc_errors/src/emitter.rs
index fe01e289334..6ab6f96079e 100644
--- a/compiler/rustc_errors/src/emitter.rs
+++ b/compiler/rustc_errors/src/emitter.rs
@@ -34,6 +34,7 @@ use crate::snippet::{
     Annotation, AnnotationColumn, AnnotationType, Line, MultilineAnnotation, Style, StyledString,
 };
 use crate::styled_buffer::StyledBuffer;
+use crate::timings::TimingRecord;
 use crate::translation::{Translate, to_fluent_args};
 use crate::{
     CodeSuggestion, DiagInner, DiagMessage, ErrCode, FluentBundle, LazyFallbackBundle, Level,
@@ -164,11 +165,16 @@ impl Margin {
     }
 }
 
+pub enum TimingEvent {
+    Start,
+    End,
+}
+
 const ANONYMIZED_LINE_NUM: &str = "LL";
 
 pub type DynEmitter = dyn Emitter + DynSend;
 
-/// Emitter trait for emitting errors.
+/// Emitter trait for emitting errors and other structured information.
 pub trait Emitter: Translate {
     /// Emit a structured diagnostic.
     fn emit_diagnostic(&mut self, diag: DiagInner, registry: &Registry);
@@ -177,6 +183,10 @@ pub trait Emitter: Translate {
     /// Currently only supported for the JSON format.
     fn emit_artifact_notification(&mut self, _path: &Path, _artifact_type: &str) {}
 
+    /// Emit a timestamp with start/end of a timing section.
+    /// Currently only supported for the JSON format.
+    fn emit_timing_section(&mut self, _record: TimingRecord, _event: TimingEvent) {}
+
     /// Emit a report about future breakage.
     /// Currently only supported for the JSON format.
     fn emit_future_breakage_report(&mut self, _diags: Vec<DiagInner>, _registry: &Registry) {}
diff --git a/compiler/rustc_errors/src/json.rs b/compiler/rustc_errors/src/json.rs
index a6583407b7e..d67e2ba2d60 100644
--- a/compiler/rustc_errors/src/json.rs
+++ b/compiler/rustc_errors/src/json.rs
@@ -28,9 +28,10 @@ use termcolor::{ColorSpec, WriteColor};
 use crate::diagnostic::IsLint;
 use crate::emitter::{
     ColorConfig, Destination, Emitter, HumanEmitter, HumanReadableErrorType, OutputTheme,
-    should_show_source_code,
+    TimingEvent, should_show_source_code,
 };
 use crate::registry::Registry;
+use crate::timings::{TimingRecord, TimingSection};
 use crate::translation::{Translate, to_fluent_args};
 use crate::{
     CodeSuggestion, FluentBundle, LazyFallbackBundle, MultiSpan, SpanLabel, Subdiag, Suggestions,
@@ -104,6 +105,7 @@ impl JsonEmitter {
 enum EmitTyped<'a> {
     Diagnostic(Diagnostic),
     Artifact(ArtifactNotification<'a>),
+    SectionTiming(SectionTimestamp<'a>),
     FutureIncompat(FutureIncompatReport<'a>),
     UnusedExtern(UnusedExterns<'a>),
 }
@@ -135,6 +137,21 @@ impl Emitter for JsonEmitter {
         }
     }
 
+    fn emit_timing_section(&mut self, record: TimingRecord, event: TimingEvent) {
+        let event = match event {
+            TimingEvent::Start => "start",
+            TimingEvent::End => "end",
+        };
+        let name = match record.section {
+            TimingSection::Linking => "link",
+        };
+        let data = SectionTimestamp { name, event, timestamp: record.timestamp };
+        let result = self.emit(EmitTyped::SectionTiming(data));
+        if let Err(e) = result {
+            panic!("failed to print timing section: {e:?}");
+        }
+    }
+
     fn emit_future_breakage_report(&mut self, diags: Vec<crate::DiagInner>, registry: &Registry) {
         let data: Vec<FutureBreakageItem<'_>> = diags
             .into_iter()
@@ -264,6 +281,16 @@ struct ArtifactNotification<'a> {
 }
 
 #[derive(Serialize)]
+struct SectionTimestamp<'a> {
+    /// Name of the section
+    name: &'a str,
+    /// Start/end of the section
+    event: &'a str,
+    /// Opaque timestamp.
+    timestamp: u128,
+}
+
+#[derive(Serialize)]
 struct FutureBreakageItem<'a> {
     // Always EmitTyped::Diagnostic, but we want to make sure it gets serialized
     // with "$message_type".
diff --git a/compiler/rustc_errors/src/lib.rs b/compiler/rustc_errors/src/lib.rs
index 08e4f61e629..0bd259366de 100644
--- a/compiler/rustc_errors/src/lib.rs
+++ b/compiler/rustc_errors/src/lib.rs
@@ -75,7 +75,9 @@ pub use snippet::Style;
 pub use termcolor::{Color, ColorSpec, WriteColor};
 use tracing::debug;
 
+use crate::emitter::TimingEvent;
 use crate::registry::Registry;
+use crate::timings::TimingRecord;
 
 pub mod annotate_snippet_emitter_writer;
 pub mod codes;
@@ -91,6 +93,7 @@ mod snippet;
 mod styled_buffer;
 #[cfg(test)]
 mod tests;
+pub mod timings;
 pub mod translation;
 
 pub type PResult<'a, T> = Result<T, Diag<'a>>;
@@ -1157,6 +1160,14 @@ impl<'a> DiagCtxtHandle<'a> {
         self.inner.borrow_mut().emitter.emit_artifact_notification(path, artifact_type);
     }
 
+    pub fn emit_timing_section_start(&self, record: TimingRecord) {
+        self.inner.borrow_mut().emitter.emit_timing_section(record, TimingEvent::Start);
+    }
+
+    pub fn emit_timing_section_end(&self, record: TimingRecord) {
+        self.inner.borrow_mut().emitter.emit_timing_section(record, TimingEvent::End);
+    }
+
     pub fn emit_future_breakage_report(&self) {
         let inner = &mut *self.inner.borrow_mut();
         let diags = std::mem::take(&mut inner.future_breakage_diagnostics);
diff --git a/compiler/rustc_errors/src/timings.rs b/compiler/rustc_errors/src/timings.rs
new file mode 100644
index 00000000000..27fc9df8d79
--- /dev/null
+++ b/compiler/rustc_errors/src/timings.rs
@@ -0,0 +1,80 @@
+use std::time::Instant;
+
+use crate::DiagCtxtHandle;
+
+/// A high-level section of the compilation process.
+#[derive(Copy, Clone, Debug)]
+pub enum TimingSection {
+    /// Time spent linking.
+    Linking,
+}
+
+/// Section with attached timestamp
+#[derive(Copy, Clone, Debug)]
+pub struct TimingRecord {
+    pub section: TimingSection,
+    /// Microseconds elapsed since some predetermined point in time (~start of the rustc process).
+    pub timestamp: u128,
+}
+
+impl TimingRecord {
+    fn from_origin(origin: Instant, section: TimingSection) -> Self {
+        Self { section, timestamp: Instant::now().duration_since(origin).as_micros() }
+    }
+
+    pub fn section(&self) -> TimingSection {
+        self.section
+    }
+
+    pub fn timestamp(&self) -> u128 {
+        self.timestamp
+    }
+}
+
+/// Manages emission of start/end section timings, enabled through `--json=timings`.
+pub struct TimingSectionHandler {
+    /// Time when the compilation session started.
+    /// If `None`, timing is disabled.
+    origin: Option<Instant>,
+}
+
+impl TimingSectionHandler {
+    pub fn new(enabled: bool) -> Self {
+        let origin = if enabled { Some(Instant::now()) } else { None };
+        Self { origin }
+    }
+
+    /// Returns a RAII guard that will immediately emit a start the provided section, and then emit
+    /// its end when it is dropped.
+    pub fn start_section<'a>(
+        &self,
+        diag_ctxt: DiagCtxtHandle<'a>,
+        section: TimingSection,
+    ) -> TimingSectionGuard<'a> {
+        TimingSectionGuard::create(diag_ctxt, section, self.origin)
+    }
+}
+
+/// RAII wrapper for starting and ending section timings.
+pub struct TimingSectionGuard<'a> {
+    dcx: DiagCtxtHandle<'a>,
+    section: TimingSection,
+    origin: Option<Instant>,
+}
+
+impl<'a> TimingSectionGuard<'a> {
+    fn create(dcx: DiagCtxtHandle<'a>, section: TimingSection, origin: Option<Instant>) -> Self {
+        if let Some(origin) = origin {
+            dcx.emit_timing_section_start(TimingRecord::from_origin(origin, section));
+        }
+        Self { dcx, section, origin }
+    }
+}
+
+impl<'a> Drop for TimingSectionGuard<'a> {
+    fn drop(&mut self) {
+        if let Some(origin) = self.origin {
+            self.dcx.emit_timing_section_end(TimingRecord::from_origin(origin, self.section));
+        }
+    }
+}
diff --git a/compiler/rustc_interface/src/queries.rs b/compiler/rustc_interface/src/queries.rs
index 9a474b910f6..877440ec7d2 100644
--- a/compiler/rustc_interface/src/queries.rs
+++ b/compiler/rustc_interface/src/queries.rs
@@ -4,6 +4,7 @@ use std::sync::Arc;
 use rustc_codegen_ssa::CodegenResults;
 use rustc_codegen_ssa::traits::CodegenBackend;
 use rustc_data_structures::svh::Svh;
+use rustc_errors::timings::TimingSection;
 use rustc_hir::def_id::LOCAL_CRATE;
 use rustc_metadata::EncodedMetadata;
 use rustc_middle::dep_graph::DepGraph;
@@ -88,6 +89,7 @@ impl Linker {
         }
 
         let _timer = sess.prof.verbose_generic_activity("link_crate");
+        let _timing = sess.timings.start_section(sess.dcx(), TimingSection::Linking);
         codegen_backend.link(sess, codegen_results, self.metadata, &self.output_filenames)
     }
 }
diff --git a/compiler/rustc_session/src/config.rs b/compiler/rustc_session/src/config.rs
index 04ca0b75c31..19db01585e3 100644
--- a/compiler/rustc_session/src/config.rs
+++ b/compiler/rustc_session/src/config.rs
@@ -1366,6 +1366,7 @@ impl Default for Options {
             real_rust_source_base_dir: None,
             edition: DEFAULT_EDITION,
             json_artifact_notifications: false,
+            json_timings: false,
             json_unused_externs: JsonUnusedExterns::No,
             json_future_incompat: false,
             pretty: None,
@@ -1880,6 +1881,9 @@ pub struct JsonConfig {
     pub json_rendered: HumanReadableErrorType,
     pub json_color: ColorConfig,
     json_artifact_notifications: bool,
+    /// Output start and end timestamps of several high-level compilation sections
+    /// (frontend, backend, linker).
+    json_timings: bool,
     pub json_unused_externs: JsonUnusedExterns,
     json_future_incompat: bool,
 }
@@ -1921,6 +1925,7 @@ pub fn parse_json(early_dcx: &EarlyDiagCtxt, matches: &getopts::Matches) -> Json
     let mut json_artifact_notifications = false;
     let mut json_unused_externs = JsonUnusedExterns::No;
     let mut json_future_incompat = false;
+    let mut json_timings = false;
     for option in matches.opt_strs("json") {
         // For now conservatively forbid `--color` with `--json` since `--json`
         // won't actually be emitting any colors and anything colorized is
@@ -1937,6 +1942,7 @@ pub fn parse_json(early_dcx: &EarlyDiagCtxt, matches: &getopts::Matches) -> Json
                 }
                 "diagnostic-rendered-ansi" => json_color = ColorConfig::Always,
                 "artifacts" => json_artifact_notifications = true,
+                "timings" => json_timings = true,
                 "unused-externs" => json_unused_externs = JsonUnusedExterns::Loud,
                 "unused-externs-silent" => json_unused_externs = JsonUnusedExterns::Silent,
                 "future-incompat" => json_future_incompat = true,
@@ -1949,6 +1955,7 @@ pub fn parse_json(early_dcx: &EarlyDiagCtxt, matches: &getopts::Matches) -> Json
         json_rendered,
         json_color,
         json_artifact_notifications,
+        json_timings,
         json_unused_externs,
         json_future_incompat,
     }
@@ -2476,6 +2483,7 @@ pub fn build_session_options(early_dcx: &mut EarlyDiagCtxt, matches: &getopts::M
         json_rendered,
         json_color,
         json_artifact_notifications,
+        json_timings,
         json_unused_externs,
         json_future_incompat,
     } = parse_json(early_dcx, matches);
@@ -2497,6 +2505,10 @@ pub fn build_session_options(early_dcx: &mut EarlyDiagCtxt, matches: &getopts::M
     let mut unstable_opts = UnstableOptions::build(early_dcx, matches, &mut target_modifiers);
     let (lint_opts, describe_lints, lint_cap) = get_cmd_lint_options(early_dcx, matches);
 
+    if !unstable_opts.unstable_options && json_timings {
+        early_dcx.early_fatal("--json=timings is unstable and requires using `-Zunstable-options`");
+    }
+
     check_error_format_stability(early_dcx, &unstable_opts, error_format);
 
     let output_types = parse_output_types(early_dcx, &unstable_opts, matches);
@@ -2774,6 +2786,7 @@ pub fn build_session_options(early_dcx: &mut EarlyDiagCtxt, matches: &getopts::M
         real_rust_source_base_dir,
         edition,
         json_artifact_notifications,
+        json_timings,
         json_unused_externs,
         json_future_incompat,
         pretty,
diff --git a/compiler/rustc_session/src/options.rs b/compiler/rustc_session/src/options.rs
index 0ac2702cac5..d22f9de6525 100644
--- a/compiler/rustc_session/src/options.rs
+++ b/compiler/rustc_session/src/options.rs
@@ -410,6 +410,10 @@ top_level_options!(
         /// by the compiler.
         json_artifact_notifications: bool [TRACKED],
 
+        /// `true` if we're emitting JSON timings with the start and end of
+        /// high-level compilation sections
+        json_timings: bool [UNTRACKED],
+
         /// `true` if we're emitting a JSON blob containing the unused externs
         json_unused_externs: JsonUnusedExterns [UNTRACKED],
 
diff --git a/compiler/rustc_session/src/session.rs b/compiler/rustc_session/src/session.rs
index b8b4518b14e..ca42c5a4256 100644
--- a/compiler/rustc_session/src/session.rs
+++ b/compiler/rustc_session/src/session.rs
@@ -18,6 +18,7 @@ use rustc_errors::emitter::{
     DynEmitter, HumanEmitter, HumanReadableErrorType, OutputTheme, stderr_destination,
 };
 use rustc_errors::json::JsonEmitter;
+use rustc_errors::timings::TimingSectionHandler;
 use rustc_errors::{
     Diag, DiagCtxt, DiagCtxtHandle, DiagMessage, Diagnostic, ErrorGuaranteed, FatalAbort,
     FluentBundle, LazyFallbackBundle, TerminalUrl, fallback_fluent_bundle,
@@ -156,6 +157,9 @@ pub struct Session {
     /// Used by `-Z self-profile`.
     pub prof: SelfProfilerRef,
 
+    /// Used to emit section timings events (enabled by `--json=timings`).
+    pub timings: TimingSectionHandler,
+
     /// Data about code being compiled, gathered during compilation.
     pub code_stats: CodeStats,
 
@@ -1126,6 +1130,8 @@ pub fn build_session(
         .as_ref()
         .map(|_| rng().next_u32().to_base_fixed_len(CASE_INSENSITIVE).to_string());
 
+    let timings = TimingSectionHandler::new(sopts.json_timings);
+
     let sess = Session {
         target,
         host,
@@ -1136,6 +1142,7 @@ pub fn build_session(
         io,
         incr_comp_session: RwLock::new(IncrCompSession::NotInitialized),
         prof,
+        timings,
         code_stats: Default::default(),
         lint_store: None,
         driver_lint_caps,