Skip to content

Commit ffba21a

Browse files
committed
feat(report): cargo report timings HTML replay
This implements `cargo report timings` HTML replay feature. The help text looks like: ``` Reports the build timings of previous builds (unstable) Usage: cargo report timings [OPTIONS] Options: --open Opens the timing report in a browser ... ``` The replayed HTML report will be written to * If in a Cargo workspace, write to `<artifact-dir>/cargo-timings/` * Otherwise, write to a temp directory The log discovery logic * Currently look at the newest log file for the workspace. * If not in a workspace, pick the newest log file in the log directory.
1 parent e11a624 commit ffba21a

File tree

2 files changed

+329
-14
lines changed

2 files changed

+329
-14
lines changed

src/cargo/ops/cargo_report/timings.rs

Lines changed: 289 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -2,30 +2,54 @@
22
33
use std::ffi::OsStr;
44
use std::fs::File;
5+
use std::io::BufReader;
6+
use std::path::Path;
57
use std::path::PathBuf;
68

79
use annotate_snippets::Level;
810
use anyhow::Context as _;
11+
use cargo_util::paths;
12+
use indexmap::IndexMap;
13+
use indexmap::map::Entry;
14+
use itertools::Itertools as _;
15+
use tempfile::TempDir;
916

1017
use crate::AlreadyPrintedError;
1118
use crate::CargoResult;
1219
use crate::GlobalContext;
1320
use crate::core::Workspace;
21+
use crate::core::compiler::CompileMode;
22+
use crate::core::compiler::timings::CompilationSection;
23+
use crate::core::compiler::timings::UnitData;
24+
use crate::core::compiler::timings::report::RenderContext;
25+
use crate::core::compiler::timings::report::aggregate_sections;
26+
use crate::core::compiler::timings::report::compute_concurrency;
27+
use crate::core::compiler::timings::report::round_to_centisecond;
28+
use crate::core::compiler::timings::report::write_html;
1429
use crate::util::BuildLogger;
1530
use crate::util::important_paths::find_root_manifest_for_wd;
31+
use crate::util::log_message::LogMessage;
1632
use crate::util::logger::RunId;
33+
use crate::util::style;
1734

1835
pub struct ReportTimingsOptions<'gctx> {
1936
/// Whether to attempt to open the browser after the report is generated
2037
pub open_result: bool,
2138
pub gctx: &'gctx GlobalContext,
2239
}
2340

