diff --git a/src/cargo/core/compiler/fingerprint/mod.rs b/src/cargo/core/compiler/fingerprint/mod.rs index e5bf19f4a3b..3cc431e1f93 100644 --- a/src/cargo/core/compiler/fingerprint/mod.rs +++ b/src/cargo/core/compiler/fingerprint/mod.rs @@ -454,7 +454,7 @@ pub fn prepare_target( if !dirty_reason.is_fresh_build() { logger.log(LogMessage::Rebuild { package_id: unit.pkg.package_id().to_spec(), - target: unit.target.clone(), + target: (&unit.target).into(), mode: unit.mode, cause: dirty_reason.clone(), }); diff --git a/src/cargo/core/compiler/job_queue/mod.rs b/src/cargo/core/compiler/job_queue/mod.rs index 13675a50791..5fa0252e306 100644 --- a/src/cargo/core/compiler/job_queue/mod.rs +++ b/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)?; @@ -712,7 +713,7 @@ impl<'gctx> DrainState<'gctx> { self.tokens.push(token); } Message::SectionTiming(id, section) => { - self.timings.unit_section_timing(id, §ion); + self.timings.unit_section_timing(build_runner, id, §ion); } } @@ -1122,10 +1123,12 @@ impl<'gctx> DrainState<'gctx> { unit.show_warnings(build_runner.bcx.gctx), )?; } - let unlocked = self.queue.finish(unit, &artifact); + let unblocked = self.queue.finish(unit, &artifact); match artifact { - Artifact::All => self.timings.unit_finished(build_runner, id, unlocked), - Artifact::Metadata => self.timings.unit_rmeta_finished(id, unlocked), + Artifact::All => self.timings.unit_finished(build_runner, id, unblocked), + Artifact::Metadata => self + .timings + .unit_rmeta_finished(build_runner, id, unblocked), } Ok(()) } diff --git a/src/cargo/core/compiler/mod.rs b/src/cargo/core/compiler/mod.rs index 84093ff0a96..3466baafb05 100644 --- a/src/cargo/core/compiler/mod.rs +++ b/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"); } diff --git a/src/cargo/core/compiler/timings/mod.rs b/src/cargo/core/compiler/timings/mod.rs index 9491112ab7d..bae60ee2ccc 100644 --- a/src/cargo/core/compiler/timings/mod.rs +++ b/src/cargo/core/compiler/timings/mod.rs @@ -17,6 +17,7 @@ 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}; @@ -51,6 +52,11 @@ pub struct Timings<'gctx> { total_fresh: u32, /// 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, /// Time tracking for each individual unit. unit_times: Vec, /// Units that are in the process of being built. @@ -89,10 +95,10 @@ struct UnitTime { /// The time when the `.rmeta` file was generated, an offset in seconds /// from `start`. rmeta_time: Option, - /// Reverse deps that are freed to run after this unit finished. - unlocked_units: Vec, - /// Same as `unlocked_units`, but unlocked by rmeta. - unlocked_rmeta_units: Vec, + /// Reverse deps that are unblocked and ready to run after this unit finishes. + unblocked_units: Vec, + /// Same as `unblocked_units`, but unblocked by rmeta. + unblocked_rmeta_units: Vec, /// Individual compilation section durations, gathered from `--json=timings`. /// /// IndexMap is used to keep original insertion order, we want to be able to tell which @@ -127,18 +133,41 @@ struct UnitData { start: f64, duration: f64, rmeta_time: Option, - unlocked_units: Vec, - unlocked_rmeta_units: Vec, + unblocked_units: Vec, + unblocked_rmeta_units: Vec, sections: Option>, } impl<'gctx> Timings<'gctx> { pub fn new(bcx: &BuildContext<'_, 'gctx>, root_units: &[Unit]) -> Timings<'gctx> { + let start = bcx.gctx.creation_time(); 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 | bcx.logger.is_some(); + if !enabled { + return Timings { + gctx: bcx.gctx, + enabled, + report_html, + report_json, + start, + start_str: String::new(), + root_targets: Vec::new(), + profile: String::new(), + total_fresh: 0, + total_dirty: 0, + unit_to_index: HashMap::new(), + unit_times: Vec::new(), + active: HashMap::new(), + concurrency: Vec::new(), + last_cpu_state: None, + last_cpu_recording: Instant::now(), + cpu_usage: Vec::new(), + }; + } + let mut root_map: HashMap> = HashMap::new(); for unit in root_units { let target_desc = unit.target.description_named(); @@ -156,29 +185,33 @@ impl<'gctx> Timings<'gctx> { .collect(); let start_str = jiff::Timestamp::now().to_string(); let profile = bcx.build_config.requested_profile.to_string(); - let last_cpu_state = if enabled { - match State::current() { - Ok(state) => Some(state), - Err(e) => { - tracing::info!("failed to get CPU state, CPU tracking disabled: {:?}", e); - None - } + let last_cpu_state = match State::current() { + Ok(state) => Some(state), + Err(e) => { + tracing::info!("failed to get CPU state, CPU tracking disabled: {:?}", e); + None } - } else { - None }; + let unit_to_index = bcx + .unit_graph + .keys() + .sorted() + .enumerate() + .map(|(i, unit)| (unit.clone(), i as u64)) + .collect(); Timings { gctx: bcx.gctx, enabled, report_html, report_json, - start: bcx.gctx.creation_time(), + start, start_str, root_targets, profile, total_fresh: 0, total_dirty: 0, + unit_to_index, unit_times: Vec::new(), active: HashMap::new(), concurrency: Vec::new(), @@ -189,7 +222,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,21 +243,36 @@ 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, - unlocked_units: Vec::new(), - unlocked_rmeta_units: Vec::new(), + 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, + index: self.unit_to_index[&unit_time.unit], + elapsed: start, + }); + } assert!(self.active.insert(id, unit_time).is_none()); } /// Mark that the `.rmeta` file as generated. - pub fn unit_rmeta_finished(&mut self, id: JobId, unlocked: Vec<&Unit>) { + pub fn unit_rmeta_finished( + &mut self, + build_runner: &BuildRunner<'_, '_>, + id: JobId, + unblocked: Vec<&Unit>, + ) { if !self.enabled { return; } @@ -234,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); - assert!(unit_time.unlocked_rmeta_units.is_empty()); + 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 - .unlocked_rmeta_units - .extend(unlocked.iter().cloned().cloned()); + .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. @@ -247,7 +304,7 @@ impl<'gctx> Timings<'gctx> { &mut self, build_runner: &BuildRunner<'_, '_>, id: JobId, - unlocked: Vec<&Unit>, + unblocked: Vec<&Unit>, ) { if !self.enabled { return; @@ -256,12 +313,12 @@ 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; - assert!(unit_time.unlocked_units.is_empty()); + let elapsed = self.start.elapsed().as_secs_f64(); + unit_time.duration = elapsed - unit_time.start; + assert!(unit_time.unblocked_units.is_empty()); unit_time - .unlocked_units - .extend(unlocked.iter().cloned().cloned()); + .unblocked_units + .extend(unblocked.iter().cloned().cloned()); if self.report_json { let msg = machine_message::TimingInfo { package_id: unit_time.unit.pkg.package_id().to_spec(), @@ -275,36 +332,56 @@ impl<'gctx> Timings<'gctx> { 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(), + let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect(); + logger.log(LogMessage::UnitFinished { + index: self.unit_to_index[&unit_time.unit], + 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(§ion_timing.name, now); + unit_time.start_section(§ion_timing.name, elapsed); } SectionTimingEvent::End => { - unit_time.end_section(§ion_timing.name, now); + unit_time.end_section(§ion_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. diff --git a/src/cargo/core/compiler/timings/report.rs b/src/cargo/core/compiler/timings/report.rs index 0fdc248e173..6faac2a6c43 100644 --- a/src/cargo/core/compiler/timings/report.rs +++ b/src/cargo/core/compiler/timings/report.rs @@ -373,13 +373,13 @@ fn to_unit_data(unit_times: &[UnitTime]) -> Vec { // These filter on the unlocked units because not all unlocked // units are actually "built". For example, Doctest mode units // don't actually generate artifacts. - let unlocked_units: Vec = ut - .unlocked_units + let unblocked_units: Vec = ut + .unblocked_units .iter() .filter_map(|unit| unit_map.get(unit).copied()) .collect(); - let unlocked_rmeta_units: Vec = ut - .unlocked_rmeta_units + let unblocked_rmeta_units: Vec = ut + .unblocked_rmeta_units .iter() .filter_map(|unit| unit_map.get(unit).copied()) .collect(); @@ -419,8 +419,8 @@ fn to_unit_data(unit_times: &[UnitTime]) -> Vec { start: round(ut.start), duration: round(ut.duration), rmeta_time: ut.rmeta_time.map(round), - unlocked_units, - unlocked_rmeta_units, + unblocked_units, + unblocked_rmeta_units, sections, } }) diff --git a/src/cargo/util/log_message.rs b/src/cargo/util/log_message.rs index ea3e49085d8..e0cf19f7769 100644 --- a/src/cargo/util/log_message.rs +++ b/src/cargo/util/log_message.rs @@ -7,8 +7,6 @@ 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; use crate::core::compiler::fingerprint::DirtyReason; @@ -20,35 +18,117 @@ use crate::core::compiler::fingerprint::DirtyReason; pub enum LogMessage { /// Emitted when a build starts. BuildStarted { + /// Current working directory. cwd: PathBuf, + /// Host triple. host: String, + /// Number of parallel jobs. jobs: u32, + /// Build profile name (e.g., "dev", "release"). profile: String, + /// The rustc version (`1.23.4-beta.2`). rustc_version: String, + /// The rustc verbose version information (the output of `rustc -vV`). rustc_version_verbose: String, + /// Target directory for build artifacts. target_dir: PathBuf, + /// Workspace root directory. workspace_root: PathBuf, }, - /// Emitted when a compilation unit finishes. - TimingInfo { + /// 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, - duration: f64, - #[serde(skip_serializing_if = "Option::is_none")] - rmeta_time: Option, + /// Unit index for compact reference in subsequent events. + 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. + index: u64, + /// Seconds elapsed from build start. + elapsed: f64, + /// Unit indices that were unblocked by this rmeta completion. + #[serde(skip_serializing_if = "Vec::is_empty")] + unblocked: Vec, + }, + /// Emitted when a section (e.g., rmeta, link) of the compilation unit starts. + /// + /// Requires `-Zsection-timings` to be enabled. + UnitSectionStarted { + /// Unit index from the associated unit-started event. + index: u64, + /// Seconds elapsed from build start. + elapsed: f64, + /// Section name from rustc's `-Zjson=timings` (e.g., "codegen", "link"). + section: String, + }, + /// Emitted when a section (e.g., rmeta, link) of the compilation unit finishes. + /// + /// Requires `-Zsection-timings` to be enabled. + UnitSectionFinished { + /// Unit index from the associated unit-started event. + index: u64, + /// Seconds elapsed from build start. + elapsed: f64, + /// Section name from rustc's `-Zjson=timings` (e.g., "codegen", "link"). + section: String, + }, + /// Emitted when a compilation unit finishes. + UnitFinished { + /// Unit index from the associated unit-started event. + index: u64, + /// Seconds elapsed from build start. + elapsed: f64, + /// Unit indices that were unblocked by this completion. #[serde(skip_serializing_if = "Vec::is_empty")] - sections: Vec<(String, CompilationSection)>, + unblocked: Vec, }, /// Emitted when a unit needs to be rebuilt. Rebuild { + /// 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, + /// Reason why the unit is dirty and needs rebuilding. cause: DirtyReason, }, } +/// Cargo target information. +#[derive(Serialize)] +pub struct Target { + /// Target name. + name: String, + /// Target kind (lib, bin, test, bench, example, build-script). + kind: &'static str, +} + +impl From<&crate::core::Target> for Target { + fn from(target: &crate::core::Target) -> Self { + use crate::core::TargetKind; + Self { + name: target.name().to_string(), + kind: match target.kind() { + TargetKind::Lib(..) => "lib", + TargetKind::Bin => "bin", + TargetKind::Test => "test", + TargetKind::Bench => "bench", + TargetKind::ExampleLib(..) | TargetKind::ExampleBin => "example", + TargetKind::CustomBuild => "build-script", + }, + } + } +} + impl LogMessage { /// Serializes this message as a JSON log line directly to the writer. pub fn write_json_log(&self, writer: &mut W, run_id: &str) -> std::io::Result<()> { diff --git a/src/doc/src/reference/timings.md b/src/doc/src/reference/timings.md index e8ff751caf5..c7d1620c156 100644 --- a/src/doc/src/reference/timings.md +++ b/src/doc/src/reference/timings.md @@ -20,13 +20,13 @@ version information of the currently used compiler. ![build-info](../images/build-info.png) -The "unit" graph shows the duration of each unit over time. A "unit" is a single -compiler invocation. There are lines that show which additional units are -"unlocked" when a unit finishes. That is, it shows the new units that are now -allowed to run because their dependencies are all finished. Hover the mouse over -a unit to highlight the lines. This can help visualize the critical path of -dependencies. This may change between runs because the units may finish in -different orders. +The "unit" graph shows the duration of each unit over time. +A "unit" is a single compiler invocation. +There are lines that show which additional units are "unblocked" when a unit finishes. +That is, it shows the new units that are now allowed to run because their dependencies are all finished. +Hover the mouse over a unit to highlight the lines. +This can help visualize the critical path of dependencies. +This may change between runs because the units may finish in different orders. The "codegen" times are highlighted in a lavender color. In some cases, build pipelining allows units to start when their dependencies are performing code diff --git a/tests/testsuite/build_analysis.rs b/tests/testsuite/build_analysis.rs index a485103cd1f..4a15bed21a5 100644 --- a/tests/testsuite/build_analysis.rs +++ b/tests/testsuite/build_analysis.rs @@ -127,27 +127,225 @@ fn log_msg_timing_info() { str![[r#" [ { - "reason": "build-started", - "...": "{...}" + "...": "{...}", + "reason": "build-started" + }, + { + "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" + }, + { + "elapsed": "{...}", + "index": 0, + "reason": "unit-rmeta-finished", + "run_id": "[..]T[..]Z-[..]", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 0, + "reason": "unit-finished", + "run_id": "[..]T[..]Z-[..]", + "timestamp": "[..]T[..]Z", + "unblocked": [ + 1 + ] + }, + { + "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" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-rmeta-finished", + "run_id": "[..]T[..]Z-[..]", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-finished", + "run_id": "[..]T[..]Z-[..]", + "timestamp": "[..]T[..]Z" + } +] +"#]] + .is_json() + .against_jsonlines(), + ); +} + +#[cargo_test(nightly, reason = "rustc --json=timings is unstable")] +fn log_msg_timing_info_section_timings() { + let p = project() + .file( + "Cargo.toml", + r#" + [package] + name = "foo" + version = "0.0.0" + edition = "2015" + + [dependencies] + bar = { path = "bar" } + "#, + ) + .file("src/main.rs", "fn main() {}") + .file("bar/Cargo.toml", &basic_manifest("bar", "0.0.0")) + .file("bar/src/lib.rs", "") + .build(); + + p.cargo("check -Zbuild-analysis -Zsection-timings") + .env("CARGO_BUILD_ANALYSIS_ENABLED", "true") + .masquerade_as_nightly_cargo(&["build-analysis", "section-timings"]) + .run(); + + assert_e2e().eq( + &get_log(0), + str![[r#" +[ + { + "...": "{...}", + "reason": "build-started" }, { - "duration": "{...}", + "elapsed": "{...}", + "index": 0, "mode": "check", "package_id": "path+[ROOTURL]/foo/bar#0.0.0", - "reason": "timing-info", - "rmeta_time": "{...}", + "reason": "unit-started", "run_id": "[..]T[..]Z-[..]", - "target": "{...}", + "target": { + "kind": "lib", + "name": "bar" + }, "timestamp": "[..]T[..]Z" }, { - "duration": "{...}", + "elapsed": "{...}", + "index": 0, + "reason": "unit-section-started", + "run_id": "[..]T[..]Z-[..]", + "section": "codegen", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 0, + "reason": "unit-rmeta-finished", + "run_id": "[..]T[..]Z-[..]", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 0, + "reason": "unit-section-finished", + "run_id": "[..]T[..]Z-[..]", + "section": "codegen", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 0, + "reason": "unit-section-started", + "run_id": "[..]T[..]Z-[..]", + "section": "link", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 0, + "reason": "unit-section-finished", + "run_id": "[..]T[..]Z-[..]", + "section": "link", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 0, + "reason": "unit-finished", + "run_id": "[..]T[..]Z-[..]", + "timestamp": "[..]T[..]Z", + "unblocked": [ + 1 + ] + }, + { + "elapsed": "{...}", + "index": 1, "mode": "check", "package_id": "path+[ROOTURL]/foo#0.0.0", - "reason": "timing-info", - "rmeta_time": "{...}", + "reason": "unit-started", + "run_id": "[..]T[..]Z-[..]", + "target": { + "kind": "bin", + "name": "foo" + }, + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-section-started", + "run_id": "[..]T[..]Z-[..]", + "section": "codegen", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-rmeta-finished", + "run_id": "[..]T[..]Z-[..]", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-section-finished", + "run_id": "[..]T[..]Z-[..]", + "section": "codegen", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-section-started", + "run_id": "[..]T[..]Z-[..]", + "section": "link", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-section-finished", + "run_id": "[..]T[..]Z-[..]", + "section": "link", + "timestamp": "[..]T[..]Z" + }, + { + "elapsed": "{...}", + "index": 1, + "reason": "unit-finished", "run_id": "[..]T[..]Z-[..]", - "target": "{...}", "timestamp": "[..]T[..]Z" } ] @@ -186,7 +384,15 @@ fn log_rebuild_reason_fresh_build() { }, { "...": "{...}", - "reason": "timing-info" + "reason": "unit-started" + }, + { + "...": "{...}", + "reason": "unit-rmeta-finished" + }, + { + "...": "{...}", + "reason": "unit-finished" } ] "#]] @@ -241,12 +447,23 @@ fn log_rebuild_reason_file_changed() { "package_id": "path+[ROOTURL]/foo#0.0.0", "reason": "rebuild", "run_id": "[..]T[..]Z-[..]", - "target": "{...}", + "target": { + "kind": "lib", + "name": "foo" + }, "timestamp": "[..]T[..]Z" }, { "...": "{...}", - "reason": "timing-info" + "reason": "unit-started" + }, + { + "...": "{...}", + "reason": "unit-rmeta-finished" + }, + { + "...": "{...}", + "reason": "unit-finished" } ] "#]]