feat(engine): log elapsed time for completed and canceled workunits by jasonwbarnett · Pull Request #22992 · pantsbuild/pants

jasonwbarnett · 2026-01-09T00:22:39Z

Problem

When Pants logs workunit state changes, the message doesn't include how long the operation took:

23:17:29.42 [INFO] Completed: Generate lockfile for my-resolve

This makes it difficult to identify slow operations or track performance over time.

Solution

Include elapsed time in workunit log messages for completed and canceled workunits:

23:17:29.42 [INFO] Completed: Generate lockfile for my-resolve (45.2s)

For operations taking 60+ seconds, the format shows minutes:

23:17:29.42 [INFO] Completed: Generate lockfile for my-resolve (2m 30.5s)

Duration is omitted for "Starting:" messages since elapsed time is always ~0s at that point.

Note: An earlier revision of this PR added a log_duration flag on WorkunitMetadata to suppress duration on "Scheduling:" workunits, which were incorrectly promoted to INFO. That root cause was fixed separately in #23251 (preserving the original DEBUG level), so the flag and all related complexity have been removed. Duration is now shown unconditionally for completed and canceled workunits.

Implementation

Added a pub(crate) format_workunit_duration() helper with minute-threshold formatting, using 1 decimal place. This is separate from the existing format_workunit_duration_ms() which is left unchanged.
Modified log_workunit_state() to compute and display duration for completed and canceled workunits
Added 11 unit tests for duration formatting
Added release notes entry

Partially addresses #21587

LLM Disclosure

This PR was developed with assistance from Claude (Anthropic). The LLM helped with rebasing, resolving merge conflicts, removing the log_duration flag after #23251 made it unnecessary, and updating the PR description. All changes were reviewed and validated by the author.

benjyw

Thanks for the contribution! See comments.

jsirois · 2026-01-09T15:28:42Z

@jasonwbarnett this partially implements this idea: #11965

benjyw · 2026-01-25T23:59:04Z

Hi, just checking in on the status of this...

jasonwbarnett · 2026-04-06T22:27:03Z

@benjyw I finally got back to this. Thanks for the reviews. Let me know if you see anything else.

## Problem When a process runs (e.g. `generate-lockfiles`), the local cache runner updates the "Scheduling:" workunit metadata to attach cache digests. As a side effect, it **overrides the workunit log level to `Info`**, regardless of its original level. Since `ExecuteProcess` workunits intentionally start at `Debug` (to avoid rendering until execution actually begins), this promotion causes duplicate INFO-level output: ``` 23:22:27.30 [INFO] Starting: Generate lockfile for pytest 23:22:53.66 [INFO] Completed: Generate lockfile for pytest (26.4s) 23:22:53.66 [INFO] Completed: Scheduling: Generate lockfile for pytest (26.4s) ``` The third line is redundant — the scheduling workunit is a wrapper whose duration mirrors its child. ## Root Cause This was inadvertently introduced in #22212, which added Action/Command digest metadata to workunits. The `update_metadata` call needed to attach `local_command` and `local_action` digests, but the closure also hardcoded `Level::Info` as the new level — discarding the original. The PR was focused on metadata, not log levels, and the level override was not discussed in review. ## Solution Preserve the workunit's original log level when updating cache metadata, instead of unconditionally overriding it to `Level::Info`. The metadata update only needs to set `local_command` and `local_action` — it has no reason to change the log level. ## Result Default (INFO-level) output is now clean: ``` 23:22:27.30 [INFO] Starting: Generate lockfile for pytest 23:22:53.66 [INFO] Completed: Generate lockfile for pytest ``` The "Scheduling:" message remains visible at `-ldebug` for debugging purposes. ## LLM Disclosure This PR was written with Amp (Claude). The LLM diagnosed the root cause by tracing the workunit level flow through the codebase, identified the accidental `Level::Info` override in #22212, and wrote the one-line fix. I reviewed the diagnosis and fix, validated it by running Pants from sources against our monorepo, and confirmed the duplicate log line no longer appears. Related: #22992 Co-authored-by: Jason Barnett <jason.barnett@altana.ai> Co-authored-by: Amp <amp@ampcode.com>

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 <noreply@anthropic.com>

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 <noreply@anthropic.com>

Address review feedback: show elapsed time for all workunits (starting, completed, canceled) instead of only completed and canceled. Since all match arms now return a value, simplify from Option<String> to String. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

…on_ms - Remove separate format_workunit_duration function; extend existing format_workunit_duration_ms with minute-threshold logic (Xm Y.Ys for durations >= 60s) - Use 1 decimal place consistently, matching the convention from pantsbuild#23215 - Move parens/spacing to the call site instead of baking into the formatter - Drop unnecessary std::time:: qualification (Duration already imported) - Update tests to match new function and formatting Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

…helper Revert format_workunit_duration_ms to its original one-liner to avoid changing behavior for existing callers (terminal progress bars, straggling workunit reports). Add a separate pub(crate) format_workunit_duration helper with minute-threshold logic used only by log_workunit_state. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

….0s") Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

These are parent workunits that wrap actual work, so their duration mirrors their children and is misleading. Omit duration for now. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Only show elapsed time for Completed and Canceled workunits, where the duration is meaningful. Starting workunits always show ~0s which is noise. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Add a `log_duration` field to `WorkunitMetadata` (defaults to true). Set it to false for ExecuteProcess workunits, which are scheduling wrappers whose duration just mirrors their children. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

