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: rust-lang/compiler-team#873

r? ``@nnethercote``

Author: Urgau

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) {}

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()
@@ -263,6 +280,16 @@ struct ArtifactNotification<'a> {
     emit: &'a str,
 }
 
+#[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

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

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

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

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,

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

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,

src/doc/rustc/src/command-line-arguments.md

@@ -471,6 +471,9 @@ to customize the output:
 - `future-incompat` - includes a JSON message that contains a report if the
   crate contains any code that may fail to compile in the future.
 
+- `timings` - output a JSON message when a certain compilation "section"
+  (such as frontend analysis, code generation, linking) begins or ends.
+
 Note that it is invalid to combine the `--json` argument with the
 [`--color`](#option-color) argument, and it is required to combine `--json`
 with `--error-format=json`.

src/doc/rustc/src/json.md

@@ -298,6 +298,35 @@ appropriately. (This is needed by Cargo which shares the same dependencies
 across multiple build targets, so it should only report an unused dependency if
 its not used by any of the targets.)
 
+## Timings
+
+**This setting is currently unstable and requires usage of `-Zunstable-options`.**
+
+The `--timings` option will tell `rustc` to emit messages when a certain compilation
+section (such as code generation or linking) begins or ends. The messages currently have
+the following format:
+
+```json
+{
+    "$message_type": "section_timing", /* Type of this message */
+    "event": "start", /* Marks the "start" or "end" of the compilation section */
+    "name": "link",  /* The name of the compilation section */
+    // Opaque timestamp when the message was emitted, in microseconds
+    // The timestamp is currently relative to the beginning of the compilation session
+    "time": 12345
+}
+```
+
+Note that the JSON format of the `timings` messages is unstable and subject to change.
+
+Compilation sections can be nested; for example, if you encounter the start of "foo",
+then the start of "bar", then the end of "bar" and then the end of "bar", it means that the
+"bar" section happened as a part of the "foo" section.
+
+The timestamp should only be used for computing the duration of each section.
+
+We currently do not guarantee any specific section names to be emitted.
+
 [option-emit]: command-line-arguments.md#option-emit
 [option-error-format]: command-line-arguments.md#option-error-format
 [option-json]: command-line-arguments.md#option-json