Skip to content

fix(taskworker): Measure child busy and wait time in shared memory - #788

Merged
enochtangg merged 18 commits into
mainfrom
track-children-busy-directly
Sep 8, 2026
Merged

enochtangg merged 18 commits into
mainfrom
track-children-busy-directly

Conversation

@enochtangg

@enochtangg enochtangg commented Aug 28, 2026

Copy link
Copy Markdown
Contributor

Context

Taskworker autoscaling is blocked by the occupancy metric. It reads below reality and the gap widens with load, so process-segments-push in s4s2 sits around 0.45 against a KEDA threshold of 0.8 and never scales out, even with its child queue pinned full.

Root Issue

In the first iterations of tracking child process utilization, each child pushed busy/idle events through a multiprocessing.Queue to a parent thread that competes for CPU with the children it measures. Under load that thread falls behind as backlog grows, and each event is billed to whichever flush interval eventually drains it rather than the one it happened in.

Changes

Children now write their own cumulative busy and wait totals into a shared-memory slot and the parent diffs and flushes on each interval, so each round of accounting costs O(children) per second instead of O(tasks) per second and there is no queue left to fall behind.

To accomplish this:

  • Each child gets its own RawArray('double') at spawn, five doubles wide: a version counter, cumulative busy, cumulative wait, the open segment's start, and its kind. The parent holds the only reference, on the TrackedChild, so the slot lives exactly as long as the child does. There is no pool to size and no free list to hand a slot back to, so no exit path can lose one.
  • Each child owns one slot and is its sole writer. Therefore, we can just track totals as plain floats and republish the whole slot on each transition.
  • The version counter is used which guards against the parent trying to flush the slot at the same time a child is trying to update it. The writer bumps the version to odd before touching a field and to even after; the reader retries up to three times if it sees an odd or changed version.
    • A failed read defers rather than drops. The reader leaves its baselines untouched, so the following sample covers both intervals.
  • The parent folds each child's open segment forward at read time by adding now - segment_start to whichever counter is open. A child inside a long task therefore contributes to every interval it spans instead of dumping its whole duration into the interval it happens to finish in.
  • Wait is tracked as the mirror of busy rather than inferred as elapsed - busy, and both counters sum over running children only, to match occupancy's divisor.
  • A slot is freed when its child is reaped, not on the exiting transition. The child publishes once more on its way out, and multiprocessing's heap hands a freed block straight back to the next allocation, so an early release would let a departing child write into its replacement's slot.
  • Occupancy is divided by the summed per-child eligible window instead of elapsed * running_count. A child started part-way through a flush could never have filled it, and billing it whole reads as idle time the pool never had.
    • Eligibility is measured from each child's last successful sample, so a deferred read carries its window forward with it and busy + wait <= eligible survives a retry.

Testing

Six sandbox tests on a single worker pod and broker pod were run to validate accuracy of metric.

Test 1 is the control: a 40ms task at ~10% CPU, which pushes ~1600 messages/s but leaves the parent CPU to spare, and is the one case the old code got right. Tests 2-5 run a 100ms all-CPU task, which is the adversarial case, since the accounting thread competes directly with the children it measures. Test 6 adds aggressive recycling at 150 tasks per child which turns a child over every ~35s, for 471 spawns in 11 minutes and as many slots allocated and freed.

arm C task recycling occupancy true error error before
1 64 40ms, ~10% CPU off 0.6301 0.6288 +0.0012 +0.014
2 16 100ms, all CPU off 0.9931 0.9938 -0.0007 -0.566
3 24 100ms, all CPU off 0.9950 0.9954 -0.0004 -0.470
4 12 100ms, all CPU off 0.9959 0.9965 -0.0005 -0.289
5 32 100ms, all CPU off 0.9951 0.9954 -0.0002 -0.361
6 32 100ms, all CPU 150 tasks 0.9812 0.9954 -0.014 not run

