diff --git a/src/cargo/core/compiler/job_queue/job_state.rs b/src/cargo/core/compiler/job_queue/job_state.rs index 2ab19b61e09..fe28d597f3c 100644 --- a/src/cargo/core/compiler/job_queue/job_state.rs +++ b/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) { diff --git a/src/cargo/core/compiler/job_queue/mod.rs b/src/cargo/core/compiler/job_queue/mod.rs index 518f3739671..152e7e75a07 100644 --- a/src/cargo/core/compiler/job_queue/mod.rs +++ b/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), Finish(JobId, Artifact, CargoResult<()>), FutureIncompatReport(JobId, Vec), + 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, §ion); + } } Ok(()) diff --git a/src/cargo/core/compiler/mod.rs b/src/cargo/core/compiler/mod.rs index fa8239edfba..bcdfac9edbb 100644 --- a/src/cargo/core/compiler/mod.rs +++ b/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}; @@ -104,6 +105,7 @@ use cargo_util_schemas::manifest::TomlDebugInfo; use cargo_util_schemas::manifest::TomlTrimPaths; use cargo_util_schemas::manifest::TomlTrimPathsValue; use rustfix::diagnostics::Applicability; +pub(crate) use timings::CompilationSection; const RUSTDOC_CRATE_VERSION_FLAG: &str = "--crate-version"; @@ -1095,6 +1097,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.cli_unstable().section_timings + && !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 +1112,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 +1970,12 @@ fn on_stderr_line_inner( return Ok(true); } + let res = serde_json::from_str::(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 { diff --git a/src/cargo/core/compiler/timings.rs b/src/cargo/core/compiler/timings.rs index 4ad23f8fa7f..e198b05ac40 100644 --- a/src/cargo/core/compiler/timings.rs +++ b/src/cargo/core/compiler/timings.rs @@ -12,10 +12,13 @@ use crate::util::style; use crate::util::{CargoResult, GlobalContext}; use anyhow::Context as _; use cargo_util::paths; +use indexmap::IndexMap; +use itertools::Itertools; 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 +66,15 @@ pub struct Timings<'gctx> { cpu_usage: Vec<(f64, f64)>, } +/// Section of compilation (e.g. frontend, backend, linking). +#[derive(Copy, Clone, serde::Serialize)] +pub struct CompilationSection { + /// 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, +} + /// Tracking information for an individual unit. struct UnitTime { unit: Unit, @@ -79,6 +91,74 @@ struct UnitTime { unlocked_units: Vec, /// Same as `unlocked_units`, but unlocked by rmeta. unlocked_rmeta_units: Vec, + /// Individual compilation section durations, gathered from `--json=timings`. + /// + /// IndexMap is used to keep original insertion order, we want to be able to tell which + /// sections were started in which order. + sections: IndexMap, +} + +const FRONTEND_SECTION_NAME: &str = "Frontend"; +const CODEGEN_SECTION_NAME: &str = "Codegen"; + +impl UnitTime { + fn aggregate_sections(&self) -> AggregatedSections { + let end = self.duration; + + if !self.sections.is_empty() { + // We have some detailed compilation section timings, so we postprocess them + // Since it is possible that we do not have an end timestamp for a given compilation + // section, we need to iterate them and if an end is missing, we assign the end of + // the section to the start of the following section. + + let mut sections = vec![]; + + // The frontend section is currently implicit in rustc, it is assumed to start at + // compilation start and end when codegen starts. So we hard-code it here. + let mut previous_section = ( + FRONTEND_SECTION_NAME.to_string(), + CompilationSection { + start: 0.0, + end: None, + }, + ); + for (name, section) in self.sections.clone() { + // Store the previous section, potentially setting its end to the start of the + // current section. + sections.push(( + previous_section.0.clone(), + SectionData { + start: previous_section.1.start, + end: previous_section.1.end.unwrap_or(section.start), + }, + )); + previous_section = (name, section); + } + // Store the last section, potentially setting its end to the end of the whole + // compilation. + sections.push(( + previous_section.0.clone(), + SectionData { + start: previous_section.1.start, + end: previous_section.1.end.unwrap_or(end), + }, + )); + + AggregatedSections::Sections(sections) + } else if let Some(rmeta) = self.rmeta_time { + // We only know when the rmeta time was generated + AggregatedSections::OnlyMetadataTime { + frontend: SectionData { + start: 0.0, + end: rmeta, + }, + codegen: SectionData { start: rmeta, end }, + } + } else { + // We only know the total duration + AggregatedSections::OnlyTotalDuration + } + } } /// Periodic concurrency tracking information. @@ -95,6 +175,35 @@ struct Concurrency { inactive: usize, } +/// Postprocessed section data that has both start and an end. +#[derive(Copy, Clone, serde::Serialize)] +struct SectionData { + /// Start (relative to the start of the unit) + start: f64, + /// End (relative to the start of the unit) + end: f64, +} + +impl SectionData { + fn duration(&self) -> f64 { + (self.end - self.start).max(0.0) + } +} + +/// Contains post-processed data of individual compilation sections. +#[derive(serde::Serialize)] +enum AggregatedSections { + /// We know the names and durations of individual compilation sections + Sections(Vec<(String, SectionData)>), + /// We only know when .rmeta was generated, so we can distill frontend and codegen time. + OnlyMetadataTime { + frontend: SectionData, + codegen: SectionData, + }, + /// We know only the total duration + OnlyTotalDuration, +} + impl<'gctx> Timings<'gctx> { pub fn new(bcx: &BuildContext<'_, 'gctx>, root_units: &[Unit]) -> Timings<'gctx> { let has_report = |what| bcx.build_config.timing_outputs.contains(&what); @@ -181,6 +290,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()); } @@ -226,6 +336,7 @@ impl<'gctx> Timings<'gctx> { mode: unit_time.unit.mode, duration: unit_time.duration, rmeta_time: unit_time.rmeta_time, + sections: unit_time.sections.clone().into_iter().collect(), } .to_json_string(); crate::drop_println!(self.gctx, "{}", msg); @@ -233,6 +344,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(§ion_timing.name, now); + } + SectionTimingEvent::End => { + unit_time.end_section(§ion_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 { @@ -517,6 +648,58 @@ impl<'gctx> Timings<'gctx> { /// Render the table of all units. fn write_unit_table(&self, f: &mut impl Write) -> CargoResult<()> { + let mut units: Vec<&UnitTime> = self.unit_times.iter().collect(); + units.sort_unstable_by(|a, b| b.duration.partial_cmp(&a.duration).unwrap()); + + // Make the first "letter" uppercase. We could probably just assume ASCII here, but this + // should be Unicode compatible. + fn capitalize(s: &str) -> String { + let first_char = s + .chars() + .next() + .map(|c| c.to_uppercase().to_string()) + .unwrap_or_default(); + format!("{first_char}{}", s.chars().skip(1).collect::()) + } + + // We can have a bunch of situations here. + // - -Zsection-timings is enabled, and we received some custom sections, in which + // case we use them to determine the headers. + // - We have at least one rmeta time, so we hard-code Frontend and Codegen headers. + // - We only have total durations, so we don't add any additional headers. + let aggregated: Vec = units + .iter() + .map(|u| + // Normalize the section names so that they are capitalized, so that we can later + // refer to them with the capitalized name both when computing headers and when + // looking up cells. + match u.aggregate_sections() { + AggregatedSections::Sections(sections) => AggregatedSections::Sections( + sections.into_iter() + .map(|(name, data)| (capitalize(&name), data)) + .collect() + ), + s => s + }) + .collect(); + + let headers: Vec = if let Some(sections) = aggregated.iter().find_map(|s| match s { + AggregatedSections::Sections(sections) => Some(sections), + _ => None, + }) { + sections.into_iter().map(|s| s.0.clone()).collect() + } else if aggregated + .iter() + .any(|s| matches!(s, AggregatedSections::OnlyMetadataTime { .. })) + { + vec![ + FRONTEND_SECTION_NAME.to_string(), + CODEGEN_SECTION_NAME.to_string(), + ] + } else { + vec![] + }; + write!( f, r#" @@ -526,20 +709,53 @@ impl<'gctx> Timings<'gctx> { Unit Total - Codegen + {headers} Features -"# +"#, + headers = headers.iter().map(|h| format!("{h}")).join("\n") )?; - let mut units: Vec<&UnitTime> = self.unit_times.iter().collect(); - units.sort_unstable_by(|a, b| b.duration.partial_cmp(&a.duration).unwrap()); - for (i, unit) in units.iter().enumerate() { - let codegen = match unit.codegen_time() { + + for (i, (unit, aggregated_sections)) in units.iter().zip(aggregated).enumerate() { + let format_duration = |section: Option| match section { + Some(section) => { + let duration = section.duration(); + let pct = (duration / unit.duration) * 100.0; + format!("{duration:.1}s ({:.0}%)", pct) + } None => "".to_string(), - Some((_rt, ctime, cent)) => format!("{:.1}s ({:.0}%)", ctime, cent), }; + + // This is a bit complex, as we assume the most general option - we can have an + // arbitrary set of headers, and an arbitrary set of sections per unit, so we always + // initiate the cells to be empty, and then try to find a corresponding column for which + // we might have data. + let mut cells: HashMap<&str, SectionData> = Default::default(); + + match &aggregated_sections { + AggregatedSections::Sections(sections) => { + for (name, data) in sections { + cells.insert(&name, *data); + } + } + AggregatedSections::OnlyMetadataTime { frontend, codegen } => { + cells.insert(FRONTEND_SECTION_NAME, *frontend); + cells.insert(CODEGEN_SECTION_NAME, *codegen); + } + AggregatedSections::OnlyTotalDuration => {} + }; + let cells = headers + .iter() + .map(|header| { + format!( + "{}", + format_duration(cells.remove(header.as_str())) + ) + }) + .join("\n"); + let features = unit.unit.features.join(", "); write!( f, @@ -548,16 +764,14 @@ impl<'gctx> Timings<'gctx> { {}. {}{} {:.1}s - {} - {} + {cells} + {features} "#, i + 1, unit.name_ver(), unit.target, unit.duration, - codegen, - features, )?; } write!(f, "\n\n")?; @@ -566,18 +780,49 @@ impl<'gctx> Timings<'gctx> { } impl UnitTime { - /// Returns the codegen time as (`rmeta_time`, `codegen_time`, percent of total) - fn codegen_time(&self) -> Option<(f64, f64, f64)> { - self.rmeta_time.map(|rmeta_time| { - let ctime = self.duration - rmeta_time; - let cent = (ctime / self.duration) * 100.0; - (rmeta_time, ctime, cent) - }) - } - 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(), + CompilationSection { + 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 { diff --git a/src/cargo/core/features.rs b/src/cargo/core/features.rs index 5c13b1a6e41..60e2ebbdb4c 100644 --- a/src/cargo/core/features.rs +++ b/src/cargo/core/features.rs @@ -856,6 +856,7 @@ unstable_cli_options!( rustdoc_scrape_examples: bool = ("Allows Rustdoc to scrape code examples from reverse-dependencies"), sbom: bool = ("Enable the `sbom` option in build config in .cargo/config.toml file"), script: bool = ("Enable support for single-file, `.rs` packages"), + section_timings: bool = ("Enable support for extended compilation sections in --timings output"), separate_nightlies: bool, skip_rustdoc_fingerprint: bool, target_applies_to_host: bool = ("Enable the `target-applies-to-host` key in the .cargo/config.toml file"), @@ -1380,6 +1381,7 @@ impl CliUnstable { "rustdoc-map" => self.rustdoc_map = parse_empty(k, v)?, "rustdoc-scrape-examples" => self.rustdoc_scrape_examples = parse_empty(k, v)?, "sbom" => self.sbom = parse_empty(k, v)?, + "section-timings" => self.section_timings = parse_empty(k, v)?, "separate-nightlies" => self.separate_nightlies = parse_empty(k, v)?, "checksum-freshness" => self.checksum_freshness = parse_empty(k, v)?, "skip-rustdoc-fingerprint" => self.skip_rustdoc_fingerprint = parse_empty(k, v)?, diff --git a/src/cargo/util/machine_message.rs b/src/cargo/util/machine_message.rs index 7ee74f73755..64e64ee3bcc 100644 --- a/src/cargo/util/machine_message.rs +++ b/src/cargo/util/machine_message.rs @@ -6,7 +6,7 @@ use serde::ser; use serde_json::{json, value::RawValue}; use crate::core::Target; -use crate::core::compiler::CompileMode; +use crate::core::compiler::{CompilationSection, CompileMode}; pub trait Message: ser::Serialize { fn reason(&self) -> &str; @@ -95,6 +95,8 @@ pub struct TimingInfo<'a> { pub duration: f64, #[serde(skip_serializing_if = "Option::is_none")] pub rmeta_time: Option, + #[serde(skip_serializing_if = "Vec::is_empty")] + pub sections: Vec<(String, CompilationSection)>, } impl<'a> Message for TimingInfo<'a> { diff --git a/src/doc/src/reference/unstable.md b/src/doc/src/reference/unstable.md index e267f63f833..ffae6b5d85e 100644 --- a/src/doc/src/reference/unstable.md +++ b/src/doc/src/reference/unstable.md @@ -1938,6 +1938,18 @@ For example: cargo +nightly fix -Zfix-edition=end=2024,future ``` +## section-timings +* Original Pull Request: [#15780](https://github.com/rust-lang/cargo/pull/15780) +* Tracking Issue: [#15817](https://github.com/rust-lang/cargo/issues/15817) + +This feature can be used to extend the output of `cargo build --timings`. It will tell rustc +to produce timings of individual compilation sections, which will be then displayed in the timings +HTML/JSON output. + +```console +cargo +nightly -Zsection-timings build --timings +``` + # Stabilized and removed features ## Compile progress diff --git a/tests/testsuite/cargo/z_help/stdout.term.svg b/tests/testsuite/cargo/z_help/stdout.term.svg index 8f424558d19..23edf8d5096 100644 --- a/tests/testsuite/cargo/z_help/stdout.term.svg +++ b/tests/testsuite/cargo/z_help/stdout.term.svg @@ -1,4 +1,4 @@ - +