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

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

Author: weihanglo

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

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 {

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,14 +162,33 @@ 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#"
 [
   {
     "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"
   }
 ]
 "#]]