24-
pub fn report_timings(gctx: &GlobalContext, _opts: ReportTimingsOptions<'_>) -> CargoResult<()> {
41+
/// Collects sections data for later post-processing through [`aggregate_sections`].
42+
struct UnitEntry {
43+
data: UnitData,
44+
sections: IndexMap<String, CompilationSection>,
45+
rmeta_time: Option<f64>,
46+
}
47+
48+
pub fn report_timings(gctx: &GlobalContext, opts: ReportTimingsOptions<'_>) -> CargoResult<()> {
2549
let ws = find_root_manifest_for_wd(gctx.cwd())
2650
.ok()
2751
.and_then(|manifest_path| Workspace::new(&manifest_path, gctx).ok());
28-
let Some((log, _run_id)) = select_log_file(gctx, ws.as_ref())? else {
52+
let Some((log, run_id)) = select_log_file(gctx, ws.as_ref())? else {
2953
let title_extra = if let Some(ws) = ws {
3054
format!(" for workspace at `{}`", ws.root().display())
3155
} else {
@@ -40,9 +64,43 @@ pub fn report_timings(gctx: &GlobalContext, _opts: ReportTimingsOptions<'_>) ->
4064
return Err(AlreadyPrintedError::new(anyhow::anyhow!("")).into());
4165
};
4266

43-
let _f = File::open(&log)
67+
let ctx = prepare_context(&log, &run_id)
4468
.with_context(|| format!("failed to analyze log at `{}`", log.display()))?;
4569

70+
// If we are in a workspace,
71+
// put timing reports in <target-dir>/cargo-timings/` as usual for easy access.
72+
// Otherwise in a temporary directory
73+
let reports_dir = if let Some(ws) = ws {
74+
let target_dir = ws.target_dir();
75+
let target_dir = target_dir.as_path_unlocked();
76+
paths::create_dir_all_excluded_from_backups_atomic(target_dir)?;
77+
let timings_dir = target_dir.join("cargo-timings");
78+
paths::create_dir_all(&timings_dir)?;
79+
timings_dir
80+
} else {
81+
TempDir::with_prefix("cargo-timings-")?.keep()
82+
};
83+
84+
let timing_path = reports_dir.join(format!("cargo-timing-{run_id}.html"));
85+
86+
let mut out_file = std::fs::OpenOptions::new()
87+
.write(true)
88+
.create(true)
89+
.truncate(true)
90+
.open(&timing_path)
91+
.with_context(|| format!("failed to open `{}`", timing_path.display()))?;
92+
93+
write_html(ctx, &mut out_file)?;
94+
95+
let link = gctx.shell().err_file_hyperlink(&timing_path);
96+
let msg = format!("report saved to {link}{}{link:#}", timing_path.display());
97+
gctx.shell()
98+
.status_with_color("Timing", msg, &style::NOTE)?;
99+
100+
if opts.open_result {
101+
crate::util::open::open(&timing_path, gctx)?;
102+
}
103+
46104
Ok(())
47105
}
48106

@@ -96,3 +154,231 @@ fn select_log_file(
96154

97155
Ok(item.map(|(entry, run_id)| (entry.into_path(), run_id)))
98156
}
157+
158+
fn prepare_context(log: &Path, run_id: &RunId) -> CargoResult<RenderContext<'static>> {
159+
let reader = BufReader::new(File::open(&log)?);
160+
161+
let mut ctx = RenderContext {
162+
start_str: run_id.timestamp().to_string(),
163+
root_units: Default::default(),
164+
profile: Default::default(),
165+
total_fresh: Default::default(),
166+
total_dirty: Default::default(),
167+
unit_data: Default::default(),
168+
concurrency: Default::default(),
169+
cpu_usage: Default::default(),
170+
rustc_version: Default::default(),
171+
host: Default::default(),
172+
requested_targets: Default::default(),
173+
jobs: 0,
174+
num_cpus: None,
175+
error: &None,
176+
};
177+
let mut units: IndexMap<_, UnitEntry> = IndexMap::new();
178+
179+
for (log_index, result) in serde_json::Deserializer::from_reader(reader)
180+
.into_iter::<LogMessage>()
181+
.enumerate()
182+
{
183+
let msg = match result {
184+
Ok(msg) => msg,
185+
Err(e) => {
186+
tracing::warn!("failed to parse log message at index {log_index}: {e}");
187+
continue;
188+
}
189+
};
190+
191+
match msg {
192+
LogMessage::BuildStarted {
193+
cwd: _,
194+
host,
195+
jobs,
196+
num_cpus,
197+
profile,
198+
rustc_version,
199+
rustc_version_verbose: _,
200+
target_dir: _,
201+
workspace_root: _,
202+
} => {
203+
ctx.host = host;
204+
ctx.jobs = jobs;
205+
ctx.num_cpus = num_cpus;
206+
ctx.profile = profile;
207+
ctx.rustc_version = rustc_version;
208+
}
209+
LogMessage::UnitStarted {
210+
package_id,
211+
target,
212+
mode,
213+
index,
214+
elapsed,
215+
} => {
216+
let version = package_id
217+
.version()
218+
.map(|v| v.to_string())
219+
.unwrap_or_else(|| "N/A".into());
220+
221+
// This is pretty similar to how the current `core::compiler::timings`
222+
// renders `core::manifest::Target`. However, our target is
223+
// a simplified type so we cannot reuse the same logic here.
224+
let mut target_str = if target.kind == "lib" && mode == CompileMode::Build {
225+
// Special case for brevity, since most dependencies hit this path.
226+
"".to_string()
227+
} else if target.kind == "build-script" {
228+
" build-script".to_string()
229+
} else {
230+
format!(r#" {} "{}""#, target.name, target.kind)
231+
};
232+
233+
match mode {
234+
CompileMode::Test => target_str.push_str(" (test)"),
235+
CompileMode::Build => {}
236+
CompileMode::Check { test: true } => target_str.push_str(" (check-test)"),
237+
CompileMode::Check { test: false } => target_str.push_str(" (check)"),
238+
CompileMode::Doc { .. } => target_str.push_str(" (doc)"),
239+
CompileMode::Doctest => target_str.push_str(" (doc test)"),
240+
CompileMode::Docscrape => target_str.push_str(" (doc scrape)"),
241+
CompileMode::RunCustomBuild => target_str.push_str(" (run)"),
242+
}
243+
244+
let mode_str = if mode.is_run_custom_build() {
245+
"run-custom-build"
246+
} else {
247+
"todo"
248+
};
249+
250+
let data = UnitData {
251+
i: index,
252+
name: package_id.name().to_string(),
253+
version,
254+
mode: mode_str.to_owned(),
255+
target: target_str,
256+
features: Vec::new(),
257+
start: elapsed,
258+
duration: 0.0,
259+
unblocked_units: Vec::new(),
260+
unblocked_rmeta_units: Vec::new(),
261+
sections: None,
262+
};
263+
264+
units.insert(
265+
index,
266+
UnitEntry {
267+
data,
268+
sections: IndexMap::new(),
269+
rmeta_time: None,
270+
},
271+
);
272+
}
273+
LogMessage::UnitRmetaFinished {
274+
index,
275+
elapsed,
276+
unblocked,
277+
} => match units.entry(index) {
278+
Entry::Occupied(mut e) => {
279+
let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
280+
e.get_mut().data.unblocked_rmeta_units = unblocked;
281+
e.get_mut().data.duration = elapsed;
282+
e.get_mut().rmeta_time = Some(elapsed);
283+
}
284+
Entry::Vacant(_) => {
285+
tracing::warn!(
286+
"section `frontend` ended, but unit {index} has no start recorded"
287+
)
288+
}
289+
},
290+
LogMessage::UnitSectionStarted {
291+
index,
292+
elapsed,
293+
section,
294+
} => match units.entry(index) {
295+
Entry::Occupied(mut e) => {
296+
let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
297+
if e.get_mut()
298+
.sections
299+
.insert(
300+
section.clone(),
301+
CompilationSection {
302+
start: elapsed,
303+
end: None,
304+
},
305+
)
306+
.is_some()
307+
{
308+
tracing::warn!(
309+
"section `{section}` for unit {index} started more than once",
310+
);
311+
}
312+
}
313+
Entry::Vacant(_) => {
314+
tracing::warn!(
315+
"section `{section}` started, but unit {index} has no start recorded"
316+
)
317+
}
318+
},
319+
LogMessage::UnitSectionFinished {
320+
index,
321+
elapsed,
322+
section,
323+
} => match units.entry(index) {
324+
Entry::Occupied(mut e) => {
325+
let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
326+
if let Some(section) = e.get_mut().sections.get_mut(&section) {
327+
section.end = Some(elapsed);
328+
} else {
329+
tracing::warn!(
330+
"section `{section}` for unit {index} ended, but section `{section}` has no start recorded"
331+
);
332+
}
333+
}
334+
Entry::Vacant(_) => {
335+
tracing::warn!(
336+
"section `{section}` ended, but unit {index} has no start recorded"
337+
)
338+
}
339+
},
340+
LogMessage::UnitFinished {
341+
index,
342+
elapsed,
343+
unblocked,
344+
} => match units.entry(index) {
345+
Entry::Occupied(mut e) => {
346+
let elapsed = f64::max(elapsed - e.get().data.start, 0.0);
347+
e.get_mut().data.duration = elapsed;
348+
e.get_mut().data.unblocked_units = unblocked;
349+
}
350+
Entry::Vacant(_) => {
351+
tracing::warn!("unit {index} ended, but it has no start recorded");
352+
}
353+
},
354+
_ => {} // skip non-timing logs
355+
}
356+
}
357+
358+
let unit_data: Vec<_> = units
359+
.into_values()
360+
.map(
361+
|UnitEntry {
362+
mut data,
363+
sections,
364+
rmeta_time,
365+
}| {
366+
// Post-processing for compilation sections we've collected so far.
367+
data.sections = aggregate_sections(sections, data.duration, rmeta_time);
368+
data.start = round_to_centisecond(data.start);
369+
data.duration = round_to_centisecond(data.duration);
370+
data
371+
},
372+
)
373+
.sorted_unstable_by(|a, b| a.start.partial_cmp(&b.start).unwrap())
374+
.collect();
375+
376+
if unit_data.is_empty() {
377+
anyhow::bail!("no timing data found in log");
378+
}
379+
380+
ctx.unit_data = unit_data;
381+
ctx.concurrency = compute_concurrency(&ctx.unit_data);
382+
383+
Ok(ctx)
384+
}

0 commit comments

Comments
 (0)