diff --git a/docs/notes/2.32.x.md b/docs/notes/2.32.x.md index 22218d048b7..f9ecb40ab57 100644 --- a/docs/notes/2.32.x.md +++ b/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: diff --git a/src/python/pants/base/specs_integration_test.py b/src/python/pants/base/specs_integration_test.py index 0d336fd61c9..028924c1bbe 100644 --- a/src/python/pants/base/specs_integration_test.py +++ b/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 diff --git a/src/rust/workunit_store/src/lib.rs b/src/rust/workunit_store/src/lib.rs index 831367e478a..473fdfa23d7 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; +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 = 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(""), + ); } } diff --git a/src/rust/workunit_store/src/tests.rs b/src/rust/workunit_store/src/tests.rs index 8e7a57b5975..3578a933003 100644 --- a/src/rust/workunit_store/src/tests.rs +++ b/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, 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" + ); +}