…root cause PR pantsbuild#23251 fixed the "Scheduling:" workunit being promoted to INFO, so the log_duration mechanism to suppress duplicate durations is no longer needed. Duration is now shown unconditionally for completed and canceled workunits. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

benjyw

Nice and simple!

benjyw · 2026-04-15T23:37:09Z

You need to run ./cargo fmt on your code

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

The specs_integration_test assertions checked for exact substrings like "tests - succeeded." which no longer match because the log output now includes a duration between the identifier and message. Use regex to allow for the parenthetical duration. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

jasonwbarnett force-pushed the jwb/log-workunit-duration branch 2 times, most recently from a16c307 to 0983a6a Compare January 9, 2026 00:31

benjyw reviewed Jan 9, 2026

View reviewed changes

Comment thread src/rust/workunit_store/src/lib.rs Outdated

Comment thread src/rust/workunit_store/src/lib.rs Outdated

Comment thread src/rust/workunit_store/src/lib.rs Outdated

jsirois mentioned this pull request Jan 9, 2026

Show progress in addition to the timer in dynamic UI swimlane lines. #11965

Open

jasonwbarnett force-pushed the jwb/log-workunit-duration branch 2 times, most recently from 2248d22 to c58d943 Compare January 9, 2026 15:56

jasonwbarnett requested a review from benjyw January 12, 2026 16:51

benjyw reviewed Jan 13, 2026

View reviewed changes

Comment thread src/rust/workunit_store/src/lib.rs Outdated

jasonwbarnett force-pushed the jwb/log-workunit-duration branch from 6d04b88 to d7d5ef1 Compare April 6, 2026 22:25

jasonwbarnett changed the title ~~feat(engine): log elapsed time for completed workunits~~ feat(engine): log elapsed time for all workunit states Apr 6, 2026

jasonwbarnett changed the title ~~feat(engine): log elapsed time for all workunit states~~ feat(engine): log elapsed time for workunits and improve duration formatting Apr 6, 2026

jasonwbarnett changed the title ~~feat(engine): log elapsed time for workunits and improve duration formatting~~ feat(engine): log elapsed time for all workunit states Apr 6, 2026

jasonwbarnett force-pushed the jwb/log-workunit-duration branch from cf784c6 to d075108 Compare April 6, 2026 23:13

jasonwbarnett changed the title ~~feat(engine): log elapsed time for all workunit states~~ feat(engine): log elapsed time for completed and canceled workunits Apr 6, 2026

jasonwbarnett force-pushed the jwb/log-workunit-duration branch from 19f9045 to 832d1e4 Compare April 6, 2026 23:14

benjyw reviewed Apr 7, 2026

View reviewed changes

Comment thread src/rust/workunit_store/src/lib.rs

Comment thread src/rust/workunit_store/src/lib.rs Outdated

jasonwbarnett mentioned this pull request Apr 14, 2026

fix: preserve workunit log level in local cache metadata update #23251

Merged

Jason Barnett and others added 9 commits April 15, 2026 23:17

feat: omit zero seconds in minute-plus durations (e.g. "1m" not "1m 0…

750f9fa

….0s") Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

docs: add release notes for workunit elapsed time logging

693ffd4

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

skip duration for "Scheduling:" prefixed workunits

aa8df83

These are parent workunits that wrap actual work, so their duration mirrors their children and is misleading. Omit duration for now. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

skip duration for "Starting:" workunits

ccb03ac

Only show elapsed time for Completed and Canceled workunits, where the duration is meaningful. Starting workunits always show ~0s which is noise. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Jason Barnett and others added 4 commits April 15, 2026 23:18

test: verify WorkunitMetadata defaults log_duration to true

a427ed2

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

fix: flip if-not-else to satisfy clippy lint

38ea727

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

jasonwbarnett force-pushed the jwb/log-workunit-duration branch from e1fa7eb to e785d32 Compare April 15, 2026 23:19

jasonwbarnett requested a review from benjyw April 15, 2026 23:22

benjyw approved these changes Apr 15, 2026

View reviewed changes

Jason Barnett and others added 3 commits April 15, 2026 23:44

style: apply cargo fmt

ffdd620

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

fix: extract helper for duration-aware test assertions, fix ruff format

50723b9

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

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

feat(engine): log elapsed time for completed and canceled workunits#22992
jasonwbarnett wants to merge 16 commits intopantsbuild:mainfrom
altana-ai:jwb/log-workunit-duration

jasonwbarnett commented Jan 9, 2026 •

edited

Loading

Uh oh!

benjyw left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jsirois commented Jan 9, 2026

Uh oh!

Uh oh!

benjyw commented Jan 25, 2026

Uh oh!

jasonwbarnett commented Apr 6, 2026

Uh oh!

Uh oh!

Uh oh!

benjyw left a comment

Uh oh!

benjyw commented Apr 15, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Uh oh!

Conversation

jasonwbarnett commented Jan 9, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Problem

Solution

Implementation

LLM Disclosure

Uh oh!

benjyw left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jsirois commented Jan 9, 2026

Uh oh!

Uh oh!

benjyw commented Jan 25, 2026

Uh oh!

jasonwbarnett commented Apr 6, 2026

Uh oh!

Uh oh!

Uh oh!

benjyw left a comment

Choose a reason for hiding this comment

Uh oh!

benjyw commented Apr 15, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

jasonwbarnett commented Jan 9, 2026 •

edited

Loading