deb,cli,test,docs: record and show dep-install and build durations

Every binary build measures its dependency installation (apt-get
update, the essential and injected packages, each build-dependency
pass) and its package build (debian/rules build plus binary) into a
timings accumulator; the record manifest stores both as an optional
`timings` field when the run ends, whatever the outcome — a failed
build keeps its partial durations, and a run that died before any
timed command records nothing.

`pkh deb list` shows the two durations as DEPS and BUILD columns,
formatted like the age ("45s", "2m41s", "1h02m"); records predating
the field show dashes. The field is serde-optional, so the manifest
schema stays at 1 and existing records remain discoverable and
forkable.

README.md

@@ -170,7 +170,8 @@ pkh deb --incremental <id>
                         # 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] [<id>] # print a record's build log; -f follows a
                         # live build
 pkh deb --no-ccache     # build without the shared compile cache

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<Vec<PathBuf>, Box<dyn Error>> {
     let sink: Option<Arc<dyn LineSink>> = 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<Context>,
     view: &dyn BuildView,
     sink: &Option<Arc<dyn LineSink>>,
+    timings: &mut session::BuildTimings,
 ) -> Result<(), Box<dyn Error>> {
     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<Context>,
     view: &dyn BuildView,
     sink: &Option<Arc<dyn LineSink>>,
+    timings: &mut session::BuildTimings,
 ) -> Result<(), Box<dyn Error>> {
     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());
         }

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
 }

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/<slug>/<record-id>/`.
 //!
 //! The chroot itself is per-run scratch: every build (plain and
@@ -18,7 +19,8 @@
 //! ```text
 //! /var/tmp/pkh/sessions/<slug>/
 //!   <record-id>/        # 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<String>,
 }
 
+/// 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<BuildTimings>,
 }
 
 /// 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<SessionListRow> {
         .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<SessionListRow> {
                 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<Vec<String>> = 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 [<id>]"),
             "{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
     // -------------------------------------------------------------------

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 <id>'.\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 <id>'.\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")

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(())
 }