fix(taskworker): Add metric to measure child busy and wait time as counters

[enochtangg]

Taskworker autoscaling is blocked by the occupancy metric. It reads far 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 cause: busy/idle events were timestamped by the parent when it drained the message queue, not when they happened. The busier the pod, the further that drain falls behind, so work lands in a neighbouring flush interval where occupancy's 1.0 clamp discards the surplus but never refunds the shortfall.

Occupancy also cannot tell saturated from starved. A pod whose children are full and a pod whose children are idle both report low occupancy, and they need opposite scaling decisions.

What changed

Stamp events in the child. ChildMessage carries a timestamp set at the event, and the parent applies that instead of its own clock.

Clamp stale events to a per-child watermark. Stamping in the child alone double bills. The parent reads 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. TrackedChild.last_drained_at now clamps every segment boundary forward to the last drain, so busy + wait always equals the interval width. This trades double billing for lag: a stale event is credited to the interval it was read in, not the one it happened in.

Track wait time as the mirror of busy time. wait_since, wait_accumulated, drain_wait. mark_running starts the clock after warmup, mark_stopped closes both segments when a child is released. Both counters now sum over running children only, matching occupancy's running_count divisor.

Two Prometheus counters alongside the occupancy gauge, for the scaler:

• taskworker_worker_child_busy_seconds_total
• taskworker_worker_child_wait_seconds_total

Counters rather than gauges because they are additive, so the scaler sums across pods and divides once instead of averaging per-pod ratios.

Two guard metrics (statsd), so neither failure mode can hide again:

• taskworker.worker.occupancy.accounting_overflow fires when either counter exceeds elapsed * running_count, which is a hard physical bound. This is what the clamp was masking.
• taskworker.worker.child_message.age is how stale the events being applied are. Flat and sub-second is healthy. A rising line means the event loop is behind and occupancy is lagging reality.

Measured

Sandbox sweep, 1 broker and 1 worker, a task burning exactly 100ms of CPU against a 12 core request. Throughput and execution duration were identical across both runs, so only the metric moved.

concurrency	before	with child timestamps	true
8	0.82	1.00	1.00
12	0.52	1.00	1.00
16	0.50	0.92	0.99
24	0.60	0.92	1.00
32	0.69	0.94	1.00

"true" is 1 - fetch_wait / cycle, where cycle = children_running / throughput. Children are idle only during the fetch wait, which measured 0.4ms to 1.4ms against a 102ms to 452ms cycle.

That same run exposed the double billing. At concurrency 24, child_busy_seconds ramped from 2 to 580 seconds per 1s flush across 24 children, 24x the ceiling of elapsed * running_count. child_wait_seconds ramped in lockstep, so busy / (busy + wait) collapsed toward 0.5. Occupancy read exactly 1.0 for the entire ramp because of the clamp. The watermark fix and the overflow counter both come from that.

Scaler queries

Corrected occupancy:

sum(rate(taskworker_worker_child_busy_seconds_total{processing_pool="$pool"}[2m]))
/ clamp_min(
    sum(rate(taskworker_worker_child_busy_seconds_total{processing_pool="$pool"}[2m]))
  + sum(rate(taskworker_worker_child_wait_seconds_total{processing_pool="$pool"}[2m])),
    0.001)

Starved child slots, in units of children. Divide by concurrency for pods-worth of idle capacity:

sum(rate(taskworker_worker_child_wait_seconds_total{processing_pool="$pool"}[2m]))

The second is what occupancy cannot express. Near zero under a backlog means saturated, so more pods help. Large means the feed is the constraint, so more pods only add idle children.

Before merging

The sweep above validated the child timestamps but predates the watermark fix, so the counters and the ratio query have not been measured end to end. Re-running it is the acceptance check, and the criterion is not occupancy but child_busy_seconds ~= children_running per flush at every cell, with accounting_overflow staying at zero.

[sentry]

Bug: A stale mark_idle call after a drain can set wait_since to an old timestamp, causing time to be double-counted as both 'busy' and 'wait'.
_{Severity: MEDIUM}

Suggested Fix

In the mark_idle function, add a guard to prevent wait_since from being updated if the provided timestamp is older than the last drain time (self.busy_since). This can be achieved by checking if ts < self.busy_since and returning early if true, ensuring stale idle events do not affect wait time calculations.

Prompt for AI Agent

Review the code at the location below. A potential bug has been identified by an AI
agent. Verify if this is a real issue. If it is, propose a fix; if not, explain why it's
not valid.

Location: clients/python/src/taskbroker_client/worker/worker.py#L267-L268

Potential issue: A stale 'idle' message arriving after a drain operation can cause time
to be double-counted. The `mark_idle` function does not guard against setting
`wait_since` to a stale timestamp. If `drain_busy` runs at time `T1`, and a stale
`mark_idle` call with timestamp `T0 < T1` arrives, `wait_since` is set to `T0`. The
subsequent `drain_wait` call will then calculate wait time from `T0`, incorrectly
including the interval `[T0, T1]` which was already accounted for as busy time, leading
to inflated wait time metrics.

_{Did we get this right? 👍 / 👎 to inform future reviews.}

[cursor]

Cursor Bugbot has reviewed your changes and found 2 potential issues.

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

^{Reviewed by Cursor Bugbot for commit ac73185. Configure here.}

[cursor]

Stale timestamps double-count child time

Medium Severity

mark_idle and mark_busy open the next segment at the raw child timestamp even when that stamp predates the last drain. drain_* already folded the previous open segment up to the parent clock, and max(0.0, …) only stops the close from going negative, so the overlapped span is credited twice. Under load the spawn loop lags the 1s flush, so wait is inflated and the scaler occupancy busy / (busy + wait) reads low — the same class of error this change is meant to fix.

Additional Locations (1)

• clients/python/src/taskbroker_client/worker/worker.py#L254-L256

 

^{Reviewed by Cursor Bugbot for commit ac73185. Configure here.}

[cursor]

Reaped children drop banked seconds

Low Severity

Dead children are removed from _children without draining busy_accumulated/wait_accumulated. mark_stopped banks the closing wait or busy span so a released child does not fold wait forward, but that bank is discarded if the process is reaped before the next 1s flush, so recycle and crash paths under-count the new counters.

Additional Locations (1)

• clients/python/src/taskbroker_client/worker/worker.py#L1273-L1276

 

^{Reviewed by Cursor Bugbot for commit ac73185. Configure here.}