fix(log): recored elapsed time rather than duration

Author: weihanglo

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

@@ -713,7 +713,7 @@ impl<'gctx> DrainState<'gctx> {
                 self.tokens.push(token);
             }
             Message::SectionTiming(id, section) => {
-                self.timings.unit_section_timing(id, &section);
+                self.timings.unit_section_timing(build_runner, id, &section);
             }
         }
 
@@ -1126,7 +1126,9 @@ impl<'gctx> DrainState<'gctx> {
         let unblocked = self.queue.finish(unit, &artifact);
         match artifact {
             Artifact::All => self.timings.unit_finished(build_runner, id, unblocked),
-            Artifact::Metadata => self.timings.unit_rmeta_finished(id, unblocked),
+            Artifact::Metadata => self
+                .timings
+                .unit_rmeta_finished(build_runner, id, unblocked),
         }
         Ok(())
     }

src/cargo/core/compiler/mod.rs

@@ -1108,7 +1108,8 @@ 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();
+        && (!build_runner.bcx.build_config.timing_outputs.is_empty()
+            || build_runner.bcx.logger.is_some());
     if enable_timings {
         cmd.arg("-Zunstable-options");
     }

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

@@ -267,7 +267,12 @@ impl<'gctx> Timings<'gctx> {
     }
 
     /// Mark that the `.rmeta` file as generated.
-    pub fn unit_rmeta_finished(&mut self, id: JobId, unblocked: Vec<&Unit>) {
+    pub fn unit_rmeta_finished(
+        &mut self,
+        build_runner: &BuildRunner<'_, '_>,
+        id: JobId,
+        unblocked: Vec<&Unit>,
+    ) {
         if !self.enabled {
             return;
         }
@@ -277,12 +282,21 @@ impl<'gctx> Timings<'gctx> {
         let Some(unit_time) = self.active.get_mut(&id) else {
             return;
         };
-        let t = self.start.elapsed().as_secs_f64();
-        unit_time.rmeta_time = Some(t - unit_time.start);
+        let elapsed = self.start.elapsed().as_secs_f64();
+        unit_time.rmeta_time = Some(elapsed - unit_time.start);
         assert!(unit_time.unblocked_rmeta_units.is_empty());
         unit_time
             .unblocked_rmeta_units
             .extend(unblocked.iter().cloned().cloned());
+
+        if let Some(logger) = build_runner.bcx.logger {
+            let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
+            logger.log(LogMessage::UnitRmetaFinished {
+                index: self.unit_to_index[&unit_time.unit],
+                elapsed,
+                unblocked,
+            });
+        }
     }
 
     /// Mark that a unit has finished running.
@@ -299,8 +313,8 @@ impl<'gctx> Timings<'gctx> {
         let Some(mut unit_time) = self.active.remove(&id) else {
             return;
         };
-        let t = self.start.elapsed().as_secs_f64();
-        unit_time.duration = t - unit_time.start;
+        let elapsed = self.start.elapsed().as_secs_f64();
+        unit_time.duration = elapsed - unit_time.start;
         assert!(unit_time.unblocked_units.is_empty());
         unit_time
             .unblocked_units
@@ -321,33 +335,53 @@ impl<'gctx> Timings<'gctx> {
             let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
             logger.log(LogMessage::UnitFinished {
                 index: self.unit_to_index[&unit_time.unit],
-                duration: unit_time.duration,
-                rmeta_time: unit_time.rmeta_time,
-                sections: unit_time.sections.clone().into_iter().collect(),
+                elapsed,
                 unblocked,
             });
         }
         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) {
+    pub fn unit_section_timing(
+        &mut self,
+        build_runner: &BuildRunner<'_, '_>,
+        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();
+        let elapsed = self.start.elapsed().as_secs_f64();
 
         match section_timing.event {
             SectionTimingEvent::Start => {
-                unit_time.start_section(&section_timing.name, now);
+                unit_time.start_section(&section_timing.name, elapsed);
             }
             SectionTimingEvent::End => {
-                unit_time.end_section(&section_timing.name, now);
+                unit_time.end_section(&section_timing.name, elapsed);
             }
         }
+
+        if let Some(logger) = build_runner.bcx.logger {
+            let index = self.unit_to_index[&unit_time.unit];
+            let section = section_timing.name.clone();
+            logger.log(match section_timing.event {
+                SectionTimingEvent::Start => LogMessage::UnitSectionStarted {
+                    index,
+                    elapsed,
+                    section,
+                },
+                SectionTimingEvent::End => LogMessage::UnitSectionFinished {
+                    index,
+                    elapsed,
+                    section,
+                },
+            })
+        }
     }
 
     /// This is called periodically to mark the concurrency of internal structures.

src/cargo/util/log_message.rs

@@ -7,7 +7,6 @@ use cargo_util_schemas::core::PackageIdSpec;
 use jiff::Timestamp;
 use serde::Serialize;
 
-use crate::core::compiler::CompilationSection;
 use crate::core::compiler::CompileMode;
 use crate::core::compiler::fingerprint::DirtyReason;
 
@@ -36,14 +35,29 @@ pub enum LogMessage {
         index: u64,
         elapsed: f64,
     },
+    /// Emitted when a section (e.g., rmeta, link) of the compilation unit finishes.
+    UnitRmetaFinished {
+        index: u64,
+        elapsed: f64,
+        #[serde(skip_serializing_if = "Vec::is_empty")]
+        unblocked: Vec<u64>,
+    },
+    /// Emitted when a section (e.g., rmeta, link) of the compilation unit starts.
+    UnitSectionStarted {
+        index: u64,
+        elapsed: f64,
+        section: String,
+    },
+    /// Emitted when a section (e.g., rmeta, link) of the compilation unit finishes.
+    UnitSectionFinished {
+        index: u64,
+        elapsed: f64,
+        section: String,
+    },
     /// Emitted when a compilation unit finishes.
     UnitFinished {
         index: u64,
-        duration: f64,
-        #[serde(skip_serializing_if = "Option::is_none")]
-        rmeta_time: Option<f64>,
-        #[serde(skip_serializing_if = "Vec::is_empty")]
-        sections: Vec<(String, CompilationSection)>,
+        elapsed: f64,
         #[serde(skip_serializing_if = "Vec::is_empty")]
         unblocked: Vec<u64>,
     },