fix(log): fix unit_to_index mapping from bcx

This also drops unit metadata fields in unit-started event.
The metdata is moved to unit-registered event instead

Author: weihanglo

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

@@ -17,7 +17,6 @@ use crate::util::{CargoResult, GlobalContext};
 
 use cargo_util::paths;
 use indexmap::IndexMap;
-use itertools::Itertools as _;
 use std::collections::HashMap;
 use std::io::BufWriter;
 use std::time::{Duration, Instant};
@@ -53,9 +52,6 @@ pub struct Timings<'gctx> {
     /// Total number of dirty units.
     total_dirty: u32,
     /// A map from unit to index.
-    ///
-    /// This for saving log size.
-    /// Only the unit-started event needs to hold the entire unit information.
     unit_to_index: HashMap<Unit, u64>,
     /// Time tracking for each individual unit.
     unit_times: Vec<UnitTime>,
@@ -174,13 +170,6 @@ impl<'gctx> Timings<'gctx> {
                 None
             }
         };
-        let unit_to_index = bcx
-            .unit_graph
-            .keys()
-            .sorted()
-            .enumerate()
-            .map(|(i, unit)| (unit.clone(), i as u64))
-            .collect();
 
         Timings {
             gctx: bcx.gctx,
@@ -193,7 +182,7 @@ impl<'gctx> Timings<'gctx> {
             profile,
             total_fresh: 0,
             total_dirty: 0,
-            unit_to_index,
+            unit_to_index: bcx.unit_to_index.clone(),
             unit_times: Vec::new(),
             active: HashMap::new(),
             last_cpu_state,
@@ -237,9 +226,6 @@ impl<'gctx> Timings<'gctx> {
         };
         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,
                 index: self.unit_to_index[&unit_time.unit],
                 elapsed: start,
             });

src/cargo/ops/cargo_report/timings.rs

@@ -1,5 +1,6 @@
 //! The `cargo report timings` command.
 
+use std::collections::HashMap;
 use std::ffi::OsStr;
 use std::fs::File;
 use std::io::BufReader;
@@ -178,6 +179,8 @@ fn prepare_context(log: &Path, run_id: &RunId) -> CargoResult<RenderContext<'sta
     };
     let mut units: IndexMap<_, UnitEntry> = IndexMap::new();
 
+    let mut unit_by_index: HashMap<u64, _> = HashMap::new();
+
     for (log_index, result) in serde_json::Deserializer::from_reader(reader)
         .into_iter::<LogMessage>()
         .enumerate()
@@ -208,13 +211,17 @@ fn prepare_context(log: &Path, run_id: &RunId) -> CargoResult<RenderContext<'sta
                 ctx.profile = profile;
                 ctx.rustc_version = rustc_version;
             }
-            LogMessage::UnitStarted {
+            LogMessage::UnitRegistered {
                 package_id,
                 target,
                 mode,
                 index,
-                elapsed,
             } => {
+                unit_by_index.insert(index, (package_id, target, mode));
+            }
+            LogMessage::UnitStarted { index, elapsed } => {
+                let (package_id, target, mode) = unit_by_index.get(&index).unwrap();
+
                 let version = package_id
                     .version()
                     .map(|v| v.to_string())
@@ -223,7 +230,7 @@ fn prepare_context(log: &Path, run_id: &RunId) -> CargoResult<RenderContext<'sta
                 // This is pretty similar to how the current `core::compiler::timings`
                 // renders `core::manifest::Target`. However, our target is
                 // a simplified type so we cannot reuse the same logic here.
-                let mut target_str = if target.kind == "lib" && mode == CompileMode::Build {
+                let mut target_str = if target.kind == "lib" && mode == &CompileMode::Build {
                     // Special case for brevity, since most dependencies hit this path.
                     "".to_string()
                 } else if target.kind == "build-script" {

src/cargo/util/log_message.rs

@@ -74,20 +74,14 @@ pub enum LogMessage {
     },
     /// Emitted when a compilation unit starts.
     UnitStarted {
-        /// Package ID specification.
-        package_id: PackageIdSpec,
-        /// Cargo target (lib, bin, example, etc.).
-        target: Target,
-        /// The compilation action this unit is for (check, build, test, etc.).
-        mode: CompileMode,
-        /// Unit index for compact reference in subsequent events.
+        /// Unit index from the associated unit-registered event.
         index: u64,
         /// Seconds elapsed from build start.
         elapsed: f64,
     },
     /// Emitted when a section (e.g., rmeta, link) of the compilation unit finishes.
     UnitRmetaFinished {
-        /// Unit index from the associated unit-started event.
+        /// Unit index from the associated unit-registered event.
         index: u64,
         /// Seconds elapsed from build start.
         elapsed: f64,
@@ -99,7 +93,7 @@ pub enum LogMessage {
     ///
     /// Requires `-Zsection-timings` to be enabled.
     UnitSectionStarted {
-        /// Unit index from the associated unit-started event.
+        /// Unit index from the associated unit-registered event.
         index: u64,
         /// Seconds elapsed from build start.
         elapsed: f64,
@@ -110,7 +104,7 @@ pub enum LogMessage {
     ///
     /// Requires `-Zsection-timings` to be enabled.
     UnitSectionFinished {
-        /// Unit index from the associated unit-started event.
+        /// Unit index from the associated unit-registered event.
         index: u64,
         /// Seconds elapsed from build start.
         elapsed: f64,
@@ -119,7 +113,7 @@ pub enum LogMessage {
     },
     /// Emitted when a compilation unit finishes.
     UnitFinished {
-        /// Unit index from the associated unit-started event.
+        /// Unit index from the associated unit-registered event.
         index: u64,
         /// Seconds elapsed from build start.
         elapsed: f64,

tests/testsuite/build_analysis.rs

@@ -131,14 +131,8 @@ fn log_msg_timing_info() {
   {
     "elapsed": "{...}",
     "index": 0,
-    "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"
   },
   {
@@ -161,14 +155,8 @@ fn log_msg_timing_info() {
   {
     "elapsed": "{...}",
     "index": 1,
-    "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"
   },
   {
@@ -225,14 +213,8 @@ fn log_msg_timing_info_section_timings() {
   {
     "elapsed": "{...}",
     "index": 0,
-    "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"
   },
   {
@@ -287,14 +269,8 @@ fn log_msg_timing_info_section_timings() {
   {
     "elapsed": "{...}",
     "index": 1,
-    "mode": "check",
-    "package_id": "path+[ROOTURL]/foo#0.0.0",
     "reason": "unit-started",
     "run_id": "[..]T[..]Z-[..]",
-    "target": {
-      "kind": "bin",
-      "name": "foo"
-    },
     "timestamp": "[..]T[..]Z"
   },
   {