feat: expose per-task queue and run timings to the producer - #20
Merged
Conversation
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 {}.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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_atand persists them in the terminaltask_result:blob — but a producer could not read any of it:created_at/queued_atinto the dict it pushed to Redis and never onto theTaskobject it handed back, sotask.queued_atwas alwaysNone.get_result()copied onlyresultandstatusoff the terminal blob and dropped the run timestamps.What
Taskthe 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.Task.stage_timings()→{queue_time, run_time, total_time}.A stage that cannot be measured is omitted, not zeroed. A fabricated
0.0reads 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.
Need help on this PR? Tag
@codesmith-botwith what you need. Autofix is disabled.