feat(log): add unit-started event

Author: weihanglo

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

@@ -606,7 +606,8 @@ impl<'gctx> DrainState<'gctx> {
                     .gctx
                     .shell()
                     .verbose(|c| c.status("Running", &cmd))?;
-                self.timings.unit_start(id, self.active[&id].clone());
+                self.timings
+                    .unit_start(build_runner, id, self.active[&id].clone());
             }
             Message::Stdout(out) => {
                 writeln!(build_runner.bcx.gctx.shell().out(), "{}", out)?;

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

@@ -189,7 +189,7 @@ impl<'gctx> Timings<'gctx> {
     }
 
     /// Mark that a unit has started running.
-    pub fn unit_start(&mut self, id: JobId, unit: Unit) {
+    pub fn unit_start(&mut self, build_runner: &BuildRunner<'_, '_>, id: JobId, unit: Unit) {
         if !self.enabled {
             return;
         }
@@ -210,16 +210,25 @@ impl<'gctx> Timings<'gctx> {
             CompileMode::Docscrape => target.push_str(" (doc scrape)"),
             CompileMode::RunCustomBuild => target.push_str(" (run)"),
         }
+        let start = self.start.elapsed().as_secs_f64();
         let unit_time = UnitTime {
             unit,
             target,
-            start: self.start.elapsed().as_secs_f64(),
+            start,
             duration: 0.0,
             rmeta_time: None,
             unblocked_units: Vec::new(),
             unblocked_rmeta_units: Vec::new(),
             sections: Default::default(),
         };
+        if let Some(logger) = build_runner.bcx.logger {
+            logger.log(LogMessage::UnitStarted {
+                package_id: unit_time.unit.pkg.package_id().to_spec(),
+                target: (&unit_time.unit.target).into(),
+                mode: unit_time.unit.mode,
+                elapsed: start,
+            });
+        }
         assert!(self.active.insert(id, unit_time).is_none());
     }
 

src/cargo/util/log_message.rs

@@ -28,6 +28,13 @@ pub enum LogMessage {
         target_dir: PathBuf,
         workspace_root: PathBuf,
     },
+    /// Emitted when a compilation unit starts.
+    UnitStarted {
+        package_id: PackageIdSpec,
+        target: Target,
+        mode: CompileMode,
+        elapsed: f64,
+    },
     /// Emitted when a compilation unit finishes.
     UnitFinished {
         package_id: PackageIdSpec,

tests/testsuite/build_analysis.rs

@@ -130,6 +130,18 @@ fn log_msg_timing_info() {
     "...": "{...}",
     "reason": "build-started"
   },
+  {
+    "elapsed": "{...}",
+    "mode": "check",
+    "package_id": "path+[ROOTURL]/foo/bar#0.0.0",
+    "reason": "unit-started",
+    "run_id": "[..]T[..]Z-[..]",
+    "target": {
+      "kind": "lib",
+      "name": "bar"
+    },
+    "timestamp": "[..]T[..]Z"
+  },
   {
     "duration": "{...}",
     "mode": "check",
@@ -143,6 +155,18 @@ fn log_msg_timing_info() {
     },
     "timestamp": "[..]T[..]Z"
   },
+  {
+    "elapsed": "{...}",
+    "mode": "check",
+    "package_id": "path+[ROOTURL]/foo#0.0.0",
+    "reason": "unit-started",
+    "run_id": "[..]T[..]Z-[..]",
+    "target": {
+      "kind": "lib",
+      "name": "foo"
+    },
+    "timestamp": "[..]T[..]Z"
+  },
   {
     "duration": "{...}",
     "mode": "check",
@@ -190,6 +214,10 @@ fn log_rebuild_reason_fresh_build() {
     "...": "{...}",
     "reason": "build-started"
   },
+  {
+    "...": "{...}",
+    "reason": "unit-started"
+  },
   {
     "...": "{...}",
     "reason": "unit-finished"
@@ -253,6 +281,10 @@ fn log_rebuild_reason_file_changed() {
     },
     "timestamp": "[..]T[..]Z"
   },
+  {
+    "...": "{...}",
+    "reason": "unit-started"
+  },
   {
     "...": "{...}",
     "reason": "unit-finished"