diff --git a/README.md b/README.md index f785d56..d6ddea5 100644 --- a/README.md +++ b/README.md @@ -170,7 +170,8 @@ pkh deb --incremental # fork that exact record (see `pkh deb list`); # a failed record is fine if its staged tree is pkh deb list # the records of this tree: id, outcome, - # version, fork lineage, staged-tree state, age + # version, fork lineage, staged-tree state, + # dep-install and build times, age pkh deb log [-f] [] # print a record's build log; -f follows a # live build pkh deb --no-ccache # build without the shared compile cache diff --git a/src/deb/local.rs b/src/deb/local.rs index 724cf7d..c28dec3 100644 --- a/src/deb/local.rs +++ b/src/deb/local.rs @@ -15,6 +15,7 @@ use crate::deb::cross; use crate::deb::session; use crate::debian::control::ControlInfo; use crate::debian::deps::{Deps, Facts, ParseOpts, PkgRelation}; +use std::time::Instant; /// Attach the capture sink to a command when the live UI is active fn cap<'a>( @@ -106,6 +107,9 @@ pub async fn build( session: Option<&session::Session>, build_resume: bool, ccache: bool, + // Accumulator of the measured dependency-installation and build + // durations; the caller records it on the build record. + timings: &mut session::BuildTimings, ) -> Result, Box> { let sink: Option> = view.sink(); @@ -261,6 +265,7 @@ pub async fn build( // Update package lists log::debug!("Updating package lists for local build..."); enter_phase(view, Phase::UpdatingPackageLists); + let started = Instant::now(); let status = cap( ctx.command("apt-get").envs(env.clone()).arg("update"), &sink, @@ -274,6 +279,7 @@ pub async fn build( e ) })?; + timings.add_deps(started.elapsed()); if !status.success() { return Err("apt-get update failed inside the build context. \ If this is a local build, try executing with sudo, \ @@ -305,7 +311,9 @@ pub async fn build( cmd.arg(format!("libc6-dev:{arch}")); } enter_phase(view, Phase::InstallingEssentials); + let started = Instant::now(); let status = cap(&mut cmd, &sink).status()?; + timings.add_deps(started.elapsed()); if !status.success() { return Err("Could not install essential packages for the build".into()); } @@ -348,7 +356,7 @@ pub async fn build( // Install injected packages if specified if !inject_packages.is_empty() { - install_injected_packages(inject_packages, &env, ctx.clone(), view, &sink)?; + install_injected_packages(inject_packages, &env, ctx.clone(), view, &sink, timings)?; } // Resolve and install the Build-* dependencies with dpkg's cross @@ -367,6 +375,7 @@ pub async fn build( ctx.clone(), view, &sink, + timings, )?; // (The build-dependency phase reruns in every fresh chroot: nothing // to journal.) @@ -400,6 +409,7 @@ pub async fn build( // Run the build step log::debug!("Building (debian/rules build) package..."); enter_phase(view, Phase::Building); + let started = Instant::now(); let status = cap( ctx.command("debian/rules") .current_dir(package_dir_str) @@ -408,6 +418,7 @@ pub async fn build( &sink, ) .status()?; + timings.add_build(started.elapsed()); if !status.success() { return Err("Error while building the package".into()); } @@ -428,6 +439,7 @@ pub async fn build( // Run the 'binary' step to produce deb enter_phase(view, Phase::ProducingBinaries); + let started = Instant::now(); let status = cap( ctx.command("fakeroot") .current_dir(package_dir_str) @@ -437,6 +449,7 @@ pub async fn build( &sink, ) .status()?; + timings.add_build(started.elapsed()); if !status.success() { return Err( "Error while building the binary artifacts (.deb) from the built package".into(), @@ -730,6 +743,7 @@ fn install_build_dependencies( ctx: Arc, view: &dyn BuildView, sink: &Option>, + timings: &mut session::BuildTimings, ) -> Result<(), Box> { enter_phase(view, Phase::InstallingBuildDeps); @@ -878,7 +892,9 @@ fn install_build_dependencies( for spec in &specs { cmd.arg(spec); } + let started = Instant::now(); let status = cap(&mut cmd, sink).status()?; + timings.add_deps(started.elapsed()); if !status.success() { view.suspend(); // Diagnosing a dependency failure the user interrupted themselves @@ -1210,6 +1226,7 @@ pub(crate) fn install_injected_packages( ctx: Arc, view: &dyn BuildView, sink: &Option>, + timings: &mut session::BuildTimings, ) -> Result<(), Box> { log::info!("Installing injected packages: {:?}", packages); @@ -1252,7 +1269,9 @@ pub(crate) fn install_injected_packages( if !package_names.is_empty() { cmd.args(&package_names); } + let started = Instant::now(); let status = cap(&mut cmd, sink).status()?; + timings.add_deps(started.elapsed()); if !status.success() { return Err(format!("Could not install injected packages: {:?}", deb_files).into()); } diff --git a/src/deb/mod.rs b/src/deb/mod.rs index a4f3e33..30ea365 100644 --- a/src/deb/mod.rs +++ b/src/deb/mod.rs @@ -458,6 +458,10 @@ async fn build_binary_package_impl( None => base_ctx.clone(), }; + // The measured durations of the build's work phases, recorded on the + // record when the run ends — success or failure alike. + let mut timings = session::BuildTimings::default(); + let result = async { // Prepare build directory: the stable /tmp/pkh-build for session // builds (see EphemeralContextGuard::build_root — the overlay @@ -571,6 +575,7 @@ async fn build_binary_package_impl( session.as_ref(), build_resume, ccache, + &mut timings, ) .await? } @@ -617,6 +622,14 @@ async fn build_binary_package_impl( { s.set_outcome(session::OUTCOME_FAILED); } + // The measured durations land in the record whatever the outcome: a + // failed build's partial timings are data too. Nothing measured (the + // run ended before any timed command) records nothing. + if let Some(s) = &session + && !timings.is_empty() + { + s.set_timings(timings); + } result } diff --git a/src/deb/session.rs b/src/deb/session.rs index 4e9e9e0..da98bf6 100644 --- a/src/deb/session.rs +++ b/src/deb/session.rs @@ -2,8 +2,9 @@ //! //! A record is one build's metadata: identity, lineage, outcome, the //! SHA-256 of the chroot tarball its environment was extracted from, a -//! tree phase journal, the full build log, and — for `--incremental` -//! runs — the staged tree's overlay upperdir. Records live under +//! tree phase journal, the measured build durations, the full build +//! log, and — for `--incremental` runs — the staged tree's overlay +//! upperdir. Records live under //! `/var/tmp/pkh/sessions///`. //! //! The chroot itself is per-run scratch: every build (plain and @@ -18,7 +19,8 @@ //! ```text //! /var/tmp/pkh/sessions// //! / # one record per build -//! manifest.json # identity, lineage, outcome, tarball sha, journal +//! manifest.json # identity, lineage, outcome, tarball sha, +//! # journal, build durations //! log/build.log # full tee of the build output (always) //! tree-upper/ # the staged tree's overlay upperdir //! # (--incremental runs only, post-run) @@ -137,6 +139,38 @@ pub struct PhaseStamp { pub stamp: Option, } +/// Wall-clock durations of one build's work, as recorded in a record's +/// manifest: the dependency installation (every apt phase before the +/// build — package list update, essential and injected packages, +/// build-dependencies) and the package build itself (`debian/rules +/// build` plus `binary`). The full build time is the sum of both. +#[derive(Debug, Clone, Copy, Default, PartialEq, Eq, Serialize, Deserialize)] +pub struct BuildTimings { + /// Seconds spent installing dependencies. + pub deps_secs: u64, + /// Seconds spent building the package. + pub build_secs: u64, +} + +impl BuildTimings { + /// Accumulate a measured duration into the dependency-installation + /// total. + pub fn add_deps(&mut self, elapsed: Duration) { + self.deps_secs += elapsed.as_secs(); + } + + /// Accumulate a measured duration into the package-build total. + pub fn add_build(&mut self, elapsed: Duration) { + self.build_secs += elapsed.as_secs(); + } + + /// Whether nothing was measured: the build ended before any timed + /// command ran, and the record must not claim durations of zero. + pub fn is_empty(&self) -> bool { + self.deps_secs == 0 && self.build_secs == 0 + } +} + /// The record manifest: identity, lineage, outcome and tree state. #[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] pub struct SessionManifest { @@ -184,6 +218,11 @@ pub struct SessionManifest { /// Whether this record's build staged the tree over a carried /// overlay upperdir (build-level resume was active). pub build_resume: bool, + /// Wall-clock durations of this record's build (`None`: not + /// recorded — the build ended before any timed command ran, or the + /// record predates the field). + #[serde(default, skip_serializing_if = "Option::is_none")] + pub timings: Option, } /// State shared through the [`Session`] handle: the manifest plus the @@ -327,6 +366,14 @@ impl Session { }); } + /// Record the measured build durations (dependency installation, + /// package build) and persist them. + pub fn set_timings(&self, timings: BuildTimings) { + self.with_manifest(|manifest| { + manifest.timings = Some(timings); + }); + } + /// 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)) { @@ -894,6 +941,7 @@ fn fresh_manifest( tree_version: tree_version.to_string(), kept_upper: false, build_resume: false, + timings: None, } } @@ -1053,6 +1101,7 @@ pub(crate) fn fork_record_in( tree_version: version.to_string(), kept_upper: false, build_resume: false, + timings: None, })?; if carry_upper { @@ -1294,6 +1343,12 @@ pub struct SessionListRow { pub upper: bool, /// Outcome of this record's build. pub outcome: String, + /// Duration of the record's dependency installation, formatted + /// ("-" when the record carries none). + pub deps: String, + /// Duration of the record's package build, formatted ("-" when the + /// record carries none). + pub build: String, /// Human-readable age of this record's build. pub age: String, } @@ -1305,6 +1360,13 @@ pub fn list_for_tree(tree: &Path) -> Vec { .map(|session| { let manifest = session.manifest(); let cross = if manifest.identity.cross { "*" } else { "" }; + let (deps, build) = match manifest.timings { + Some(timings) => ( + format_duration(timings.deps_secs), + format_duration(timings.build_secs), + ), + None => ("-".to_string(), "-".to_string()), + }; SessionListRow { id: manifest.id, package: manifest.identity.package, @@ -1316,6 +1378,8 @@ pub fn list_for_tree(tree: &Path) -> Vec { base: manifest.base, upper: session.has_upper(), outcome: manifest.last_outcome, + deps, + build, age: age_of(&manifest.last_used), } }) @@ -1343,6 +1407,17 @@ fn age_of(rfc3339: &str) -> String { } } +/// Human-readable duration of a build phase ("45s", "2m41s", "1h02m", +/// "3d04h"): unlike [`age_of`] the minutes matter at every scale. +fn format_duration(secs: u64) -> String { + match secs { + 0..=59 => format!("{secs}s"), + 60..=3599 => format!("{}m{:02}s", secs / 60, secs % 60), + 3600..=86399 => format!("{}h{:02}m", secs / 3600, (secs % 3600) / 60), + _ => format!("{}d{:02}h", secs / 86400, (secs % 86400) / 3600), + } +} + /// Render the `pkh deb list` table. pub fn render_session_list(tree: &Path, rows: &[SessionListRow]) -> String { let mut out = String::new(); @@ -1355,7 +1430,7 @@ pub fn render_session_list(tree: &Path, rows: &[SessionListRow]) -> String { } out.push_str(&format!("Records for {}:\n", tree.display())); let headers = [ - "ID", "PACKAGE", "VERSION", "TARGET", "BASE", "UPPER", "OUTCOME", "AGE", + "ID", "PACKAGE", "VERSION", "TARGET", "BASE", "UPPER", "OUTCOME", "DEPS", "BUILD", "AGE", ]; let table: Vec> = rows .iter() @@ -1368,6 +1443,8 @@ pub fn render_session_list(tree: &Path, rows: &[SessionListRow]) -> String { row.base.clone().unwrap_or_else(|| "-".to_string()), if row.upper { "yes" } else { "-" }.to_string(), row.outcome.clone(), + row.deps.clone(), + row.build.clone(), row.age.clone(), ] }) @@ -2283,6 +2360,10 @@ mod tests { tree_version: "7.3.0-5.6~local2".to_string(), kept_upper: true, build_resume: true, + timings: Some(BuildTimings { + deps_secs: 41, + build_secs: 9020, + }), }; let base = tempfile::tempdir().unwrap(); save_manifest(base.path(), &manifest).unwrap(); @@ -2296,10 +2377,12 @@ mod tests { object.remove("base"); object.remove("tarball_sha256"); object.remove("kept_upper"); + object.remove("timings"); 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); // A foreign schema is not discoverable. let mut foreign = manifest.clone(); @@ -2308,8 +2391,9 @@ mod tests { assert!(open_from_dir(base.path().to_path_buf()).is_none()); } - /// `pkh deb list` renders a table with the fork lineage and the - /// upper-kept state; the empty case explains itself. + /// `pkh deb list` renders a table with the fork lineage, the + /// upper-kept state and the recorded build durations; the empty + /// case explains itself. #[test] fn session_list_rendering() { let rows = vec![ @@ -2321,6 +2405,8 @@ mod tests { base: Some("20260926T140000".to_string()), upper: true, outcome: OUTCOME_FAILED.to_string(), + deps: "2m05s".to_string(), + build: "2h30m".to_string(), age: "2h".to_string(), }, SessionListRow { @@ -2331,6 +2417,8 @@ mod tests { base: None, upper: false, outcome: OUTCOME_SUCCESS.to_string(), + deps: "-".to_string(), + build: "-".to_string(), age: "1d".to_string(), }, ]; @@ -2345,6 +2433,11 @@ mod tests { // record's dash. assert!(rendered.contains("20260926T140000"), "{rendered}"); assert!(rendered.contains("UPPER"), "{rendered}"); + // The timing columns: both durations of the timed record, the + // dashes of the record without any. + assert!(rendered.contains("DEPS"), "{rendered}"); + assert!(rendered.contains("2m05s"), "{rendered}"); + assert!(rendered.contains("2h30m"), "{rendered}"); assert!( rendered.contains("Fork with: pkh deb --incremental []"), "{rendered}" @@ -2354,6 +2447,43 @@ mod tests { assert!(empty.contains("No build records recorded"), "{empty}"); } + /// The recorded durations round-trip through the manifest and the + /// list rows, and unmeasured builds record none: the accumulator + /// sums both totals, an empty one is not recorded, and + /// `pkh deb list` formats the seconds into stable units. + #[test] + fn timings_accumulate_render_and_persist() { + let mut timings = BuildTimings::default(); + assert!(timings.is_empty()); + timings.add_deps(Duration::from_millis(1500)); + timings.add_deps(Duration::from_secs(3)); + timings.add_build(Duration::from_secs(65)); + assert_eq!(timings.deps_secs, 4); + assert_eq!(timings.build_secs, 65); + assert!(!timings.is_empty()); + + let (root, _tarball) = sessions_fixture(); + let identity = test_identity(); + let host_tree = root.path().join("tree"); + let record = new_record_in(root.path(), &host_tree, &identity, "1.0").unwrap(); + assert_eq!(record.manifest().timings, None); + + record.set_timings(timings); + let stored = record + .manifest() + .timings + .expect("set_timings must record the durations"); + assert_eq!(stored, timings); + let reloaded = open_from_dir(record.root().to_path_buf()).unwrap(); + assert_eq!(reloaded.manifest().timings, Some(timings)); + + assert_eq!(format_duration(0), "0s"); + assert_eq!(format_duration(45), "45s"); + assert_eq!(format_duration(125), "2m05s"); + assert_eq!(format_duration(5400), "1h30m"); + assert_eq!(format_duration(277_200), "3d05h"); + } + // ------------------------------------------------------------------- // Record layout, fork gate, retention, sweep and logs // ------------------------------------------------------------------- diff --git a/src/main.rs b/src/main.rs index d554c2a..8fea431 100644 --- a/src/main.rs +++ b/src/main.rs @@ -383,7 +383,7 @@ fn main() { .subcommand( Command::new("list") .about("List the build records recorded from this tree") - .long_about("List the build records recorded from this tree (plain runs too, as metadata records), with their outcome, version, fork lineage, whether their staged tree is kept, and the id to pass to 'pkh deb --incremental '.\nRead-only: never builds or removes anything (at most five staged trees per target are kept, 'pkh prune' removes records older than a week)."), + .long_about("List the build records recorded from this tree (plain runs too, as metadata records), with their outcome, version, fork lineage, whether their staged tree is kept, how long the dependency installation and the package build took, and the id to pass to 'pkh deb --incremental '.\nRead-only: never builds or removes anything (at most five staged trees per target are kept, 'pkh prune' removes records older than a week)."), ) .subcommand( Command::new("log") diff --git a/src/test/mod.rs b/src/test/mod.rs index 5bda8c0..5d9e4d1 100644 --- a/src/test/mod.rs +++ b/src/test/mod.rs @@ -561,7 +561,15 @@ async fn configure_testbed( } if !opts.inject.is_empty() { - crate::deb::local::install_injected_packages(&opts.inject, env, ctx.clone(), view, &None)?; + // Testbed setup is not a timed build: the durations go nowhere. + crate::deb::local::install_injected_packages( + &opts.inject, + env, + ctx.clone(), + view, + &None, + &mut crate::deb::session::BuildTimings::default(), + )?; } Ok(()) }