Skip to content

feat: expose per-task queue and run timings to the producer - #20

Merged
adhikjoshi merged 1 commit into
mainfrom
feat/expose-stage-timings
Aug 21, 2026
Merged

feat: expose per-task queue and run timings to the producer#20
adhikjoshi merged 1 commit into
mainfrom
feat/expose-stage-timings

Conversation

@adhikjoshi

@adhikjoshi adhikjoshi commented Aug 21, 2026

Copy link
Copy Markdown
Contributor

Why

A generation API answered a request in 37.7s while the only timer in its response read generationTime: 5.55. That timer starts after the task is enqueued, so it hid the 30s the HTTP handler had already spent, and it merged queue wait into the same number as the run. Nothing in the response could account for the missing 32s.

ModelQ already records created_at / queued_at / started_at / finished_at and persists them in the terminal task_result: blob — but a producer could not read any of it:

  1. The task decorator wrote created_at/queued_at into the dict it pushed to Redis and never onto the Task object it handed back, so task.queued_at was always None.
  2. get_result() copied only result and status off the terminal blob and dropped the run timestamps.

What

  • Mirror the enqueue stamps onto the Task the producer receives.
  • get_result() absorbs the terminal blob's timestamps before it can raise, so a failed or cancelled task still reports where its time went — the case that most needs the split.
  • New Task.stage_timings(){queue_time, run_time, total_time}.

A stage that cannot be measured is omitted, not zeroed. A fabricated 0.0 reads as "instant" and would hide the very stall this exists to expose.

Compatibility

Additive. A result blob from an older worker leaves the timestamps the producer already holds untouched, and stage_timings() returns {}. Callers that never look at the timestamps are unaffected.

Tests

tests/test_stage_timings.py — 5 tests covering the queue/run split, the omit-don't-zero rule, timestamps surviving a failed task, and an older worker's blob not clobbering what the producer holds.

Mutation-tested: with both source changes reverted, all 5 go red. Full suite: 107 passed.


View with [code]smith Autofix with [code]smith
Need help on this PR? Tag @codesmith-bot with what you need. Autofix is disabled.

A generation API answered a request in 37.7s while the only timer in its
response read `generationTime: 5.55`. That timer is measured from enqueue to
result, so it hid everything the HTTP handler did beforehand and merged queue
wait into the same number as the run. Nothing in the response could account for
the missing 32s.

ModelQ already records created_at/queued_at/started_at/finished_at and persists
them in the terminal blob, but a producer could not read any of it:

- The task decorator wrote created_at/queued_at into the dict it pushed to Redis
  and never onto the Task object it handed back, so `task.queued_at` was None.
- `get_result()` copied only `result` and `status` off the terminal blob and
  dropped the run timestamps.

Mirror the enqueue stamps onto the returned Task, absorb the terminal blob's
timestamps in `get_result()` before it can raise, and add `Task.stage_timings()`
returning the queue/run/total split. Stages that cannot be measured are omitted
rather than reported as 0.0 -- a fabricated zero reads as "instant" and would
hide the very stall this exists to expose.

Backwards compatible: a result blob from an older worker leaves the timestamps
the producer already holds untouched, and stage_timings() simply returns {}.
@adhikjoshi
adhikjoshi merged commit 15849b5 into main Aug 21, 2026
3 checks passed
@adhikjoshi
adhikjoshi deleted the feat/expose-stage-timings branch August 21, 2026 07:50
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant