feat(build-analysis): emit timing-info log (#16179)

### What does this PR try to resolve?

Log timing information.
The schema is currently the same as the `--timings` JSON output.

Part of #15844

### How to test and review this PR?

```
CARGO_BUILD_ANALYSIS_ENABLED=true cargo -Zbuild-analysis check
```

Author: epage

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,

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

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<PackageId, Vec<String>> = HashMap::new();
         for unit in root_units {
@@ -314,7 +315,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;
         }
@@ -340,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);
     }
 

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<BuildContext<'a, 'gctx>> {
     let CompileOptions {
         ref build_config,
@@ -586,6 +587,7 @@ where `<compatible-ver>` is the latest version supporting rustc {rustc_version}"
 
     let bcx = BuildContext::new(
         ws,
+        logger,
         pkg_set,
         build_config,
         profiles,

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<f64>,
+        #[serde(skip_serializing_if = "Vec::is_empty")]
+        sections: Vec<(String, CompilationSection)>,
+    },
 }
 
 impl LogMessage {

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;

tests/testsuite/build_analysis.rs

@@ -116,6 +116,79 @@ fn log_msg_build_started() {
     "target_dir": "[ROOT]/foo/target",
     "timestamp": "[..]T[..]Z",
     "workspace_root": "[ROOT]/foo"
+  },
+  "{...}"
+]
+"#]]
+        .is_json()
+        .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();
+
+    assert_e2e().eq(
+        &content,
+        str![[r#"
+[
+  {
+    "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"
   }
 ]
 "#]]