@enochtangg
enochtangg requested a review from a team as a code owner August 28, 2026 21:39
Comment thread clients/python/src/taskbroker_client/worker/worker.py Outdated
Comment thread clients/python/src/taskbroker_client/worker/worker.py Outdated
Comment thread clients/python/src/taskbroker_client/worker/worker.py
@enochtangg
enochtangg marked this pull request as draft August 31, 2026 15:47
A sandbox concurrency sweep showed child_busy_seconds reaching 580
seconds per 1s flush across 24 children, 24x the physical ceiling of
elapsed * running_count, ramping linearly through a stage. Occupancy
read exactly 1.0 the whole time because min(occupancy, 1.0) hid it.

The parent reads child events on a 100ms loop while the metrics thread
drains on a 1s cadence, so an event routinely arrives stamped before a
drain that already accounted for that time. mark_busy then clipped the
wait closure to zero, leaving the emitted wait in place, and opened a
busy segment starting back inside it. Both counters billed the same wall
clock, and the error grew with the event backlog.

- Give TrackedChild a last_drained_at watermark and clamp every segment
  boundary forward to it, so no interval can be credited twice. This
  trades double billing for lag: busy + wait stays equal to the interval
  width, but a stale event lands in the interval it was read, not the
  one it happened in.
- Sum the counters over running children only. Occupancy divides by
  running_count, so folding pending or exiting children into the
  numerator measured one population against another.
- Emit taskworker.worker.occupancy.accounting_overflow when either
  counter exceeds elapsed * running_count, so this class of fault cannot
  hide behind the clamp again.
- Emit taskworker.worker.child_message.age so the lag the clamp
  introduces is visible. Flat and sub-second is healthy; a rising line
  means the event loop is not keeping up and the signal is going stale.

@evanh evanh left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Something to think about: it's OK if occupancy goes above 1.0. You can have greater than 100% utilization. Not sure if that simplifies any logic here.

# Time-weighted busy tracking
busy_since: float | None = None # monotonic timestamp of the currently-open busy segment
busy_accumulated: float = 0.0 # the busy seconds banked since the last occupancy flush
class TimeSegment:

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can this all be simplified? This is a lot of code to measure "executing a task" vs. "not executing a task".

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Discussed offline: there has been a significant change in the implementation since last reviewed. We have replaced the whole accounting path with shared memory, and occupancy now divides by the summed per-child eligible window rather than elapsed * running_count, so it's probably worth a fresh pass.

On going above 1.0, a child is either executing or blocked in get_task at any instant, so its window has a physical bound busy <= eligible, which means above 1.0 can only be the accounting double-billing. That's why the clamp is paired with accounting_overflow: the clamp keeps the value bounded and the counter makes the double-billing visible instead of letting it read as a healthy 1.0. Most in-flight reads never get that far, since the seqlock catches them and the parent leaves its baselines alone so the next flush covers both intervals rather than dropping one.

enochtangg and others added 2 commits September 2, 2026 11:21
Occupancy was only accurate while the parent's spawn-children thread kept
up with the child event stream. Every task pushed two ChildMessage objects
through a multiprocessing.Queue, each pickled in the child and unpickled in
a parent thread competing for CPU with the children it measures. Sandbox
run 1788289180 showed the result: under a 100ms all-CPU task at ~276
messages/s, child_message.age ramped from 0.25s to 81.4s inside one stage
and never recovered, and occupancy read 0.430 against a true 0.996. The
C=64 control on the 40ms task, at 6x the message rate but with CPU
headroom, stayed flat at 0.199s and accurate to 0.014.

Children now write their own cumulative busy/wait totals into a RawArray
slot and the parent diffs them at flush, so the cost is O(children) per
second instead of O(tasks) per second. Only lifecycle events still cross
the queue, two per child rather than two per task.

Slots are cumulative and absolute rather than deltas, which is what makes a
torn read survivable: a bad sample is transient and the next one re-derives
the truth from the slot. A seqlock guards the four-field publish. Folding
the open segment forward at read time preserves the property that a child
in a long task contributes to every interval it spans, which is why this is
shared memory rather than children emitting their own metrics.

