Skip to content

Commit 4aae037

Browse files
weihangloweihanglo
committed
feat(log): emit more section timing info
New events * UnitRmetaFinished * UnitSectionStarted * UnitSectionFinished So that no need to track rmeta and section timings in unit-finished
1 parent a7402b7 commit 4aae037

File tree

5 files changed

+253
-19
lines changed

5 files changed

+253
-19
lines changed

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -713,7 +713,7 @@ impl<'gctx> DrainState<'gctx> {
713713
self.tokens.push(token);
714714
}
715715
Message::SectionTiming(id, section) => {
716-
self.timings.unit_section_timing(id, &section);
716+
self.timings.unit_section_timing(build_runner, id, &section);
717717
}
718718
}
719719

@@ -1126,7 +1126,7 @@ impl<'gctx> DrainState<'gctx> {
11261126
let unlocked = self.queue.finish(unit, &artifact);
11271127
match artifact {
11281128
Artifact::All => self.timings.unit_finished(build_runner, id, unlocked),
1129-
Artifact::Metadata => self.timings.unit_rmeta_finished(id, unlocked),
1129+
Artifact::Metadata => self.timings.unit_rmeta_finished(build_runner, id, unlocked),
11301130
}
11311131
Ok(())
11321132
}

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1108,7 +1108,8 @@ fn add_allow_features(build_runner: &BuildRunner<'_, '_>, cmd: &mut ProcessBuild
11081108
/// [`--error-format`]: https://doc.rust-lang.org/nightly/rustc/command-line-arguments.html#--error-format-control-how-errors-are-produced
11091109
fn add_error_format_and_color(build_runner: &BuildRunner<'_, '_>, cmd: &mut ProcessBuilder) {
11101110
let enable_timings = build_runner.bcx.gctx.cli_unstable().section_timings
1111-
&& !build_runner.bcx.build_config.timing_outputs.is_empty();
1111+
&& (!build_runner.bcx.build_config.timing_outputs.is_empty()
1112+
|| build_runner.bcx.logger.is_some());
11121113
if enable_timings {
11131114
cmd.arg("-Zunstable-options");
11141115
}

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

Lines changed: 47 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -251,7 +251,12 @@ impl<'gctx> Timings<'gctx> {
251251
}
252252

253253
/// Mark that the `.rmeta` file as generated.
254-
pub fn unit_rmeta_finished(&mut self, id: JobId, unlocked: Vec<&Unit>) {
254+
pub fn unit_rmeta_finished(
255+
&mut self,
256+
build_runner: &BuildRunner<'_, '_>,
257+
id: JobId,
258+
unlocked: Vec<&Unit>,
259+
) {
255260
if !self.enabled {
256261
return;
257262
}
@@ -261,12 +266,25 @@ impl<'gctx> Timings<'gctx> {
261266
let Some(unit_time) = self.active.get_mut(&id) else {
262267
return;
263268
};
264-
let t = self.start.elapsed().as_secs_f64();
265-
unit_time.rmeta_time = Some(t - unit_time.start);
269+
let elapsed = self.start.elapsed().as_secs_f64();
270+
unit_time.rmeta_time = Some(elapsed - unit_time.start);
266271
assert!(unit_time.unlocked_rmeta_units.is_empty());
267272
unit_time
268273
.unlocked_rmeta_units
269274
.extend(unlocked.iter().cloned().cloned());
275+
276+
if let Some(logger) = build_runner.bcx.logger {
277+
let index = self.unit_to_index[&unit_time.unit] as u64;
278+
let unlocked = unlocked
279+
.iter()
280+
.map(|u| self.unit_to_index[u] as u64)
281+
.collect();
282+
logger.log(LogMessage::UnitRmetaFinished {
283+
index,
284+
elapsed,
285+
unlocked,
286+
});
287+
}
270288
}
271289

272290
/// Mark that a unit has finished running.
@@ -310,32 +328,52 @@ impl<'gctx> Timings<'gctx> {
310328
logger.log(LogMessage::UnitFinished {
311329
index,
312330
elapsed,
313-
rmeta_time: unit_time.rmeta_time,
314-
sections: unit_time.sections.clone().into_iter().collect(),
315331
unlocked,
316332
});
317333
}
318334
self.unit_times.push(unit_time);
319335
}
320336

321337
/// Handle the start/end of a compilation section.
322-
pub fn unit_section_timing(&mut self, id: JobId, section_timing: &SectionTiming) {
338+
pub fn unit_section_timing(
339+
&mut self,
340+
build_runner: &BuildRunner<'_, '_>,
341+
id: JobId,
342+
section_timing: &SectionTiming,
343+
) {
323344
if !self.enabled {
324345
return;
325346
}
326347
let Some(unit_time) = self.active.get_mut(&id) else {
327348
return;
328349
};
329-
let now = self.start.elapsed().as_secs_f64();
350+
let elapsed = self.start.elapsed().as_secs_f64();
330351

331352
match section_timing.event {
332353
SectionTimingEvent::Start => {
333-
unit_time.start_section(&section_timing.name, now);
354+
unit_time.start_section(&section_timing.name, elapsed);
334355
}
335356
SectionTimingEvent::End => {
336-
unit_time.end_section(&section_timing.name, now);
357+
unit_time.end_section(&section_timing.name, elapsed);
337358
}
338359
}
360+
361+
if let Some(logger) = build_runner.bcx.logger {
362+
let index = self.unit_to_index[&unit_time.unit] as u64;
363+
let section = section_timing.name.clone();
364+
logger.log(match section_timing.event {
365+
SectionTimingEvent::Start => LogMessage::UnitSectionStarted {
366+
index,
367+
elapsed,
368+
section,
369+
},
370+
SectionTimingEvent::End => LogMessage::UnitSectionFinished {
371+
index,
372+
elapsed,
373+
section,
374+
},
375+
})
376+
}
339377
}
340378

341379
/// This is called periodically to mark the concurrency of internal structures.

‎src/cargo/util/log_message.rs‎

Lines changed: 19 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@ use cargo_util_schemas::core::PackageIdSpec;
77
use jiff::Timestamp;
88
use serde::Serialize;
99

10-
use crate::core::compiler::CompilationSection;
1110
use crate::core::compiler::CompileMode;
1211
use crate::core::compiler::fingerprint::DirtyReason;
1312

@@ -36,14 +35,29 @@ pub enum LogMessage {
3635
index: u64,
3736
elapsed: f64,
3837
},
38+
/// Emitted when a section (e.g., rmeta, link) of the compilation unit finishes.
39+
UnitRmetaFinished {
40+
index: u64,
41+
elapsed: f64,
42+
#[serde(skip_serializing_if = "Vec::is_empty")]
43+
unlocked: Vec<u64>,
44+
},
45+
/// Emitted when a section (e.g., rmeta, link) of the compilation unit starts.
46+
UnitSectionStarted {
47+
index: u64,
48+
elapsed: f64,
49+
section: String,
50+
},
51+
/// Emitted when a section (e.g., rmeta, link) of the compilation unit finishes.
52+
UnitSectionFinished {
53+
index: u64,
54+
elapsed: f64,
55+
section: String,
56+
},
3957
/// Emitted when a compilation unit finishes.
4058
UnitFinished {
4159
index: u64,
4260
elapsed: f64,
43-
#[serde(skip_serializing_if = "Option::is_none")]
44-
rmeta_time: Option<f64>,
45-
#[serde(skip_serializing_if = "Vec::is_empty")]
46-
sections: Vec<(String, CompilationSection)>,
4761
#[serde(skip_serializing_if = "Vec::is_empty")]
4862
unlocked: Vec<u64>,
4963
},

‎tests/testsuite/build_analysis.rs‎

Lines changed: 183 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -143,11 +143,17 @@ fn log_msg_timing_info() {
143143
},
144144
"timestamp": "[..]T[..]Z"
145145
},
146+
{
147+
"elapsed": "{...}",
148+
"index": 0,
149+
"reason": "unit-rmeta-finished",
150+
"run_id": "[..]T[..]Z-[..]",
151+
"timestamp": "[..]T[..]Z"
152+
},
146153
{
147154
"elapsed": "{...}",
148155
"index": 0,
149156
"reason": "unit-finished",
150-
"rmeta_time": "{...}",
151157
"run_id": "[..]T[..]Z-[..]",
152158
"timestamp": "[..]T[..]Z",
153159
"unlocked": [
@@ -167,11 +173,178 @@ fn log_msg_timing_info() {
167173
},
168174
"timestamp": "[..]T[..]Z"
169175
},
176+
{
177+
"elapsed": "{...}",
178+
"index": 1,
179+
"reason": "unit-rmeta-finished",
180+
"run_id": "[..]T[..]Z-[..]",
181+
"timestamp": "[..]T[..]Z"
182+
},
183+
{
184+
"elapsed": "{...}",
185+
"index": 1,
186+
"reason": "unit-finished",
187+
"run_id": "[..]T[..]Z-[..]",
188+
"timestamp": "[..]T[..]Z"
189+
}
190+
]
191+
"#]]
192+
.is_json()
193+
.against_jsonlines(),
194+
);
195+
}
196+
197+
#[cargo_test(nightly, reason = "rustc --json=timings is unstable")]
198+
fn log_msg_timing_info_section_timings() {
199+
let p = project()
200+
.file(
201+
"Cargo.toml",
202+
r#"
203+
[package]
204+
name = "foo"
205+
version = "0.0.0"
206+
edition = "2015"
207+
208+
[dependencies]
209+
bar = { path = "bar" }
210+
"#,
211+
)
212+
.file("src/main.rs", "fn main() {}")
213+
.file("bar/Cargo.toml", &basic_manifest("bar", "0.0.0"))
214+
.file("bar/src/lib.rs", "")
215+
.build();
216+
217+
p.cargo("check -Zbuild-analysis -Zsection-timings")
218+
.env("CARGO_BUILD_ANALYSIS_ENABLED", "true")
219+
.masquerade_as_nightly_cargo(&["build-analysis", "section-timings"])
220+
.run();
221+
222+
assert_e2e().eq(
223+
&get_log(0),
224+
str![[r#"
225+
[
226+
{
227+
"...": "{...}",
228+
"reason": "build-started"
229+
},
230+
{
231+
"elapsed": "{...}",
232+
"index": 0,
233+
"mode": "check",
234+
"package_id": "path+[ROOTURL]/foo/bar#0.0.0",
235+
"reason": "unit-started",
236+
"run_id": "[..]T[..]Z-[..]",
237+
"target": {
238+
"kind": "lib",
239+
"name": "bar"
240+
},
241+
"timestamp": "[..]T[..]Z"
242+
},
243+
{
244+
"elapsed": "{...}",
245+
"index": 0,
246+
"reason": "unit-section-started",
247+
"run_id": "[..]T[..]Z-[..]",
248+
"section": "codegen",
249+
"timestamp": "[..]T[..]Z"
250+
},
251+
{
252+
"elapsed": "{...}",
253+
"index": 0,
254+
"reason": "unit-rmeta-finished",
255+
"run_id": "[..]T[..]Z-[..]",
256+
"timestamp": "[..]T[..]Z"
257+
},
258+
{
259+
"elapsed": "{...}",
260+
"index": 0,
261+
"reason": "unit-section-finished",
262+
"run_id": "[..]T[..]Z-[..]",
263+
"section": "codegen",
264+
"timestamp": "[..]T[..]Z"
265+
},
266+
{
267+
"elapsed": "{...}",
268+
"index": 0,
269+
"reason": "unit-section-started",
270+
"run_id": "[..]T[..]Z-[..]",
271+
"section": "link",
272+
"timestamp": "[..]T[..]Z"
273+
},
274+
{
275+
"elapsed": "{...}",
276+
"index": 0,
277+
"reason": "unit-section-finished",
278+
"run_id": "[..]T[..]Z-[..]",
279+
"section": "link",
280+
"timestamp": "[..]T[..]Z"
281+
},
282+
{
283+
"elapsed": "{...}",
284+
"index": 0,
285+
"reason": "unit-finished",
286+
"run_id": "[..]T[..]Z-[..]",
287+
"timestamp": "[..]T[..]Z",
288+
"unlocked": [
289+
1
290+
]
291+
},
292+
{
293+
"elapsed": "{...}",
294+
"index": 1,
295+
"mode": "check",
296+
"package_id": "path+[ROOTURL]/foo#0.0.0",
297+
"reason": "unit-started",
298+
"run_id": "[..]T[..]Z-[..]",
299+
"target": {
300+
"kind": "bin",
301+
"name": "foo"
302+
},
303+
"timestamp": "[..]T[..]Z"
304+
},
305+
{
306+
"elapsed": "{...}",
307+
"index": 1,
308+
"reason": "unit-section-started",
309+
"run_id": "[..]T[..]Z-[..]",
310+
"section": "codegen",
311+
"timestamp": "[..]T[..]Z"
312+
},
313+
{
314+
"elapsed": "{...}",
315+
"index": 1,
316+
"reason": "unit-rmeta-finished",
317+
"run_id": "[..]T[..]Z-[..]",
318+
"timestamp": "[..]T[..]Z"
319+
},
320+
{
321+
"elapsed": "{...}",
322+
"index": 1,
323+
"reason": "unit-section-finished",
324+
"run_id": "[..]T[..]Z-[..]",
325+
"section": "codegen",
326+
"timestamp": "[..]T[..]Z"
327+
},
328+
{
329+
"elapsed": "{...}",
330+
"index": 1,
331+
"reason": "unit-section-started",
332+
"run_id": "[..]T[..]Z-[..]",
333+
"section": "link",
334+
"timestamp": "[..]T[..]Z"
335+
},
336+
{
337+
"elapsed": "{...}",
338+
"index": 1,
339+
"reason": "unit-section-finished",
340+
"run_id": "[..]T[..]Z-[..]",
341+
"section": "link",
342+
"timestamp": "[..]T[..]Z"
343+
},
170344
{
171345
"elapsed": "{...}",
172346
"index": 1,
173347
"reason": "unit-finished",
174-
"rmeta_time": "{...}",
175348
"run_id": "[..]T[..]Z-[..]",
176349
"timestamp": "[..]T[..]Z"
177350
}
@@ -213,6 +386,10 @@ fn log_rebuild_reason_fresh_build() {
213386
"...": "{...}",
214387
"reason": "unit-started"
215388
},
389+
{
390+
"...": "{...}",
391+
"reason": "unit-rmeta-finished"
392+
},
216393
{
217394
"...": "{...}",
218395
"reason": "unit-finished"
@@ -280,6 +457,10 @@ fn log_rebuild_reason_file_changed() {
280457
"...": "{...}",
281458
"reason": "unit-started"
282459
},
460+
{
461+
"...": "{...}",
462+
"reason": "unit-rmeta-finished"
463+
},
283464
{
284465
"...": "{...}",
285466
"reason": "unit-finished"

0 commit comments

Comments
 (0)