From 1b4af3f4e536ebbb1f085b3bce3d31de311e738b Mon Sep 17 00:00:00 2001 From: Jason Barnett Date: Thu, 8 Jan 2026 16:40:35 -0700 Subject: [PATCH 1/2] feat(engine): log duration for completed workunits When a workunit completes, the log message now includes how long it took. For example: "Completed: Generate lockfile for foo (12.34s)" For operations taking 60 seconds or more, the format shows minutes: "Completed: Build target (2m 30.0s)" Co-Authored-By: Claude Opus 4.5 --- src/rust/workunit_store/src/lib.rs | 21 ++++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) diff --git a/src/rust/workunit_store/src/lib.rs b/src/rust/workunit_store/src/lib.rs index 453be969eaf..21bf9c5741d 100644 --- a/src/rust/workunit_store/src/lib.rs +++ b/src/rust/workunit_store/src/lib.rs @@ -254,6 +254,25 @@ impl Workunit { (WorkunitState::Completed { .. }, _) => "Completed:", }; + // Format duration for completed workunits (not canceled ones) + let duration_str = if !canceled { + if let WorkunitState::Completed { time_span } = &self.state { + let duration = std::time::Duration::from(time_span.duration); + let total_secs = duration.as_secs_f64(); + if total_secs >= 60.0 { + let mins = (total_secs / 60.0).floor() as u64; + let secs = total_secs % 60.0; + format!(" ({mins}m {secs:.1}s)") + } else { + format!(" ({total_secs:.2}s)") + } + } else { + String::new() + } + } else { + String::new() + }; + let identifier = if let Some(ref s) = metadata.desc { s.as_str() } else { @@ -281,7 +300,7 @@ impl Workunit { "".to_string() }; - log!(self.level, "{state} {effective_identifier}{message}"); + log!(self.level, "{state} {effective_identifier}{duration_str}{message}"); } } From c58d9435e5ec28093d5e2530c375c95c8dcc5770 Mon Sep 17 00:00:00 2001 From: Jason Barnett Date: Thu, 8 Jan 2026 17:21:25 -0700 Subject: [PATCH 2/2] test(engine): add tests for workunit duration formatting Extract format_workunit_duration into a standalone function and add comprehensive unit tests covering: - Sub-second durations - Durations under 60 seconds - Boundary case at exactly 60 seconds - Durations with minutes and seconds - Zero duration Co-Authored-By: Claude Opus 4.5 --- src/rust/workunit_store/src/lib.rs | 45 ++++++++++++++---------- src/rust/workunit_store/src/tests.rs | 51 +++++++++++++++++++++++++++- 2 files changed, 78 insertions(+), 18 deletions(-) diff --git a/src/rust/workunit_store/src/lib.rs b/src/rust/workunit_store/src/lib.rs index 21bf9c5741d..9863acc2816 100644 --- a/src/rust/workunit_store/src/lib.rs +++ b/src/rust/workunit_store/src/lib.rs @@ -28,6 +28,21 @@ use tokio::task_local; mod metrics; +/// Formats a duration for display in workunit completion logs. +/// +/// For durations under 60 seconds, returns " (X.XXs)". +/// For durations of 60 seconds or more, returns " (Xm Y.Ys)". +pub(crate) fn format_workunit_duration(duration: Duration) -> String { + let total_secs = duration.as_secs_f64(); + if total_secs >= 60.0 { + let mins = (total_secs / 60.0).floor() as u64; + let secs = total_secs % 60.0; + format!(" ({mins}m {secs:.1}s)") + } else { + format!(" ({total_secs:.2}s)") + } +} + /// /// A unique id for a single run or `--loop` iteration of Pants within a single Scheduler. /// @@ -254,23 +269,15 @@ impl Workunit { (WorkunitState::Completed { .. }, _) => "Completed:", }; - // Format duration for completed workunits (not canceled ones) - let duration_str = if !canceled { - if let WorkunitState::Completed { time_span } = &self.state { - let duration = std::time::Duration::from(time_span.duration); - let total_secs = duration.as_secs_f64(); - if total_secs >= 60.0 { - let mins = (total_secs / 60.0).floor() as u64; - let secs = total_secs % 60.0; - format!(" ({mins}m {secs:.1}s)") - } else { - format!(" ({total_secs:.2}s)") - } - } else { - String::new() + let duration_str: Option = match &self.state { + WorkunitState::Completed { time_span } => { + Some(format_workunit_duration(std::time::Duration::from(time_span.duration))) } - } else { - String::new() + WorkunitState::Started { start_time, .. } if canceled => { + let elapsed = start_time.elapsed().unwrap_or_default(); + Some(format_workunit_duration(elapsed)) + } + _ => None, }; let identifier = if let Some(ref s) = metadata.desc { @@ -300,7 +307,11 @@ impl Workunit { "".to_string() }; - log!(self.level, "{state} {effective_identifier}{duration_str}{message}"); + log!( + self.level, + "{state} {effective_identifier}{}{message}", + duration_str.as_deref().unwrap_or("") + ); } } diff --git a/src/rust/workunit_store/src/tests.rs b/src/rust/workunit_store/src/tests.rs index 8e7a57b5975..c933cbc2d6d 100644 --- a/src/rust/workunit_store/src/tests.rs +++ b/src/rust/workunit_store/src/tests.rs @@ -6,7 +6,7 @@ use std::time::Duration; use internment::Intern; -use crate::{Level, ParentIds, SpanId, WorkunitMetadata, WorkunitState, WorkunitStore}; +use crate::{Level, ParentIds, SpanId, WorkunitMetadata, WorkunitState, WorkunitStore, format_workunit_duration}; #[test] fn heavy_hitters_basic() { @@ -224,3 +224,52 @@ fn wu_level(span_id: u64, parent_id: Option, level: Level) -> AnonymousWork metadata.desc = Some(format!("{span_id}")); (level, SpanId(span_id), parent_id.map(SpanId), metadata) } + +#[test] +fn format_duration_sub_second() { + let duration = Duration::from_millis(123); + assert_eq!(format_workunit_duration(duration), " (0.12s)"); +} + +#[test] +fn format_duration_seconds() { + let duration = Duration::from_secs_f64(12.345); + assert_eq!(format_workunit_duration(duration), " (12.35s)"); +} + +#[test] +fn format_duration_just_under_minute() { + let duration = Duration::from_secs_f64(59.99); + assert_eq!(format_workunit_duration(duration), " (59.99s)"); +} + +#[test] +fn format_duration_exactly_one_minute() { + let duration = Duration::from_secs(60); + assert_eq!(format_workunit_duration(duration), " (1m 0.0s)"); +} + +#[test] +fn format_duration_minutes_and_seconds() { + let duration = Duration::from_secs_f64(90.5); + assert_eq!(format_workunit_duration(duration), " (1m 30.5s)"); +} + +#[test] +fn format_duration_multiple_minutes() { + let duration = Duration::from_secs_f64(185.7); + assert_eq!(format_workunit_duration(duration), " (3m 5.7s)"); +} + +#[test] +fn format_duration_zero() { + let duration = Duration::from_secs(0); + assert_eq!(format_workunit_duration(duration), " (0.00s)"); +} + +#[test] +fn format_duration_over_one_hour() { + // 1 hour 30 minutes 45.5 seconds = 5445.5 seconds + let duration = Duration::from_secs_f64(5445.5); + assert_eq!(format_workunit_duration(duration), " (90m 45.5s)"); +}