The watermark from the previous commit is gone; it existed only to defend
against stale busy/idle events and there are none left. Metric names,
the occupancy formula, accounting_overflow and the KEDA trigger are all
unchanged, so no dashboard or scaler edits are needed.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@enochtangg enochtangg changed the title fix(taskworker): Add metric to measure child busy and wait time as counters fix(taskworker): Measure child busy and wait time in shared memory Sep 2, 2026
enochtangg and others added 5 commits September 2, 2026 16:06
Occupancy cannot separate a pool whose children are starved from one with
no work to do. Both leave children idle, and they need opposite scaling
decisions. The discriminator is whether work exists, which children cannot
see because they only ever see work they were handed.

execution_latency already carries that information but cannot be alerted on
with a single threshold, because it is queue_wait + execution_duration and
the second term is exactly what differs per pool: a pool running 4s tasks
would trip a 2s threshold while perfectly healthy.

queue_wait is the term that does not scale with task duration. Measured on
process-segments-push over 7 days, execution_latency p95 holds a flat floor
of 1.008-1.11s while execution_duration swings 3x, so the wait is pipeline
overhead rather than task cost and one threshold is meaningful across pools.
Healthy reads ~1s; a starved sandbox pod reads 330s.

Also fixes the timestamp both metrics are derived from. ToDatetime() returns
a naive datetime holding UTC and .timestamp() then reads it as local time,
so task_added_time was wrong by the host's UTC offset. Containers run UTC so
this was latent in production, but it silently skewed every latency reading
off-cluster, and it is what surfaced when the new test asserted a known wait.
seconds+nanos is exact and timezone-free.

Datadog only. queue_wait is computed per task in the child, and the
Prometheus registry lives in the parent process, so exposing it for scraping
would need the same cross-process plumbing this branch added for busy/wait.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sandbox cell 6 (C=32 with recycling every 150 tasks) showed busy + wait at
0.70 of elapsed * running_count for its first four minutes, converging to
0.98 after. execution_duration was flat throughout, so the workload did not
change and roughly 20% of executed time was going unaccounted. Occupancy
read 0.729 against a true 0.996.

accounting_overflow stayed silent through all of it, because it only tests
busy > ceiling. It is structurally blind to the under-count direction, which
is the exact failure this project started from.

Three additions, chosen to identify the cause rather than just alarm:

accounting_ratio is (busy + wait) / ceiling, the continuous form of what the
overflow guard tests as a threshold. eligible_ratio is the same numerator
over the time children were actually eligible to accrue in, which differs
for a child baselined part-way through an interval: the ceiling counts it
whole. If eligible_ratio reads ~1.0 while accounting_ratio reads low, the
denominator is at fault and no time is missing. If both read low, time is
genuinely lost and sample_outcome says where: not_accounted, read_failed or
clamped, the last meaning a cumulative total went backwards, which is a torn
read or a reused slot.

accounting_deficit fires below 0.9 and logs the decomposition, mirroring the
overflow guard so the metric can no longer under-report silently.

sample() now returns SampleResult rather than a tuple, carrying eligibility
and the reason alongside busy and wait.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`elapsed * running_count` bills a child baselined part-way through a flush
as if it had been present for all of it, so a recycling pool reports idle
time it never had. Sum each child's own measured window instead.

`eligible` now runs from the child's last successful sample rather than
from the flush boundary, so a read deferred by a seqlock retry carries its
window forward with the busy it recovers. Without that, the recovering
sample reports two intervals of busy against one interval of ceiling and
trips accounting_overflow.

Both diagnostic gauges change meaning with it:

  accounting_ratio  (busy + wait) / summed eligible window. An invariant
                    now, pinned at 1.0. Below it means a measurable child
                    reported less than its own window, i.e. time genuinely
                    lost, and sample_outcome says which of the three ways.

  eligible_ratio    summed eligible window / (elapsed * running_count).
                    The size of the correction rather than a fault. Below
                    1.0 during ramp-up and steady recycling is expected.

Measured on the sandbox at C=32 recycling every 150 tasks: the correction
is worth 2-4% on average, dipping to 0.86 on flushes that catch several
new children at once.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The ratios and the per-reason sample counter were built to find the cause
of the under-reporting. That is done, so keep only what is worth carrying
in production:

  accounting_overflow   busy or wait exceeded the measured window
  accounting_deficit    the pair fell short of it

