Pass --json=timings to rustc and handle section timings events

Author: Kobzol

src/cargo/core/compiler/job_queue/job_state.rs

@@ -7,6 +7,7 @@ use cargo_util::ProcessBuilder;
 use crate::CargoResult;
 use crate::core::compiler::build_runner::OutputFile;
 use crate::core::compiler::future_incompat::FutureBreakageItem;
+use crate::core::compiler::timings::SectionTiming;
 use crate::util::Queue;
 
 use super::{Artifact, DiagDedupe, Job, JobId, Message};
@@ -143,6 +144,10 @@ impl<'a, 'gctx> JobState<'a, 'gctx> {
             .push(Message::Finish(self.id, Artifact::Metadata, Ok(())));
     }
 
+    pub fn on_section_timing_emitted(&self, section: SectionTiming) {
+        self.messages.push(Message::SectionTiming(self.id, section));
+    }
+
     /// Drives a [`Job`] to finish. This ensures that a [`Message::Finish`] is
     /// sent even if our job panics.
     pub(super) fn run_to_finish(self, job: Job) {

src/cargo/core/compiler/job_queue/mod.rs

@@ -133,7 +133,7 @@ pub use self::job::{Job, Work};
 pub use self::job_state::JobState;
 use super::build_runner::OutputFile;
 use super::custom_build::Severity;
-use super::timings::Timings;
+use super::timings::{SectionTiming, Timings};
 use super::{BuildContext, BuildPlan, BuildRunner, CompileMode, Unit};
 use crate::core::compiler::descriptive_pkg_name;
 use crate::core::compiler::future_incompat::{
@@ -374,6 +374,7 @@ enum Message {
     Token(io::Result<Acquired>),
     Finish(JobId, Artifact, CargoResult<()>),
     FutureIncompatReport(JobId, Vec<FutureBreakageItem>),
+    SectionTiming(JobId, SectionTiming),
 }
 
 impl<'gctx> JobQueue<'gctx> {
@@ -714,6 +715,9 @@ impl<'gctx> DrainState<'gctx> {
                 let token = acquired_token.context("failed to acquire jobserver token")?;
                 self.tokens.push(token);
             }
+            Message::SectionTiming(id, section) => {
+                self.timings.unit_section_timing(id, &section);
+            }
         }
 
         Ok(())

src/cargo/core/compiler/mod.rs

@@ -90,6 +90,7 @@ use self::output_depinfo::output_depinfo;
 use self::output_sbom::build_sbom;
 use self::unit_graph::UnitDep;
 use crate::core::compiler::future_incompat::FutureIncompatReport;
+use crate::core::compiler::timings::SectionTiming;
 pub use crate::core::compiler::unit::{Unit, UnitInterner};
 use crate::core::manifest::TargetSourcePath;
 use crate::core::profiles::{PanicStrategy, Profile, StripInner};
@@ -1095,6 +1096,12 @@ fn add_allow_features(build_runner: &BuildRunner<'_, '_>, cmd: &mut ProcessBuild
 ///
 /// [`--error-format`]: https://doc.rust-lang.org/nightly/rustc/command-line-arguments.html#--error-format-control-how-errors-are-produced
 fn add_error_format_and_color(build_runner: &BuildRunner<'_, '_>, cmd: &mut ProcessBuilder) {
+    let enable_timings = build_runner.bcx.gctx.nightly_features_allowed
+        && !build_runner.bcx.build_config.timing_outputs.is_empty();
+    if enable_timings {
+        cmd.arg("-Zunstable-options");
+    }
+
     cmd.arg("--error-format=json");
     let mut json = String::from("--json=diagnostic-rendered-ansi,artifacts,future-incompat");
 
@@ -1104,6 +1111,11 @@ fn add_error_format_and_color(build_runner: &BuildRunner<'_, '_>, cmd: &mut Proc
         }
         _ => {}
     }
+
+    if enable_timings {
+        json.push_str(",timings");
+    }
+
     cmd.arg(json);
 
     let gctx = build_runner.bcx.gctx;
@@ -1957,6 +1969,12 @@ fn on_stderr_line_inner(
         return Ok(true);
     }
 
+    let res = serde_json::from_str::<SectionTiming>(compiler_message.get());
+    if let Ok(timing_record) = res {
+        state.on_section_timing_emitted(timing_record);
+        return Ok(false);
+    }
+
     // Depending on what we're emitting from Cargo itself, we figure out what to
     // do with this JSON message.
     match options.format {

src/cargo/core/compiler/timings.rs

@@ -16,6 +16,7 @@ use std::collections::HashMap;
 use std::io::{BufWriter, Write};
 use std::thread::available_parallelism;
 use std::time::{Duration, Instant};
+use tracing::warn;
 
 /// Tracking information for the entire build.
 ///
@@ -63,6 +64,14 @@ pub struct Timings<'gctx> {
     cpu_usage: Vec<(f64, f64)>,
 }
 
+/// Section of compilation.
+struct TimingSection {
+    /// Start of the section, as an offset in seconds from `UnitTime::start`.
+    start: f64,
+    /// End of the section, as an offset in seconds from `UnitTime::start`.
+    end: Option<f64>,
+}
+
 /// Tracking information for an individual unit.
 struct UnitTime {
     unit: Unit,
@@ -79,6 +88,8 @@ struct UnitTime {
     unlocked_units: Vec<Unit>,
     /// Same as `unlocked_units`, but unlocked by rmeta.
     unlocked_rmeta_units: Vec<Unit>,
+    /// Individual compilation section durations, gathered from `--json=timings`.
+    sections: HashMap<String, TimingSection>,
 }
 
 /// Periodic concurrency tracking information.
@@ -181,6 +192,7 @@ impl<'gctx> Timings<'gctx> {
             rmeta_time: None,
             unlocked_units: Vec::new(),
             unlocked_rmeta_units: Vec::new(),
+            sections: Default::default(),
         };
         assert!(self.active.insert(id, unit_time).is_none());
     }
@@ -233,6 +245,26 @@ impl<'gctx> Timings<'gctx> {
         self.unit_times.push(unit_time);
     }
 
+    /// Handle the start/end of a compilation section.
+    pub fn unit_section_timing(&mut self, id: JobId, section_timing: &SectionTiming) {
+        if !self.enabled {
+            return;
+        }
+        let Some(unit_time) = self.active.get_mut(&id) else {
+            return;
+        };
+        let now = self.start.elapsed().as_secs_f64();
+
+        match section_timing.event {
+            SectionTimingEvent::Start => {
+                unit_time.start_section(&section_timing.name, now);
+            }
+            SectionTimingEvent::End => {
+                unit_time.end_section(&section_timing.name, now);
+            }
+        }
+    }
+
     /// This is called periodically to mark the concurrency of internal structures.
     pub fn mark_concurrency(&mut self, active: usize, waiting: usize, inactive: usize) {
         if !self.enabled {
@@ -578,6 +610,46 @@ impl UnitTime {
     fn name_ver(&self) -> String {
         format!("{} v{}", self.unit.pkg.name(), self.unit.pkg.version())
     }
+
+    fn start_section(&mut self, name: &str, now: f64) {
+        if self
+            .sections
+            .insert(
+                name.to_string(),
+                TimingSection {
+                    start: now - self.start,
+                    end: None,
+                },
+            )
+            .is_some()
+        {
+            warn!("Compilation section {name} started more than once");
+        }
+    }
+
+    fn end_section(&mut self, name: &str, now: f64) {
+        let Some(section) = self.sections.get_mut(name) else {
+            warn!("Compilation section {name} ended, but it has no start recorded");
+            return;
+        };
+        section.end = Some(now - self.start);
+    }
+}
+
+/// Start or end of a section timing.
+#[derive(serde::Deserialize, Debug)]
+#[serde(rename_all = "kebab-case")]
+pub enum SectionTimingEvent {
+    Start,
+    End,
+}
+
+/// Represents a certain section (phase) of rustc compilation.
+/// It is emitted by rustc when the `--json=timings` flag is used.
+#[derive(serde::Deserialize, Debug)]
+pub struct SectionTiming {
+    pub name: String,
+    pub event: SectionTimingEvent,
 }
 
 fn render_rustc_info(bcx: &BuildContext<'_, '_>) -> String {