feat(engine): log elapsed time for completed and canceled workunits

docs/notes/2.32.x.md

@@ -31,6 +31,8 @@ Fixed the sandboxer daemon inheriting the parent process's stdin/stdout file des
 
 Fixed "Scheduling:" workunits (process execution wrappers) being logged at INFO instead of DEBUG, which caused duplicate log lines like `Completed: Scheduling: Generate lockfile for pytest` alongside the actual `Completed: Generate lockfile for pytest`.
 
+Completed and canceled workunit log messages now include elapsed time, e.g. `Completed: Generate lockfile for my-resolve (45.2s)`. Durations of 60 seconds or more use a minutes format like `2m 30.5s`.
+
 #### Internal Python Upgrade
 
 The version of Python used by Pants itself has been updated to [3.14](https://docs.python.org/3/whatsnew/3.14.html). To support this, the [Pants Launcher Binary](https://www.pantsbuild.org/blog/2023/02/23/the-pants-launcher-binary-a-much-simpler-way-to-install-and-run-pants) (also known as [`scie-pants`](https://github.com/pantsbuild/scie-pants/)) now has a minimum version of `0.13.0`. To update to the latest launcher binary, either:

src/rust/workunit_store/src/lib.rs

@@ -28,6 +28,21 @@ use tokio::task_local;
 
 mod metrics;
 
+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;
+        if secs < 0.05 {
+            format!("{mins}m")
+        } else {
+            format!("{mins}m {secs:.1}s")
+        }
+    } else {
+        format!("{total_secs:.1}s")
+    }
+}
+
 ///
 /// A unique id for a single run or `--loop` iteration of Pants within a single Scheduler.
 ///
@@ -260,6 +275,18 @@ impl Workunit {
             self.name
         };
 
+        let duration_suffix: Option<String> = match &self.state {
+            WorkunitState::Completed { time_span } => Some(format!(
+                " ({})",
+                format_workunit_duration(Duration::from(time_span.duration))
+            )),
+            WorkunitState::Started { start_time, .. } if canceled => Some(format!(
+                " ({})",
+                format_workunit_duration(start_time.elapsed().unwrap_or_default())
+            )),
+            _ => None,
+        };
+
         /* This length calculation doesn't treat multi-byte unicode charcters identically
          * to single-byte ones for the purpose of figuring out where to truncate the string. But that's
          * ok, since we just want to truncate the log string if it's roughly "too long", we don't care
@@ -281,7 +308,11 @@ impl Workunit {
             "".to_string()
         };
 
-        log!(self.level, "{state} {effective_identifier}{message}");
+        log!(
+            self.level,
+            "{state} {effective_identifier}{}{message}",
+            duration_suffix.as_deref().unwrap_or(""),
+        );
     }
 }
 

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,62 @@ fn wu_level(span_id: u64, parent_id: Option<u64>, level: Level) -> AnonymousWork
     metadata.desc = Some(format!("{span_id}"));
     (level, SpanId(span_id), parent_id.map(SpanId), metadata)
 }
+
+#[test]
+fn format_duration_sub_second() {
+    assert_eq!(format_workunit_duration(Duration::from_millis(123)), "0.1s");
+}
+
+#[test]
+fn format_duration_seconds() {
+    assert_eq!(format_workunit_duration(Duration::from_secs_f64(12.345)), "12.3s");
+}
+
+#[test]
+fn format_duration_just_under_minute() {
+    assert_eq!(format_workunit_duration(Duration::from_secs_f64(59.5)), "59.5s");
+}
+
+#[test]
+fn format_duration_exactly_one_minute() {
+    assert_eq!(format_workunit_duration(Duration::from_secs(60)), "1m");
+}
+
+#[test]
+fn format_duration_exact_multiple_minutes() {
+    assert_eq!(format_workunit_duration(Duration::from_secs(120)), "2m");
+}
+
+#[test]
+fn format_duration_negligible_seconds_omitted() {
+    // 60.04s is below the 0.05 threshold, so seconds are omitted
+    assert_eq!(format_workunit_duration(Duration::from_secs_f64(60.04)), "1m");
+}
+
+#[test]
+fn format_duration_just_above_seconds_threshold() {
+    // 60.1s is above the 0.05 threshold, so seconds are shown
+    assert_eq!(format_workunit_duration(Duration::from_secs_f64(60.1)), "1m 0.1s");
+}
+
+#[test]
+fn format_duration_minutes_and_seconds() {
+    assert_eq!(format_workunit_duration(Duration::from_secs_f64(90.5)), "1m 30.5s");
+}
+
+#[test]
+fn format_duration_multiple_minutes() {
+    assert_eq!(format_workunit_duration(Duration::from_secs_f64(185.7)), "3m 5.7s");
+}
+
+#[test]
+fn format_duration_zero() {
+    assert_eq!(format_workunit_duration(Duration::from_secs(0)), "0.0s");
+}
+
+#[test]
+fn format_duration_over_one_hour() {
+    // 1 hour 30 minutes 45.5 seconds = 5445.5 seconds
+    assert_eq!(format_workunit_duration(Duration::from_secs_f64(5445.5)), "90m 45.5s");
+}
+