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/python/pants/base/specs_integration_test.py

@@ -3,6 +3,7 @@
 
 from __future__ import annotations
 
+import re
 from textwrap import dedent
 
 from pants.testutil.pants_integration_test import PantsResult, run_pants, setup_tmpdir
@@ -54,6 +55,11 @@ def test_capitalize():
 }
 
 
+def _assert_succeeded(test_result: str, target: str) -> None:
+    pattern = re.escape(target) + r" \([^)]+\) - succeeded\."
+    assert re.search(pattern, test_result), f"Expected '{target}' succeeded in output"
+
+
 def run(args: list[str]) -> PantsResult:
     result = run_pants(
         [
@@ -80,8 +86,8 @@ def test_address_literal() -> None:
         assert run(["list", *list_specs]).stdout.splitlines() == list_specs
 
         test_result = run(["test", f"{tmpdir}/py:tests"]).stderr
-        assert f"{tmpdir}/py/utils/strutil_test.py:../tests - succeeded." in test_result
-        assert f"{tmpdir}/py/base/common_test.py:../tests - succeeded." in test_result
+        _assert_succeeded(test_result, f"{tmpdir}/py/utils/strutil_test.py:../tests")
+        _assert_succeeded(test_result, f"{tmpdir}/py/base/common_test.py:../tests")
         assert f"{tmpdir}/py:tests" not in test_result
 
 
@@ -109,14 +115,14 @@ def test_sibling_addresses() -> None:
         # Even though no `python_test` targets are explicitly defined in `util/`, a generated
         # target is resident there.
         test_result = run(["test", f"{tmpdir}/py/utils:"]).stderr
-        assert f"{tmpdir}/py/utils/strutil_test.py:../tests - succeeded." in test_result
+        _assert_succeeded(test_result, f"{tmpdir}/py/utils/strutil_test.py:../tests")
         assert f"{tmpdir}/py/base/common_test.py:../tests" not in test_result
         assert f"{tmpdir}/py:tests" not in test_result
 
         # Even though no `_test.py` files live in this dir, we match the `python_tests` target
         # and replace it with its generated targets.
         test_result = run(["test", f"{tmpdir}/py:"]).stderr
-        assert f"{tmpdir}/py/utils/strutil_test.py:../tests - succeeded." in test_result
+        _assert_succeeded(test_result, f"{tmpdir}/py/utils/strutil_test.py:../tests")
         assert f"{tmpdir}/py/base/common_test.py:../tests" in test_result
         assert f"{tmpdir}/py:tests" not in test_result
 
@@ -137,7 +143,7 @@ def test_descendent_addresses() -> None:
         ]
 
         test_result = run(["test", f"{tmpdir}/py::"]).stderr
-        assert f"{tmpdir}/py/utils/strutil_test.py:../tests - succeeded." in test_result
+        _assert_succeeded(test_result, f"{tmpdir}/py/utils/strutil_test.py:../tests")
         assert f"{tmpdir}/py/base/common_test.py:../tests" in test_result
         assert f"{tmpdir}/py:tests" not in test_result
 

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,10 @@ 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 +227,82 @@ 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"
+    );
+}