Two counters guarding one invariant in both directions, both expected to
sit at zero. Dropped `occupancy.accounting_ratio` (the continuous form of
the same check), `occupancy.eligible_ratio` (needed the headcount versus
eligible distinction explained to be read at all), and
`occupancy.sample_outcome` with its four tag values.

`SampleResult` loses its `reason` field with them, and a failed seqlock
read now reports an empty result rather than zero busy against a full
window. Busy and eligible then advance together across a deferred sample
instead of one outrunning the other.

`_last_occupancy_flush_at` is gone too. Each child carries the window its
own delta covers, so the pool no longer needs a shared flush boundary.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@enochtangg
enochtangg marked this pull request as ready for review September 3, 2026 19:08

@cursor cursor Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Stale Bugbot comment from a previous run.

Comment thread clients/python/src/taskbroker_client/worker/childtiming.py
Comment thread clients/python/src/taskbroker_client/worker/childtiming.py
Comment thread clients/python/src/taskbroker_client/worker/childtiming.py
self._metrics_thread: threading.Thread | None = None
self._spawn_children_thread: threading.Thread | None = None

def _acquire_timing_slot(self) -> int:

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there some way to avoid slot acquisition? I am worried that we now have a failure mode where there is an accounting bug and processes stop getting assigned slots.

@enochtangg enochtangg Sep 8, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Slot exhaustion should not stop children from spawning or running tasks. If no slot can be acquired, it should continue; however, the metric becomes broken and it won't be able to scale out by utilization. In theory, this shouldn't happen as we assign 2x the slots what we need, it's possible it's a failure mode that could come up somehow unexpectedly. I added a metric to monitor that: taskworker.worker.child.timing_slot_exhausted.

To mitigate this though, we could assign each child process its own RawArray('d', 5) at spawn. This should also reduce the surface area that might cause potential memory leaks as well.

enochtangg and others added 2 commits September 8, 2026 11:06
The free list had to be handed back on every path a child could leave by:
the reap scan, and the spawn except. A missed path lost that slot for the
life of the pool, and enough of them would drop running_count to zero and
stop occupancy being emitted at all.

Derive the available set from _children instead. A slot is in use exactly
while its child is tracked, so reaping the child returns it and there is
no bookkeeping left to get wrong. Derived once per spawn batch, under the
same lock hold that sizes the batch.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Deriving the free set from _children removed the leak but kept the pool: a
fixed 2 * concurrency array, an index per child, and an exhaustion path that
could still switch occupancy off.

Allocate a five-double RawArray per child at spawn instead, and hang it on
the TrackedChild. The parent holds the only reference, so reaping the child
frees it and there is nothing to hand back. slot_count, NO_SLOT and the
timing_slot_exhausted metric all go, and shm is no longer optional because a
tracked child cannot be without one.
Comment thread clients/python/src/taskbroker_client/worker/childtiming.py

@cursor cursor Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Stale Bugbot comment from a previous run.

Comment thread clients/python/src/taskbroker_client/worker/childtiming.py
Comment thread clients/python/src/taskbroker_client/worker/worker.py Outdated

@cursor cursor Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cursor Bugbot has reviewed your changes and found 1 potential issue.

Fix All in Cursor

❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, enable autofix in the Cursor dashboard.

Reviewed by Cursor Bugbot for commit 7afcd9e. Configure here.

Comment thread clients/python/src/taskbroker_client/worker/childtiming.py Outdated
enochtangg and others added 2 commits September 8, 2026 13:44
get_task had a standing return_value, so every run_once in the wait loop
pushed another task. The loop breaks on update_task.call_count >= 1 and then
asserts == 1, so a slow result thread meant a second task landed and the
assertion saw 2. Hands out one task and then None, matching the sibling test
above it.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@enochtangg
enochtangg merged commit e665a7c into main Sep 8, 2026
29 checks passed
@enochtangg
enochtangg deleted the track-children-busy-directly branch September 8, 2026 20:13
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.

2 participants