From 478f117919a53f25399ba37ef37fda8e16f3f350 Mon Sep 17 00:00:00 2001 From: Weihang Lo Date: Thu, 30 Oct 2025 12:28:23 -0400 Subject: [PATCH 1/3] test(build-analysis): show logs contain no timing-info --- tests/testsuite/build_analysis.rs | 53 +++++++++++++++++++++++++++++++ 1 file changed, 53 insertions(+) diff --git a/tests/testsuite/build_analysis.rs b/tests/testsuite/build_analysis.rs index 15252088a84..19c94dd8944 100644 --- a/tests/testsuite/build_analysis.rs +++ b/tests/testsuite/build_analysis.rs @@ -123,3 +123,56 @@ fn log_msg_build_started() { .against_jsonlines(), ); } + +#[cargo_test] +fn log_msg_timing_info() { + let p = project() + .file( + "Cargo.toml", + r#" + [package] + name = "foo" + version = "0.0.0" + edition = "2015" + + [dependencies] + bar = { path = "bar" } + "#, + ) + .file("src/lib.rs", "") + .file("bar/Cargo.toml", &basic_manifest("bar", "0.0.0")) + .file("bar/src/lib.rs", "") + .build(); + + p.cargo("check -Zbuild-analysis") + .env("CARGO_BUILD_ANALYSIS_ENABLED", "true") + .masquerade_as_nightly_cargo(&["build-analysis"]) + .run(); + + let cargo_home = paths::cargo_home(); + let log_dir = cargo_home.join("log"); + assert!(log_dir.exists()); + + let entries = std::fs::read_dir(&log_dir).unwrap(); + let log_file = entries + .filter_map(Result::ok) + .find(|e| e.path().extension().and_then(|s| s.to_str()) == Some("jsonl")) + .unwrap(); + + let content = std::fs::read_to_string(log_file.path()).unwrap(); + + // Current behavior: only build-started, no timing-info logs exist yet + assert_e2e().eq( + &content, + str![[r#" +[ + { + "reason": "build-started", + "...": "{...}" + } +] +"#]] + .is_json() + .against_jsonlines(), + ); +} From 0cb115f6b3ec9c1a6fb41058ddf642b20536b3d0 Mon Sep 17 00:00:00 2001 From: Weihang Lo Date: Thu, 30 Oct 2025 17:09:12 -0400 Subject: [PATCH 2/3] feat(build-analysis): wire logger into build process --- src/cargo/core/compiler/build_context/mod.rs | 6 ++++++ src/cargo/core/compiler/job_queue/mod.rs | 2 +- src/cargo/core/compiler/timings.rs | 7 ++++++- src/cargo/ops/cargo_compile/mod.rs | 4 +++- src/cargo/util/mod.rs | 2 +- 5 files changed, 17 insertions(+), 4 deletions(-) diff --git a/src/cargo/core/compiler/build_context/mod.rs b/src/cargo/core/compiler/build_context/mod.rs index a0df44430ad..90ba0907e4c 100644 --- a/src/cargo/core/compiler/build_context/mod.rs +++ b/src/cargo/core/compiler/build_context/mod.rs @@ -9,6 +9,7 @@ use crate::util::Rustc; use crate::util::context::GlobalContext; use crate::util::errors::CargoResult; use crate::util::interning::InternedString; +use crate::util::logger::BuildLogger; use std::collections::{HashMap, HashSet}; mod target_info; @@ -50,6 +51,9 @@ pub struct BuildContext<'a, 'gctx> { /// The cargo context. pub gctx: &'gctx GlobalContext, + /// Build logger for `-Zbuild-analysis`. + pub logger: Option<&'a BuildLogger>, + /// This contains a collection of compiler flags presets. pub profiles: Profiles, @@ -83,6 +87,7 @@ pub struct BuildContext<'a, 'gctx> { impl<'a, 'gctx> BuildContext<'a, 'gctx> { pub fn new( ws: &'a Workspace<'gctx>, + logger: Option<&'a BuildLogger>, packages: PackageSet<'gctx>, build_config: &'a BuildConfig, profiles: Profiles, @@ -102,6 +107,7 @@ impl<'a, 'gctx> BuildContext<'a, 'gctx> { Ok(BuildContext { ws, gctx: ws.gctx(), + logger, packages, build_config, profiles, diff --git a/src/cargo/core/compiler/job_queue/mod.rs b/src/cargo/core/compiler/job_queue/mod.rs index c3097c78cdc..77d413ec2fe 100644 --- a/src/cargo/core/compiler/job_queue/mod.rs +++ b/src/cargo/core/compiler/job_queue/mod.rs @@ -1124,7 +1124,7 @@ impl<'gctx> DrainState<'gctx> { } let unlocked = self.queue.finish(unit, &artifact); match artifact { - Artifact::All => self.timings.unit_finished(id, unlocked), + Artifact::All => self.timings.unit_finished(build_runner, id, unlocked), Artifact::Metadata => self.timings.unit_rmeta_finished(id, unlocked), } Ok(()) diff --git a/src/cargo/core/compiler/timings.rs b/src/cargo/core/compiler/timings.rs index 999c1305815..79197c87fa1 100644 --- a/src/cargo/core/compiler/timings.rs +++ b/src/cargo/core/compiler/timings.rs @@ -314,7 +314,12 @@ impl<'gctx> Timings<'gctx> { } /// Mark that a unit has finished running. - pub fn unit_finished(&mut self, id: JobId, unlocked: Vec<&Unit>) { + pub fn unit_finished( + &mut self, + _build_runner: &BuildRunner<'_, '_>, + id: JobId, + unlocked: Vec<&Unit>, + ) { if !self.enabled { return; } diff --git a/src/cargo/ops/cargo_compile/mod.rs b/src/cargo/ops/cargo_compile/mod.rs index d53396186e5..e4e4b830b3e 100644 --- a/src/cargo/ops/cargo_compile/mod.rs +++ b/src/cargo/ops/cargo_compile/mod.rs @@ -173,7 +173,7 @@ pub fn compile_ws<'a>( }); } - let bcx = create_bcx(ws, options, &interner)?; + let bcx = create_bcx(ws, options, &interner, logger.as_ref())?; if options.build_config.unit_graph { unit_graph::emit_serialized_unit_graph(&bcx.roots, &bcx.unit_graph, ws.gctx())?; @@ -232,6 +232,7 @@ pub fn create_bcx<'a, 'gctx>( ws: &'a Workspace<'gctx>, options: &'a CompileOptions, interner: &'a UnitInterner, + logger: Option<&'a BuildLogger>, ) -> CargoResult> { let CompileOptions { ref build_config, @@ -586,6 +587,7 @@ where `` is the latest version supporting rustc {rustc_version}" let bcx = BuildContext::new( ws, + logger, pkg_set, build_config, profiles, diff --git a/src/cargo/util/mod.rs b/src/cargo/util/mod.rs index d8416d3e3db..6c4cffe03fb 100644 --- a/src/cargo/util/mod.rs +++ b/src/cargo/util/mod.rs @@ -57,7 +57,7 @@ pub mod job; pub mod lints; mod lockserver; pub mod log_message; -mod logger; +pub mod logger; pub mod machine_message; pub mod network; mod once; From 5b83f800de5907d2e18078b0d7d2a0ba8d3694ea Mon Sep 17 00:00:00 2001 From: Weihang Lo Date: Thu, 30 Oct 2025 18:02:34 -0400 Subject: [PATCH 3/3] feat(build-analysis): emit timing-info log Log timing information. The schema is currently the same as the `--timings` JSON output. --- src/cargo/core/compiler/timings.rs | 15 +++++++++++++-- src/cargo/util/log_message.rs | 16 ++++++++++++++++ tests/testsuite/build_analysis.rs | 24 ++++++++++++++++++++++-- 3 files changed, 51 insertions(+), 4 deletions(-) diff --git a/src/cargo/core/compiler/timings.rs b/src/cargo/core/compiler/timings.rs index 79197c87fa1..4eb7f3831a7 100644 --- a/src/cargo/core/compiler/timings.rs +++ b/src/cargo/core/compiler/timings.rs @@ -7,6 +7,7 @@ use crate::core::PackageId; use crate::core::compiler::job_queue::JobId; use crate::core::compiler::{BuildContext, BuildRunner, TimingOutput}; use crate::util::cpu::State; +use crate::util::log_message::LogMessage; use crate::util::machine_message::{self, Message}; use crate::util::style; use crate::util::{CargoResult, GlobalContext}; @@ -208,7 +209,7 @@ impl<'gctx> Timings<'gctx> { let has_report = |what| bcx.build_config.timing_outputs.contains(&what); let report_html = has_report(TimingOutput::Html); let report_json = has_report(TimingOutput::Json); - let enabled = report_html | report_json; + let enabled = report_html | report_json | bcx.logger.is_some(); let mut root_map: HashMap> = HashMap::new(); for unit in root_units { @@ -316,7 +317,7 @@ impl<'gctx> Timings<'gctx> { /// Mark that a unit has finished running. pub fn unit_finished( &mut self, - _build_runner: &BuildRunner<'_, '_>, + build_runner: &BuildRunner<'_, '_>, id: JobId, unlocked: Vec<&Unit>, ) { @@ -345,6 +346,16 @@ impl<'gctx> Timings<'gctx> { .to_json_string(); crate::drop_println!(self.gctx, "{}", msg); } + if let Some(logger) = build_runner.bcx.logger { + logger.log(LogMessage::TimingInfo { + package_id: unit_time.unit.pkg.package_id().to_spec(), + target: unit_time.unit.target.clone(), + mode: unit_time.unit.mode, + duration: unit_time.duration, + rmeta_time: unit_time.rmeta_time, + sections: unit_time.sections.clone().into_iter().collect(), + }); + } self.unit_times.push(unit_time); } diff --git a/src/cargo/util/log_message.rs b/src/cargo/util/log_message.rs index 510670f244c..30c7fc99e98 100644 --- a/src/cargo/util/log_message.rs +++ b/src/cargo/util/log_message.rs @@ -3,9 +3,14 @@ use std::io::Write; use std::path::PathBuf; +use cargo_util_schemas::core::PackageIdSpec; use jiff::Timestamp; use serde::Serialize; +use crate::core::Target; +use crate::core::compiler::CompilationSection; +use crate::core::compiler::CompileMode; + /// A log message. /// /// Each variant represents a different type of event. @@ -23,6 +28,17 @@ pub enum LogMessage { target_dir: PathBuf, workspace_root: PathBuf, }, + /// Emitted when a compilation unit finishes. + TimingInfo { + package_id: PackageIdSpec, + target: Target, + mode: CompileMode, + duration: f64, + #[serde(skip_serializing_if = "Option::is_none")] + rmeta_time: Option, + #[serde(skip_serializing_if = "Vec::is_empty")] + sections: Vec<(String, CompilationSection)>, + }, } impl LogMessage { diff --git a/tests/testsuite/build_analysis.rs b/tests/testsuite/build_analysis.rs index 19c94dd8944..0b448f547cf 100644 --- a/tests/testsuite/build_analysis.rs +++ b/tests/testsuite/build_analysis.rs @@ -116,7 +116,8 @@ fn log_msg_build_started() { "target_dir": "[ROOT]/foo/target", "timestamp": "[..]T[..]Z", "workspace_root": "[ROOT]/foo" - } + }, + "{...}" ] "#]] .is_json() @@ -161,7 +162,6 @@ fn log_msg_timing_info() { let content = std::fs::read_to_string(log_file.path()).unwrap(); - // Current behavior: only build-started, no timing-info logs exist yet assert_e2e().eq( &content, str![[r#" @@ -169,6 +169,26 @@ fn log_msg_timing_info() { { "reason": "build-started", "...": "{...}" + }, + { + "duration": "{...}", + "mode": "check", + "package_id": "path+[ROOTURL]/foo/bar#0.0.0", + "reason": "timing-info", + "rmeta_time": "{...}", + "run_id": "[..]T[..]Z-[..]", + "target": "{...}", + "timestamp": "[..]T[..]Z" + }, + { + "duration": "{...}", + "mode": "check", + "package_id": "path+[ROOTURL]/foo#0.0.0", + "reason": "timing-info", + "rmeta_time": "{...}", + "run_id": "[..]T[..]Z-[..]", + "target": "{...}", + "timestamp": "[..]T[..]Z" } ] "#]]