vhaudiquet/pkh
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

deb: record per-phase build timings, shown by pkh deb profile

Browse Source 
Time every Phase the build flow announces through enter_phase — the
chroot bootstrap (tarball download, extraction, finalization), the
apt phases, patch application, the build and binary steps and the
artifact retrieval — and land the ordered profile in the record's
manifest of every run, failed builds included: their profile ends
at the phase the error propagated out of.

Timing rides the enter_phase choke point instead of new measurement
sites, so a phase added later profiles itself. The manifest field
is additive (serde default, skipped when absent), so older manifests
keep loading without a schema bump. The coarse timings stay the
source of the deb list columns: they measure the apt transactions
themselves, where the profile measures whole phases.

pkh deb profile renders a record's profile through the same
read-only record discovery as pkh deb log — the newest record of
the tree, or an id prefix as shown by pkh deb list — so
record_for_log becomes the neutral find_record. Phase keys are
storage names, distinct from the display labels; Phase::from_key
turns them back and a test keeps both in sync.
This commit is contained in:
vhaudiquet
2026-10-02 14:17:15 +02:00
parent 7055d69152
commit 2ab2ff91e9
8 changed files with 552 additions and 38 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/deb/session.rs
+266 -9
View File
@@ -171,6 +171,43 @@ impl BuildTimings {
}
}
/// One executed phase of a build profile: the stable machine name of a
/// [`crate::deb::Phase`] ([`crate::deb::Phase::key`]) and the
/// wall-clock milliseconds it ran.
#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
pub struct PhaseTiming {
/// Stable machine name of the phase.
pub phase: String,
/// Wall-clock milliseconds the phase ran.
pub millis: u64,
}
/// Per-phase wall-clock profile of one build, recorded in the record's
/// manifest and shown by `pkh deb profile`: one entry per executed
/// phase, in execution order. A phase the flow skipped (the chroot
/// tarball was already cached, the device nodes were ready) has no
/// entry; a failed build's profile ends at the phase the error
/// propagated out of.
#[derive(Debug, Clone, Default, PartialEq, Eq, Serialize, Deserialize)]
pub struct BuildProfile {
/// Executed phases with their durations, in execution order.
pub phases: Vec<PhaseTiming>,
}
impl BuildProfile {
/// Whether nothing was recorded: the build ended before any phase
/// produced a measurement, and the record must not claim an empty
/// profile.
pub fn is_empty(&self) -> bool {
self.phases.is_empty()
}
/// Total milliseconds across the recorded phases.
pub fn total_millis(&self) -> u64 {
self.phases.iter().map(|p| p.millis).sum()
}
}
/// The record manifest: identity, lineage, outcome and tree state.
#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
pub struct SessionManifest {
@@ -223,6 +260,11 @@ pub struct SessionManifest {
/// record predates the field).
#[serde(default, skip_serializing_if = "Option::is_none")]
pub timings: Option<BuildTimings>,
/// Per-phase wall-clock profile of this record's build (`None`: not
/// recorded — the record predates the field, or the build ended
/// before any phase produced a measurement).
#[serde(default, skip_serializing_if = "Option::is_none")]
pub profile: Option<BuildProfile>,
}
/// State shared through the [`Session`] handle: the manifest plus the
@@ -374,6 +416,14 @@ impl Session {
});
}
/// Record the per-phase wall-clock profile of this record's build
/// and persist it.
pub fn set_profile(&self, profile: BuildProfile) {
self.with_manifest(|manifest| {
manifest.profile = Some(profile);
});
}
/// Run `f` over the manifest and persist the result; failures are
/// logged and never abort the build (the journal is a cache).
fn with_manifest(&self, f: impl FnOnce(&mut SessionManifest)) {
@@ -942,6 +992,7 @@ fn fresh_manifest(
kept_upper: false,
build_resume: false,
timings: None,
profile: None,
}
}
@@ -1102,6 +1153,7 @@ pub(crate) fn fork_record_in(
kept_upper: false,
build_resume: false,
timings: None,
profile: None,
})?;
if carry_upper {
@@ -1418,6 +1470,115 @@ fn format_duration(secs: u64) -> String {
}
}
/// Human-readable duration of a profiled phase: the phases can be
/// shorter than a second (artifact retrieval), so sub-second entries
/// render as milliseconds and the rest through [`format_duration`].
fn format_phase_millis(millis: u64) -> String {
if millis < 1000 {
format!("{millis}ms")
} else {
format_duration(millis / 1000)
}
}
/// Render `pkh deb profile` for `record`: its identity in the header,
/// one row per recorded phase with its duration and its share of the
/// total, and — for a failed build — the phase the error surfaced
/// from. A record without a profile (predating the field, or a build
/// interrupted before any phase completed) says so.
pub fn render_record_profile(record: &Session) -> String {
let manifest = record.manifest();
let cross = if manifest.identity.cross { "*" } else { "" };
let mut out = format!(
"Profile of build {} — {} {}, {}/{}{}, {}",
manifest.id,
manifest.identity.package,
manifest.tree_version,
manifest.identity.series,
manifest.identity.arch,
cross,
manifest.last_outcome
);
if let Some(base) = &manifest.base {
out.push_str(&format!(" (fork of {base})"));
}
out.push_str(":\n");
let Some(profile) = &manifest.profile else {
out.push_str("No phase profile recorded for this build.\n");
return out;
};
if profile.is_empty() {
out.push_str("No phase profile recorded for this build.\n");
return out;
}
let total = profile.total_millis();
let rows: Vec<Vec<String>> = profile
.phases
.iter()
.map(|entry| {
let label = crate::deb::Phase::from_key(&entry.phase)
.map(|phase| phase.label().to_string())
.unwrap_or_else(|| entry.phase.clone());
let share = entry
.millis
.checked_mul(100)
.and_then(|scaled| scaled.checked_div(total.max(1)))
.map(|share| format!("{share}%"))
.unwrap_or_else(|| "-".to_string());
vec![label, format_phase_millis(entry.millis), share]
})
.collect();
let headers = ["PHASE", "TIME", "SHARE"];
let widths: Vec<usize> = headers
.iter()
.enumerate()
.map(|(i, header)| {
rows.iter()
.map(|row| row[i].chars().count())
.max()
.unwrap_or(0)
.max(header.len())
})
.collect();
let line = |cells: &[String]| {
cells
.iter()
.enumerate()
.map(|(i, cell)| {
if i == 0 {
format!("{cell:<width$}", width = widths[i])
} else {
format!("{cell:>width$}", width = widths[i])
}
})
.collect::<Vec<_>>()
.join(" ")
};
out.push_str(&line(
&headers.iter().map(|h| h.to_string()).collect::<Vec<_>>(),
));
out.push('\n');
for row in &rows {
out.push_str(&line(row));
out.push('\n');
}
out.push_str(&line(&[
"Total".to_string(),
format_phase_millis(total),
String::new(),
]));
out.push('\n');
if manifest.last_outcome == OUTCOME_FAILED
&& let Some(last) = profile.phases.last()
&& let Some(phase) = crate::deb::Phase::from_key(&last.phase)
{
out.push_str(&format!("The build failed during \"{}\".\n", phase.label()));
}
out
}
/// Render the `pkh deb list` table.
pub fn render_session_list(tree: &Path, rows: &[SessionListRow]) -> String {
let mut out = String::new();
@@ -1490,11 +1651,12 @@ pub fn render_session_list(tree: &Path, rows: &[SessionListRow]) -> String {
// Build log (`pkh deb log`)
// ---------------------------------------------------------------------------
/// Resolve the record whose log `pkh deb log` prints: with no id, the
/// newest record of `tree`; with an id (or unique prefix), that exact
/// record of `tree`. `root` is the sessions root (`sessions_root()` in
/// production, a fixture root in tests).
pub fn record_for_log(
/// Resolve the record a read-only deb query targets (`pkh deb log`,
/// `pkh deb profile`): with no id, the newest record of `tree`; with
/// an id (or unique prefix), that exact record of `tree`. `root` is
/// the sessions root (`sessions_root()` in production, a fixture root
/// in tests).
pub fn find_record(
root: &Path,
tree: &Path,
id: Option<&str>,
@@ -2364,6 +2526,18 @@ mod tests {
deps_secs: 41,
build_secs: 9020,
}),
profile: Some(BuildProfile {
phases: vec![
PhaseTiming {
phase: "preparing_chroot".to_string(),
millis: 38_200,
},
PhaseTiming {
phase: "building".to_string(),
millis: 125_000,
},
],
}),
};
let base = tempfile::tempdir().unwrap();
save_manifest(base.path(), &manifest).unwrap();
@@ -2378,11 +2552,13 @@ mod tests {
object.remove("tarball_sha256");
object.remove("kept_upper");
object.remove("timings");
object.remove("profile");
let older: SessionManifest = serde_json::from_value(value).unwrap();
assert_eq!(older.base, None);
assert_eq!(older.tarball_sha256, "");
assert!(!older.kept_upper);
assert_eq!(older.timings, None);
assert_eq!(older.profile, None);
// A foreign schema is not discoverable.
let mut foreign = manifest.clone();
@@ -2484,6 +2660,87 @@ mod tests {
assert_eq!(format_duration(277_200), "3d05h");
}
/// The per-phase profile round-trips through the manifest, and
/// `pkh deb profile` renders each recorded phase under its human
/// label with its share of the total, the total itself, and — for a
/// failed build — the phase the error surfaced from; a record
/// without a profile says so instead.
#[test]
fn profile_persists_and_renders() {
let (root, _tarball) = sessions_fixture();
let identity = test_identity();
let host_tree = root.path().join("tree");
let record = metadata_record(root.path(), &host_tree, &identity, "1.0", OUTCOME_FAILED);
assert_eq!(record.manifest().profile, None);
// No profile recorded: the renderer explains rather than fails.
assert!(
render_record_profile(&record).contains("No phase profile recorded"),
"{}",
render_record_profile(&record)
);
let profile = BuildProfile {
phases: vec![
// An unknown key (an older pkh's phase since renamed)
// renders as its raw key instead of disappearing.
PhaseTiming {
phase: "retired_phase".to_string(),
millis: 500,
},
PhaseTiming {
phase: "preparing_chroot".to_string(),
millis: 10_000,
},
PhaseTiming {
phase: "updating_package_lists".to_string(),
millis: 5_000,
},
PhaseTiming {
phase: "installing_build_deps".to_string(),
millis: 75_000,
},
PhaseTiming {
phase: "building".to_string(),
millis: 10_000,
},
],
};
record.set_profile(profile.clone());
assert_eq!(record.manifest().profile, Some(profile.clone()));
let reloaded = open_from_dir(record.root().to_path_buf()).unwrap();
assert_eq!(reloaded.manifest().profile, Some(profile));
let rendered = render_record_profile(&record);
assert!(rendered.contains("Profile of build"), "{rendered}");
assert!(rendered.contains("1.0"), "{rendered}");
assert!(rendered.contains("failed"), "{rendered}");
// Labels come from the known keys; the unknown key stays raw.
assert!(rendered.contains("Preparing chroot"), "{rendered}");
assert!(rendered.contains("Updating package lists"), "{rendered}");
assert!(
rendered.contains("Installing build dependencies"),
"{rendered}"
);
assert!(rendered.contains("Building package"), "{rendered}");
assert!(rendered.contains("retired_phase"), "{rendered}");
// Shares of the 100_500 ms total, and the total itself.
assert!(rendered.contains("9%"), "{rendered}");
assert!(rendered.contains("74%"), "{rendered}");
assert!(rendered.contains("500ms"), "{rendered}");
assert!(rendered.contains("1m40s"), "{rendered}");
// A failed build's profile names the phase it died in (the last
// recorded one).
assert!(
rendered.contains("failed during \"Building package\""),
"{rendered}"
);
assert_eq!(format_phase_millis(0), "0ms");
assert_eq!(format_phase_millis(740), "740ms");
assert_eq!(format_phase_millis(1000), "1s");
assert_eq!(format_phase_millis(100_500), "1m40s");
}
// -------------------------------------------------------------------
// Record layout, fork gate, retention, sweep and logs
// -------------------------------------------------------------------
@@ -2915,20 +3172,20 @@ mod tests {
drop(newest);
// No id: the newest record of the tree.
let record = record_for_log(root.path(), &host_tree, None).unwrap();
let record = find_record(root.path(), &host_tree, None).unwrap();
let mut out = Vec::new();
print_record_log(&record, false, &mut out).unwrap();
assert_eq!(String::from_utf8(out).unwrap(), "newest build log\n");
// The exact id of the older record; the record is terminal, so
// --follow just prints.
let record = record_for_log(root.path(), &host_tree, Some(&first_id)).unwrap();
let record = find_record(root.path(), &host_tree, Some(&first_id)).unwrap();
let mut out = Vec::new();
print_record_log(&record, true, &mut out).unwrap();
assert_eq!(String::from_utf8(out).unwrap(), "first build log\n");
// A wrong id is an error.
assert!(record_for_log(root.path(), &host_tree, Some("nonesuch")).is_err());
assert!(find_record(root.path(), &host_tree, Some("nonesuch")).is_err());
}
/// A record whose build captured no line yet streams an empty log.
@@ -2940,7 +3197,7 @@ mod tests {
let record = new_record_in(root.path(), &host_tree, &identity, "1.0").unwrap();
record.set_outcome(OUTCOME_SUCCESS);
drop(record);
let record = record_for_log(root.path(), &host_tree, None).unwrap();
let record = find_record(root.path(), &host_tree, None).unwrap();
let mut out = Vec::new();
print_record_log(&record, true, &mut out).unwrap();
assert_eq!(out.len(), 0);