From a4ef39796f14dd0fde6cb252325d520329d353f5 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Fri, 28 Aug 2026 15:18:43 -0400 Subject: [PATCH 01/17] Measure child busy and wait time as counters --- .../src/taskbroker_client/worker/worker.py | 148 +++++++++++++- .../taskbroker_client/worker/workerchild.py | 25 ++- clients/python/tests/worker/test_worker.py | 189 ++++++++++++++++++ 3 files changed, 351 insertions(+), 11 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index f429f6a2..c5c6572c 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -132,6 +132,41 @@ def __init__( registry=self.registry, ) + # Counters, not a ratio gauge. The gauge above is sampled per pod and + # then averaged across pods by the scaler, which is an unweighted mean of + # ratios and is not the pool's occupancy. These two are additive, so a + # scaler can sum them across pods first and divide once: + # + # busy_rate / (busy_rate + wait_rate) + # + # They are also unclamped, which matters more than it sounds. Occupancy + # is clipped to 1.0 per interval, so an interval that over-counts loses + # the excess while one that under-counts keeps the deficit. Work landing + # in a neighbouring interval therefore drags the average down instead of + # cancelling out. Summing counters over the scaler's rate window has no + # such ceiling, so the same misattribution cancels. + # + # And a missed scrape shows up as a flat rate rather than as a + # plausible-looking low occupancy that triggers a scale down. + self.child_busy_seconds = prometheus_client.Counter( + "taskworker_worker_child_busy_seconds", + "Cumulative child-seconds spent executing tasks.", + ["processing_pool"], + registry=self.registry, + ) + + # The signal occupancy cannot express on its own: child slots that are + # available and have nothing to do. If this is near zero while a backlog + # exists, the pod is saturated no matter what occupancy reports, and more + # pods will help. If it is large, the pod is starved and more pods will + # only add idle children. + self.child_wait_seconds = prometheus_client.Counter( + "taskworker_worker_child_wait_seconds", + "Cumulative child-seconds spent blocked waiting for a task to arrive.", + ["processing_pool"], + registry=self.registry, + ) + prometheus_client.start_http_server(port, registry=self.registry) logger.info("taskworker.worker.prometheus_server_started", extra={"port": port}) @@ -214,26 +249,65 @@ class TrackedChild: # 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 + # Time-weighted wait tracking, the mirror of the two fields above. A running + # child is always in exactly one of the two states: executing a task, or + # blocked in `child_tasks.get()` with nothing to execute. + # + # Wait is tracked separately rather than inferred as `elapsed - busy` because + # the inference is only valid for children that were running for the whole + # interval. Children spawn, warm up, and exit mid-interval, and those + # transitions are exactly when a pool is scaling, which is when the signal + # has to be trustworthy. + wait_since: float | None = None # monotonic timestamp of the currently-open wait segment + wait_accumulated: float = 0.0 # the waiting seconds banked since the last flush + + def mark_running(self, now: float) -> None: + """Start counting wait time once the child has finished warming up. + + A `pending` child is importing the app, not starving for work, so it + accrues neither busy nor wait until it reports in. + """ + if self.busy_since is None and self.wait_since is None: + self.wait_since = now def mark_busy(self, now: float) -> None: - """Open a busy segment when the child starts a task. + """Close the open wait segment and open a busy one. - `busy`/`idle` strictly alternate per child today, so a segment should - never already be open; the guard is defensive and keeps the original - start time if that invariant ever drifts. + `busy`/`idle` strictly alternate per child today, so a busy segment + should never already be open; the guard is defensive and keeps the + original start time if that invariant ever drifts. """ + if self.wait_since is not None: + self.wait_accumulated += max(0.0, now - self.wait_since) + self.wait_since = None if self.busy_since is None: self.busy_since = now def mark_idle(self, now: float) -> None: - """Close the open busy segment and bank its elapsed seconds. + """Close the open busy segment and open a wait one. Guarded so an unexpected `idle` with no open segment is a no-op rather than a crash. """ if self.busy_since is not None: - self.busy_accumulated += now - self.busy_since + self.busy_accumulated += max(0.0, now - self.busy_since) + self.busy_since = None + if self.wait_since is None: + self.wait_since = now + + def mark_stopped(self, now: float) -> None: + """Close both segments when the child is released to shut down. + + Without this a released child keeps an open wait segment that folds + forward on every drain, so a pool that is recycling children would look + starved for work when it is not. + """ + if self.busy_since is not None: + self.busy_accumulated += max(0.0, now - self.busy_since) self.busy_since = None + if self.wait_since is not None: + self.wait_accumulated += max(0.0, now - self.wait_since) + self.wait_since = None def drain_busy(self, now: float) -> float: """Return busy seconds since the last drain and reset the counter. @@ -243,12 +317,27 @@ def drain_busy(self, now: float) -> float: contributing to each one. """ if self.busy_since is not None: - self.busy_accumulated += now - self.busy_since + self.busy_accumulated += max(0.0, now - self.busy_since) self.busy_since = now banked = self.busy_accumulated self.busy_accumulated = 0.0 return banked + def drain_wait(self, now: float) -> float: + """Return waiting seconds since the last drain and reset the counter. + + Mirrors `drain_busy`: an open wait segment is folded in up to `now` and + left open, so a child blocked across several intervals contributes to + each of them rather than dumping the whole wait into the interval it + finally gets a task in. + """ + if self.wait_since is not None: + self.wait_accumulated += max(0.0, now - self.wait_since) + self.wait_since = now + banked = self.wait_accumulated + self.wait_accumulated = 0.0 + return banked + class PushTaskWorker: _mp_context: ForkContext | SpawnContext | ForkServerContext @@ -970,15 +1059,45 @@ def _emit_periodic_metrics(self) -> None: } busy_time = 0.0 + wait_time = 0.0 for child in self._children.values(): state_counts[child.state] += 1 busy_time += child.drain_busy(now) + wait_time += child.drain_wait(now) exiting_children = len(self._exiting_children) elapsed = now - self._last_occupancy_flush_at self._last_occupancy_flush_at = now + # Emitted unconditionally, including during warmup, because they are + # counters: an interval with no running children contributes zero to + # both and is indistinguishable from not being scraped, which is the + # correct behaviour. The occupancy gauge below still has to skip warmup, + # since a zero there is a real value that drags the fleet average down. + self._metrics.distribution( + "taskworker.worker.child_busy_seconds", + busy_time, + tags=tags, + ) + self._metrics.distribution( + "taskworker.worker.child_wait_seconds", + wait_time, + tags=tags, + ) + if self._prom is not None: + # inc(0.0) is deliberate rather than guarded. It registers the + # labelled series on the first flush, so a pod that has not done any + # work yet still exposes both counters at zero. Without that the + # scaler sees the series appear only once a pod gets busy, and a + # brand new pod reads as missing rather than as idle. + self._prom.child_busy_seconds.labels(processing_pool=self._processing_pool_name).inc( + max(0.0, busy_time) + ) + self._prom.child_wait_seconds.labels(processing_pool=self._processing_pool_name).inc( + max(0.0, wait_time) + ) + running_count = state_counts["running"] if running_count > 0 and elapsed > 0: occupancy = busy_time / (elapsed * running_count) @@ -1161,19 +1280,27 @@ def spawn_children_thread() -> None: # This child is now running if message.event == "running": child.state = "running" + child.mark_running(message.timestamp) # This child wants to exit, but we may not have enough running children to shut down right away elif message.event == "exiting": self._exiting_children.append(message.child_id) - # This child started executing a task: open a busy segment. + # This child started executing a task: close the wait + # segment and open a busy one. + # + # These use the child's own timestamp, not the time + # this loop happens to drain the queue. This thread + # sleeps 100ms per iteration, so stamping here rounded + # every boundary up to the next drain tick and credited + # the work to the wrong flush interval. elif message.event == "busy": - child.mark_busy(time.monotonic()) + child.mark_busy(message.timestamp) # This child finished a task: close the open busy segment # and bank the elapsed time. elif message.event == "idle": - child.mark_idle(time.monotonic()) + child.mark_idle(message.timestamp) while True: # Compute how many children are still running @@ -1195,6 +1322,7 @@ def spawn_children_thread() -> None: continue child.state = "exiting" + child.mark_stopped(time.monotonic()) child.release.set() spawned = sum(1 for c in self._children.values() if c.state != "exiting") diff --git a/clients/python/src/taskbroker_client/worker/workerchild.py b/clients/python/src/taskbroker_client/worker/workerchild.py index ac029f19..c13e84b7 100644 --- a/clients/python/src/taskbroker_client/worker/workerchild.py +++ b/clients/python/src/taskbroker_client/worker/workerchild.py @@ -8,7 +8,7 @@ import threading import time from collections.abc import Callable, Generator, Sequence -from dataclasses import dataclass +from dataclasses import dataclass, field from functools import partial from multiprocessing.synchronize import Event from types import FrameType @@ -170,6 +170,29 @@ def _log_task_retry_exhausted( class ChildMessage: child_id: UUID event: Literal["running", "exiting", "busy", "idle"] + # Stamped here, in the child, at the moment the event happens. + # + # The parent used to stamp these when it drained the queue, which it does + # from spawn_children_thread on a 100ms sleep, competing for the GIL with + # the gRPC servicer and the result thread. Every segment boundary therefore + # landed on a drain tick rather than on the event, and the work was credited + # to whichever flush interval the parent happened to read the message in + # rather than the one it happened in. + # + # That misattribution is not symmetric in its effect on occupancy, because + # occupancy is a per-interval ratio clamped to 1.0: an interval credited too + # much work is clipped, an interval credited too little is not floored. So + # anything that makes attribution bursty biases occupancy down, and drain + # lag gets burstier the more loaded the pod is. + # + # time.monotonic() is CLOCK_MONOTONIC, which is system-wide on Linux and + # macOS rather than per-process, so a value stamped in a forked child is + # directly comparable to one read in the parent. + # + # compare=False so two messages describing the same event stay equal. The + # timestamp is payload, not identity, and callers match on child_id and + # event. + timestamp: float = field(default_factory=time.monotonic, compare=False) def child_process( diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 9045ab04..0e22c73f 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1280,6 +1280,8 @@ def _make_tracked_child( *, busy_since: float | None = None, busy_accumulated: float = 0.0, + wait_since: float | None = None, + wait_accumulated: float = 0.0, ) -> TrackedChild: return TrackedChild( process=mock.Mock(), @@ -1287,9 +1289,15 @@ def _make_tracked_child( release=mock.Mock(), busy_since=busy_since, busy_accumulated=busy_accumulated, + wait_since=wait_since, + wait_accumulated=wait_accumulated, ) +def _distribution_calls(metrics: mock.Mock, name: str) -> list[Any]: + return [c for c in metrics.distribution.call_args_list if c.args[0] == name] + + def _gauge_calls(metrics: mock.Mock, name: str) -> list[Any]: return [c for c in metrics.gauge.call_args_list if c.args[0] == name] @@ -1416,6 +1424,187 @@ def test_spawn_children_tracks_busy_and_idle_transitions() -> None: pool.shutdown() +def test_tracked_child_records_real_widths_for_events_in_one_batch() -> None: + # The regression this change exists for. + # + # spawn_children_thread drains the child message queue on a 100ms sleep, so + # a child running 50ms tasks delivers several busy/idle pairs per drain. The + # parent used to stamp all of them with the drain time, which collapsed + # every segment inside the batch to zero width and left the whole interval + # credited to whichever segment happened to span the drain boundary. Total + # busy time survived that, but the per-interval split did not, and occupancy + # is computed per interval and clipped at 1.0. + # + # Two 50ms tasks with a 10ms gap, all delivered at once: + child = _make_tracked_child("running", wait_since=100.00) + + child.mark_busy(100.00) + child.mark_idle(100.05) + child.mark_busy(100.06) + child.mark_idle(100.11) + + # 0.05 + 0.05 of work, and the 0.01 gap between them counted as waiting. + assert child.busy_accumulated == pytest.approx(0.10) + assert child.wait_accumulated == pytest.approx(0.01) + + +def test_tracked_child_busy_and_wait_partition_the_interval() -> None: + # A running child is always in exactly one of the two states, so over an + # interval with no state changes the two drains must sum to its width. + child = _make_tracked_child("running", wait_since=10.0) + + child.mark_busy(10.4) + busy = child.drain_busy(11.0) + wait = child.drain_wait(11.0) + + assert busy == pytest.approx(0.6) + assert wait == pytest.approx(0.4) + assert busy + wait == pytest.approx(1.0) + + # Both open segments are carried forward rather than restarted at zero. + assert child.busy_since == pytest.approx(11.0) + assert child.wait_since is None + + +def test_tracked_child_ignores_events_older_than_the_last_drain() -> None: + # Child timestamps and the parent's drain clock can cross: drain_busy folds + # an open segment forward to the parent's `now`, and a message stamped just + # before that can be processed just after. The delta is then negative and + # would silently subtract already-credited time. + child = _make_tracked_child("running", busy_since=10.0) + + child.drain_busy(11.0) # credits 1.0s, advances busy_since to 11.0 + child.mark_idle(10.95) # stamped before the drain, delivered after + + assert child.busy_accumulated == pytest.approx(0.0) + + +def test_tracked_child_stops_accruing_wait_once_released() -> None: + # A child released to shut down stops sending messages, so an open wait + # segment would fold forward on every drain forever and make a pool that is + # recycling children look starved for work. + child = _make_tracked_child("running", wait_since=10.0) + + child.mark_stopped(10.5) + assert child.drain_wait(20.0) == pytest.approx(0.5) + assert child.drain_wait(30.0) == pytest.approx(0.0) + + +def test_tracked_child_pending_accrues_neither_busy_nor_wait() -> None: + # Warmup is not starvation. A child importing the app has no slot to fill. + child = _make_tracked_child("pending") + + assert child.drain_busy(11.0) == pytest.approx(0.0) + assert child.drain_wait(11.0) == pytest.approx(0.0) + + child.mark_running(11.0) + assert child.drain_wait(12.0) == pytest.approx(1.0) + + +def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: + # Interval [10.0, 11.0], two running children: one busy throughout, one that + # spent 0.25s of it waiting for a task that never arrived. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = _make_tracked_child( + "running", busy_accumulated=0.75, wait_since=10.75 + ) + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + busy = _distribution_calls(pool._metrics, "taskworker.worker.child_busy_seconds") + wait = _distribution_calls(pool._metrics, "taskworker.worker.child_wait_seconds") + assert len(busy) == 1 and len(wait) == 1 + assert busy[0].args[1] == pytest.approx(1.75) + assert wait[0].args[1] == pytest.approx(0.25) + + # The pair is what the scaler divides, and it recovers the same answer the + # occupancy gauge reports without depending on the flush interval or on the + # running-child count. + assert busy[0].args[1] / (busy[0].args[1] + wait[0].args[1]) == pytest.approx(0.875) + occupancy_calls = _gauge_calls(pool._metrics, "taskworker.worker.occupancy") + assert occupancy_calls[0].args[1] == pytest.approx(1.75 / 2) + + +def test_emit_periodic_metrics_emits_counters_during_warmup() -> None: + # Unlike occupancy, these are emitted even with no running children. A zero + # contribution from a warming pod is correct for a counter and is what lets + # the scaler tell "idle" apart from "not reporting". + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("pending") + + pool._emit_periodic_metrics() + + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy") == [] + assert len(_distribution_calls(pool._metrics, "taskworker.worker.child_busy_seconds")) == 1 + assert len(_distribution_calls(pool._metrics, "taskworker.worker.child_wait_seconds")) == 1 + + +def test_spawn_children_uses_the_child_timestamp_not_the_drain_time() -> None: + fake_context = _FakeContext() + pool = _make_fake_context_pool(fake_context, concurrency=1) + + pool.start_spawn_children_thread() + try: + _wait_for(lambda: len(fake_context.processes) == 1) + messages = fake_context.queues[-1] + child_id = fake_context.processes[0].args[0] + + messages.put(ChildMessage(child_id, "running")) + _wait_for(lambda: pool.ready_count == 1) + + stamped_at = time.monotonic() - 5.0 + messages.put(ChildMessage(child_id, "busy", timestamp=stamped_at)) + _wait_for(lambda: pool._children[child_id].busy_since is not None) + + # The drain happens up to 100ms later and on a different thread; the + # segment has to start when the child said it did. + assert pool._children[child_id].busy_since == pytest.approx(stamped_at) + finally: + pool.shutdown() + + +def test_spawn_children_tracks_wait_between_tasks() -> None: + fake_context = _FakeContext() + pool = _make_fake_context_pool(fake_context, concurrency=1) + + pool.start_spawn_children_thread() + try: + _wait_for(lambda: len(fake_context.processes) == 1) + messages = fake_context.queues[-1] + child_id = fake_context.processes[0].args[0] + + base = time.monotonic() - 10.0 + + # Reporting in opens a wait segment: the child is available and blocked + # in child_tasks.get(). + messages.put(ChildMessage(child_id, "running", timestamp=base)) + _wait_for(lambda: pool._children[child_id].wait_since == pytest.approx(base)) + + # 2s of waiting, then 1s of work, then waiting again. + messages.put(ChildMessage(child_id, "busy", timestamp=base + 2.0)) + messages.put(ChildMessage(child_id, "idle", timestamp=base + 3.0)) + # `wait_since` is already set by the "running" message above, so wait on + # the banked busy time, which only lands once "idle" is processed. + _wait_for(lambda: pool._children[child_id].busy_accumulated > 0) + + child = pool._children[child_id] + assert child.wait_accumulated == pytest.approx(2.0) + assert child.busy_accumulated == pytest.approx(1.0) + assert child.busy_since is None + assert child.wait_since == pytest.approx(base + 3.0) + finally: + pool.shutdown() + + def test_spawn_children_counts_pending_children_toward_concurrency() -> None: fake_context = _FakeContext() pool = _make_fake_context_pool(fake_context, concurrency=2) From ac731850ee8e1161401672868226e6d4b7eaeb3e Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Fri, 28 Aug 2026 16:37:59 -0400 Subject: [PATCH 02/17] comment --- .../src/taskbroker_client/worker/worker.py | 82 ++++--------------- .../taskbroker_client/worker/workerchild.py | 25 +----- clients/python/tests/worker/test_worker.py | 53 ++++-------- 3 files changed, 37 insertions(+), 123 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index c5c6572c..901e68dd 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -132,22 +132,8 @@ def __init__( registry=self.registry, ) - # Counters, not a ratio gauge. The gauge above is sampled per pod and - # then averaged across pods by the scaler, which is an unweighted mean of - # ratios and is not the pool's occupancy. These two are additive, so a - # scaler can sum them across pods first and divide once: - # - # busy_rate / (busy_rate + wait_rate) - # - # They are also unclamped, which matters more than it sounds. Occupancy - # is clipped to 1.0 per interval, so an interval that over-counts loses - # the excess while one that under-counts keeps the deficit. Work landing - # in a neighbouring interval therefore drags the average down instead of - # cancelling out. Summing counters over the scaler's rate window has no - # such ceiling, so the same misattribution cancels. - # - # And a missed scrape shows up as a flat rate rather than as a - # plausible-looking low occupancy that triggers a scale down. + # Additive and unclamped, unlike the gauge above: the scaler sums across + # pods and divides once, and no interval clips at 1.0. self.child_busy_seconds = prometheus_client.Counter( "taskworker_worker_child_busy_seconds", "Cumulative child-seconds spent executing tasks.", @@ -155,11 +141,8 @@ def __init__( registry=self.registry, ) - # The signal occupancy cannot express on its own: child slots that are - # available and have nothing to do. If this is near zero while a backlog - # exists, the pod is saturated no matter what occupancy reports, and more - # pods will help. If it is large, the pod is starved and more pods will - # only add idle children. + # What occupancy cannot express: slots that are free with nothing to do. + # Near zero under a backlog means saturated, so more pods help. self.child_wait_seconds = prometheus_client.Counter( "taskworker_worker_child_wait_seconds", "Cumulative child-seconds spent blocked waiting for a task to arrive.", @@ -249,24 +232,13 @@ class TrackedChild: # 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 - # Time-weighted wait tracking, the mirror of the two fields above. A running - # child is always in exactly one of the two states: executing a task, or - # blocked in `child_tasks.get()` with nothing to execute. - # - # Wait is tracked separately rather than inferred as `elapsed - busy` because - # the inference is only valid for children that were running for the whole - # interval. Children spawn, warm up, and exit mid-interval, and those - # transitions are exactly when a pool is scaling, which is when the signal - # has to be trustworthy. + # Mirror of the two fields above. Measured rather than inferred as + # `elapsed - busy`, which only holds for children running the whole interval. wait_since: float | None = None # monotonic timestamp of the currently-open wait segment wait_accumulated: float = 0.0 # the waiting seconds banked since the last flush def mark_running(self, now: float) -> None: - """Start counting wait time once the child has finished warming up. - - A `pending` child is importing the app, not starving for work, so it - accrues neither busy nor wait until it reports in. - """ + """Start the wait clock: a `pending` child is importing, not starving.""" if self.busy_since is None and self.wait_since is None: self.wait_since = now @@ -296,12 +268,7 @@ def mark_idle(self, now: float) -> None: self.wait_since = now def mark_stopped(self, now: float) -> None: - """Close both segments when the child is released to shut down. - - Without this a released child keeps an open wait segment that folds - forward on every drain, so a pool that is recycling children would look - starved for work when it is not. - """ + """Close both segments so a released child stops folding wait forward.""" if self.busy_since is not None: self.busy_accumulated += max(0.0, now - self.busy_since) self.busy_since = None @@ -324,13 +291,7 @@ def drain_busy(self, now: float) -> float: return banked def drain_wait(self, now: float) -> float: - """Return waiting seconds since the last drain and reset the counter. - - Mirrors `drain_busy`: an open wait segment is folded in up to `now` and - left open, so a child blocked across several intervals contributes to - each of them rather than dumping the whole wait into the interval it - finally gets a task in. - """ + """Mirror of `drain_busy`, so a long block counts in every interval it spans.""" if self.wait_since is not None: self.wait_accumulated += max(0.0, now - self.wait_since) self.wait_since = now @@ -1070,11 +1031,8 @@ def _emit_periodic_metrics(self) -> None: elapsed = now - self._last_occupancy_flush_at self._last_occupancy_flush_at = now - # Emitted unconditionally, including during warmup, because they are - # counters: an interval with no running children contributes zero to - # both and is indistinguishable from not being scraped, which is the - # correct behaviour. The occupancy gauge below still has to skip warmup, - # since a zero there is a real value that drags the fleet average down. + # Emitted during warmup too: zero is correct for a counter, unlike for + # the occupancy gauge below where it drags the fleet average down. self._metrics.distribution( "taskworker.worker.child_busy_seconds", busy_time, @@ -1086,11 +1044,8 @@ def _emit_periodic_metrics(self) -> None: tags=tags, ) if self._prom is not None: - # inc(0.0) is deliberate rather than guarded. It registers the - # labelled series on the first flush, so a pod that has not done any - # work yet still exposes both counters at zero. Without that the - # scaler sees the series appear only once a pod gets busy, and a - # brand new pod reads as missing rather than as idle. + # inc(0.0) registers the series on the first flush, so a new pod + # reads as idle rather than as missing. self._prom.child_busy_seconds.labels(processing_pool=self._processing_pool_name).inc( max(0.0, busy_time) ) @@ -1286,14 +1241,9 @@ def spawn_children_thread() -> None: elif message.event == "exiting": self._exiting_children.append(message.child_id) - # This child started executing a task: close the wait - # segment and open a busy one. - # - # These use the child's own timestamp, not the time - # this loop happens to drain the queue. This thread - # sleeps 100ms per iteration, so stamping here rounded - # every boundary up to the next drain tick and credited - # the work to the wrong flush interval. + # Close the wait segment and open a busy one, at the + # child's timestamp: this loop drains on a 100ms sleep, + # so stamping here credits work to the wrong interval. elif message.event == "busy": child.mark_busy(message.timestamp) diff --git a/clients/python/src/taskbroker_client/worker/workerchild.py b/clients/python/src/taskbroker_client/worker/workerchild.py index c13e84b7..3229132e 100644 --- a/clients/python/src/taskbroker_client/worker/workerchild.py +++ b/clients/python/src/taskbroker_client/worker/workerchild.py @@ -170,28 +170,9 @@ def _log_task_retry_exhausted( class ChildMessage: child_id: UUID event: Literal["running", "exiting", "busy", "idle"] - # Stamped here, in the child, at the moment the event happens. - # - # The parent used to stamp these when it drained the queue, which it does - # from spawn_children_thread on a 100ms sleep, competing for the GIL with - # the gRPC servicer and the result thread. Every segment boundary therefore - # landed on a drain tick rather than on the event, and the work was credited - # to whichever flush interval the parent happened to read the message in - # rather than the one it happened in. - # - # That misattribution is not symmetric in its effect on occupancy, because - # occupancy is a per-interval ratio clamped to 1.0: an interval credited too - # much work is clipped, an interval credited too little is not floored. So - # anything that makes attribution bursty biases occupancy down, and drain - # lag gets burstier the more loaded the pod is. - # - # time.monotonic() is CLOCK_MONOTONIC, which is system-wide on Linux and - # macOS rather than per-process, so a value stamped in a forked child is - # directly comparable to one read in the parent. - # - # compare=False so two messages describing the same event stay equal. The - # timestamp is payload, not identity, and callers match on child_id and - # event. + # Stamped at the event, not when the parent drains it 100ms later. + # CLOCK_MONOTONIC is system-wide, so a child's stamp is valid in the parent. + # compare=False: the timestamp is payload, not identity. timestamp: float = field(default_factory=time.monotonic, compare=False) diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 0e22c73f..4e58d7a2 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1425,17 +1425,8 @@ def test_spawn_children_tracks_busy_and_idle_transitions() -> None: def test_tracked_child_records_real_widths_for_events_in_one_batch() -> None: - # The regression this change exists for. - # - # spawn_children_thread drains the child message queue on a 100ms sleep, so - # a child running 50ms tasks delivers several busy/idle pairs per drain. The - # parent used to stamp all of them with the drain time, which collapsed - # every segment inside the batch to zero width and left the whole interval - # credited to whichever segment happened to span the drain boundary. Total - # busy time survived that, but the per-interval split did not, and occupancy - # is computed per interval and clipped at 1.0. - # - # Two 50ms tasks with a 10ms gap, all delivered at once: + # The regression this change exists for: stamping at drain time collapsed + # every segment in a batch to zero width. Two 50ms tasks, 10ms apart: child = _make_tracked_child("running", wait_since=100.00) child.mark_busy(100.00) @@ -1449,8 +1440,8 @@ def test_tracked_child_records_real_widths_for_events_in_one_batch() -> None: def test_tracked_child_busy_and_wait_partition_the_interval() -> None: - # A running child is always in exactly one of the two states, so over an - # interval with no state changes the two drains must sum to its width. + # A running child is always in exactly one state, so the drains must sum + # to the interval width. child = _make_tracked_child("running", wait_since=10.0) child.mark_busy(10.4) @@ -1467,10 +1458,8 @@ def test_tracked_child_busy_and_wait_partition_the_interval() -> None: def test_tracked_child_ignores_events_older_than_the_last_drain() -> None: - # Child timestamps and the parent's drain clock can cross: drain_busy folds - # an open segment forward to the parent's `now`, and a message stamped just - # before that can be processed just after. The delta is then negative and - # would silently subtract already-credited time. + # drain_busy folds forward to the parent's clock, so a message stamped just + # before that and processed just after must not subtract credited time. child = _make_tracked_child("running", busy_since=10.0) child.drain_busy(11.0) # credits 1.0s, advances busy_since to 11.0 @@ -1480,9 +1469,8 @@ def test_tracked_child_ignores_events_older_than_the_last_drain() -> None: def test_tracked_child_stops_accruing_wait_once_released() -> None: - # A child released to shut down stops sending messages, so an open wait - # segment would fold forward on every drain forever and make a pool that is - # recycling children look starved for work. + # A released child stops sending messages, so an open wait segment would + # fold forward forever and make a recycling pool look starved. child = _make_tracked_child("running", wait_since=10.0) child.mark_stopped(10.5) @@ -1491,7 +1479,7 @@ def test_tracked_child_stops_accruing_wait_once_released() -> None: def test_tracked_child_pending_accrues_neither_busy_nor_wait() -> None: - # Warmup is not starvation. A child importing the app has no slot to fill. + # Warmup is not starvation: a child importing the app has no slot to fill. child = _make_tracked_child("pending") assert child.drain_busy(11.0) == pytest.approx(0.0) @@ -1502,8 +1490,7 @@ def test_tracked_child_pending_accrues_neither_busy_nor_wait() -> None: def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: - # Interval [10.0, 11.0], two running children: one busy throughout, one that - # spent 0.25s of it waiting for a task that never arrived. + # Interval [10.0, 11.0]: one child busy throughout, one waiting 0.25s. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() pool._last_occupancy_flush_at = 10.0 @@ -1523,18 +1510,16 @@ def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: assert busy[0].args[1] == pytest.approx(1.75) assert wait[0].args[1] == pytest.approx(0.25) - # The pair is what the scaler divides, and it recovers the same answer the - # occupancy gauge reports without depending on the flush interval or on the - # running-child count. + # The scaler divides the pair, recovering occupancy without needing the + # flush interval or the running-child count. assert busy[0].args[1] / (busy[0].args[1] + wait[0].args[1]) == pytest.approx(0.875) occupancy_calls = _gauge_calls(pool._metrics, "taskworker.worker.occupancy") assert occupancy_calls[0].args[1] == pytest.approx(1.75 / 2) def test_emit_periodic_metrics_emits_counters_during_warmup() -> None: - # Unlike occupancy, these are emitted even with no running children. A zero - # contribution from a warming pod is correct for a counter and is what lets - # the scaler tell "idle" apart from "not reporting". + # Emitted with no running children, unlike occupancy: zero is correct for a + # counter and separates "idle" from "not reporting". pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() @@ -1565,8 +1550,8 @@ def test_spawn_children_uses_the_child_timestamp_not_the_drain_time() -> None: messages.put(ChildMessage(child_id, "busy", timestamp=stamped_at)) _wait_for(lambda: pool._children[child_id].busy_since is not None) - # The drain happens up to 100ms later and on a different thread; the - # segment has to start when the child said it did. + # The drain lands up to 100ms later on another thread; the segment has + # to start when the child said it did. assert pool._children[child_id].busy_since == pytest.approx(stamped_at) finally: pool.shutdown() @@ -1584,16 +1569,14 @@ def test_spawn_children_tracks_wait_between_tasks() -> None: base = time.monotonic() - 10.0 - # Reporting in opens a wait segment: the child is available and blocked - # in child_tasks.get(). + # Reporting in opens a wait segment: available, blocked in get(). messages.put(ChildMessage(child_id, "running", timestamp=base)) _wait_for(lambda: pool._children[child_id].wait_since == pytest.approx(base)) # 2s of waiting, then 1s of work, then waiting again. messages.put(ChildMessage(child_id, "busy", timestamp=base + 2.0)) messages.put(ChildMessage(child_id, "idle", timestamp=base + 3.0)) - # `wait_since` is already set by the "running" message above, so wait on - # the banked busy time, which only lands once "idle" is processed. + # `wait_since` is already set by "running" above, so wait on banked busy. _wait_for(lambda: pool._children[child_id].busy_accumulated > 0) child = pool._children[child_id] From a9716c20ef032a4c2cc8fad8507273482d70598e Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Mon, 31 Aug 2026 19:48:32 -0400 Subject: [PATCH 03/17] Stop double billing child busy and wait time 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. --- .../src/taskbroker_client/worker/worker.py | 76 ++++++++++++++- clients/python/tests/worker/test_worker.py | 93 ++++++++++++++++++- 2 files changed, 163 insertions(+), 6 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 901e68dd..56a94964 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -236,9 +236,28 @@ class TrackedChild: # `elapsed - busy`, which only holds for children running the whole interval. wait_since: float | None = None # monotonic timestamp of the currently-open wait segment wait_accumulated: float = 0.0 # the waiting seconds banked since the last flush + # Everything up to here has already been drained and emitted. Segment + # boundaries stamped earlier than this are clamped forward to it. 0.0 means + # "never drained"; time.monotonic() is always well above it, so a child that + # has not been flushed yet accepts its events verbatim. + last_drained_at: float = 0.0 + + def _clamp(self, now: float) -> float: + """Never let a segment boundary land inside an already-emitted interval. + + 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* + the drain that already accounted for that time. Honouring the stale + stamp would re-bill those seconds: `mark_busy` would clip the wait + closure to zero, leaving the emitted wait in place, and then open a + busy segment starting back inside it. Both counters then bill the same + wall clock, which is unbounded when the event backlog grows. + """ + return max(now, self.last_drained_at) def mark_running(self, now: float) -> None: """Start the wait clock: a `pending` child is importing, not starving.""" + now = self._clamp(now) if self.busy_since is None and self.wait_since is None: self.wait_since = now @@ -249,6 +268,7 @@ def mark_busy(self, now: float) -> None: should never already be open; the guard is defensive and keeps the original start time if that invariant ever drifts. """ + now = self._clamp(now) if self.wait_since is not None: self.wait_accumulated += max(0.0, now - self.wait_since) self.wait_since = None @@ -261,6 +281,7 @@ def mark_idle(self, now: float) -> None: Guarded so an unexpected `idle` with no open segment is a no-op rather than a crash. """ + now = self._clamp(now) if self.busy_since is not None: self.busy_accumulated += max(0.0, now - self.busy_since) self.busy_since = None @@ -269,6 +290,7 @@ def mark_idle(self, now: float) -> None: def mark_stopped(self, now: float) -> None: """Close both segments so a released child stops folding wait forward.""" + now = self._clamp(now) if self.busy_since is not None: self.busy_accumulated += max(0.0, now - self.busy_since) self.busy_since = None @@ -286,6 +308,7 @@ def drain_busy(self, now: float) -> float: if self.busy_since is not None: self.busy_accumulated += max(0.0, now - self.busy_since) self.busy_since = now + self.last_drained_at = now banked = self.busy_accumulated self.busy_accumulated = 0.0 return banked @@ -295,6 +318,7 @@ def drain_wait(self, now: float) -> float: if self.wait_since is not None: self.wait_accumulated += max(0.0, now - self.wait_since) self.wait_since = now + self.last_drained_at = now banked = self.wait_accumulated self.wait_accumulated = 0.0 return banked @@ -1023,6 +1047,16 @@ def _emit_periodic_metrics(self) -> None: wait_time = 0.0 for child in self._children.values(): state_counts[child.state] += 1 + + # Running children only: occupancy divides by `running_count`, + # so folding a `pending` or `exiting` child into the numerator + # measures one population against another. Neither has time to + # lose here. A `pending` child has not opened a segment yet, + # and `mark_stopped` deliberately closes an `exiting` child's + # segments so its tail stops counting against the live pool. + if child.state != "running": + continue + busy_time += child.drain_busy(now) wait_time += child.drain_wait(now) @@ -1055,7 +1089,30 @@ def _emit_periodic_metrics(self) -> None: running_count = state_counts["running"] if running_count > 0 and elapsed > 0: - occupancy = busy_time / (elapsed * running_count) + # A child cannot be busy for longer than the interval, so this is a + # hard physical bound on both counters. Exceeding it means the + # accounting is double billing, and the clamp below would hide that + # behind a healthy-looking 1.0. Emit it so the metric cannot lie + # silently again. + ceiling = elapsed * running_count + if busy_time > ceiling or wait_time > ceiling: + self._metrics.incr( + "taskworker.worker.occupancy.accounting_overflow", + tags=tags, + ) + logger.warning( + "taskworker.worker.occupancy.accounting_overflow", + extra={ + "busy_time": busy_time, + "wait_time": wait_time, + "ceiling": ceiling, + "running_count": running_count, + "elapsed": elapsed, + "processing_pool": self._processing_pool_name, + }, + ) + + occupancy = busy_time / ceiling occupancy = min(occupancy, 1.0) self._metrics.gauge( "taskworker.worker.occupancy", @@ -1195,6 +1252,23 @@ def spawn_children_thread() -> None: except queue.Empty: break + # How stale the events we are about to apply are. The clamp in + # `TrackedChild._clamp` keeps busy + wait conserved when this + # loop falls behind, but it cannot recover *when* the work + # happened, so occupancy lags by roughly this age. Flat and + # sub-second is healthy; a rising line means this thread is not + # keeping up with the children and the signal is going stale. + if received: + drain_at = time.monotonic() + self._metrics.distribution( + "taskworker.worker.child_message.age", + drain_at - min(m.timestamp for m in received), + tags={ + "processing_pool": self._processing_pool_name, + "pod_name": self._pod_name, + }, + ) + with self._children_lock: children = list(self._children.items()) diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 4e58d7a2..5cb3f073 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1298,6 +1298,10 @@ def _distribution_calls(metrics: mock.Mock, name: str) -> list[Any]: return [c for c in metrics.distribution.call_args_list if c.args[0] == name] +def _incr_calls(metrics: mock.Mock, name: str) -> list[Any]: + return [c for c in metrics.incr.call_args_list if c.args[0] == name] + + def _gauge_calls(metrics: mock.Mock, name: str) -> list[Any]: return [c for c in metrics.gauge.call_args_list if c.args[0] == name] @@ -1378,16 +1382,18 @@ def test_emit_periodic_metrics_divides_by_running_children() -> None: assert occupancy_calls[0].args[1] == pytest.approx(2 / 3) -def test_emit_periodic_metrics_clamps_occupancy_to_one() -> None: - # A draining child can still be mid-task, so busy-time can exceed the running - # capacity for the interval; occupancy must clamp to 1.0. +def test_emit_periodic_metrics_clamps_occupancy_and_flags_the_overflow() -> None: + # A child cannot be busy for longer than the interval, so 1.5s of busy over + # a 1s interval is an accounting fault, not a busy pool. Occupancy still has + # to clamp for KEDA, but the fault must be visible: reading a healthy 1.0 + # while the numerator is nonsense is how the double-billing bug hid. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() pool._last_occupancy_flush_at = 10.0 with pool._children_lock: - pool._children[uuid4()] = _make_tracked_child("running", busy_accumulated=1.0) - pool._children[uuid4()] = _make_tracked_child("exiting", busy_accumulated=1.0) + pool._children[uuid4()] = _make_tracked_child("running", busy_accumulated=1.5) + pool._children[uuid4()] = _make_tracked_child("running", busy_accumulated=1.5) with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): pool._emit_periodic_metrics() @@ -1395,6 +1401,49 @@ def test_emit_periodic_metrics_clamps_occupancy_to_one() -> None: occupancy_calls = _gauge_calls(pool._metrics, "taskworker.worker.occupancy") assert len(occupancy_calls) == 1 assert occupancy_calls[0].args[1] == pytest.approx(1.0) + assert len(_incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow")) == 1 + + +def test_emit_periodic_metrics_does_not_flag_a_legitimately_full_pool() -> None: + # The guard must not fire on a pool that is simply saturated, or it is noise. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( + 1.0 + ) + assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] + + +def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: + # occupancy divides by running_count, so the counters have to sum over the + # same population. An exiting child folded into the numerator inflates both + # the counters and the gauge against slots that are no longer taking work. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = _make_tracked_child("exiting", busy_accumulated=1.0) + pool._children[uuid4()] = _make_tracked_child("pending") + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + busy = _distribution_calls(pool._metrics, "taskworker.worker.child_busy_seconds") + assert busy[0].args[1] == pytest.approx(1.0) + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( + 1.0 + ) def test_spawn_children_tracks_busy_and_idle_transitions() -> None: @@ -1468,6 +1517,40 @@ def test_tracked_child_ignores_events_older_than_the_last_drain() -> None: assert child.busy_accumulated == pytest.approx(0.0) +def test_tracked_child_stale_event_cannot_bill_an_interval_twice() -> None: + # The regression found in the sandbox sweep. The parent reads child events + # on a 100ms loop while the metrics thread drains on a 1s cadence, so a + # `busy` stamped at 10.2 can arrive after the 11.0 drain has already billed + # 10.2-11.0 as wait. Backdating busy_since to 10.2 then bills those same + # 0.8s again as busy, and the error grows with the event backlog: the sweep + # measured 580 busy-seconds per 1s flush across 24 children, 24x the + # physical ceiling, which the occupancy clamp turned into a healthy 1.0. + child = _make_tracked_child("running", wait_since=10.0) + + assert child.drain_wait(11.0) == pytest.approx(1.0) + assert child.drain_busy(11.0) == pytest.approx(0.0) + + child.mark_busy(10.2) # stamped before the drain, delivered after it + + busy = child.drain_busy(12.0) + wait = child.drain_wait(12.0) + + # The second interval is 1s wide and cannot yield more than 1s of credit. + assert busy == pytest.approx(1.0) + assert wait == pytest.approx(0.0) + + +def test_tracked_child_accepts_events_predating_its_first_drain() -> None: + # The watermark starts at 0.0 so a child that has never been flushed still + # records real segment widths rather than collapsing them to the drain time. + child = _make_tracked_child("running", wait_since=10.0) + + child.mark_busy(10.4) + + assert child.drain_wait(11.0) == pytest.approx(0.4) + assert child.drain_busy(11.0) == pytest.approx(0.6) + + def test_tracked_child_stops_accruing_wait_once_released() -> None: # A released child stops sending messages, so an open wait segment would # fold forward forever and make a recycling pool look starved. From b64314dcc03e8a5feef2247f05db76a70d3ce39b Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Tue, 1 Sep 2026 14:39:12 -0400 Subject: [PATCH 04/17] move segment tracking to own class --- .../src/taskbroker_client/worker/worker.py | 154 +++++++++--------- clients/python/tests/worker/test_worker.py | 94 +++++------ 2 files changed, 127 insertions(+), 121 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 56a94964..630d6aa2 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -9,7 +9,7 @@ import time from collections import deque from concurrent.futures import ThreadPoolExecutor -from dataclasses import dataclass +from dataclasses import dataclass, field from multiprocessing.context import ForkContext, ForkServerContext, SpawnContext from multiprocessing.process import BaseProcess from multiprocessing.synchronize import Event @@ -225,105 +225,109 @@ class RequeueException(Exception): @dataclass -class TrackedChild: - process: BaseProcess - state: ChildState - release: Event - # 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 - # Mirror of the two fields above. Measured rather than inferred as - # `elapsed - busy`, which only holds for children running the whole interval. - wait_since: float | None = None # monotonic timestamp of the currently-open wait segment - wait_accumulated: float = 0.0 # the waiting seconds banked since the last flush - # Everything up to here has already been drained and emitted. Segment - # boundaries stamped earlier than this are clamped forward to it. 0.0 means - # "never drained"; time.monotonic() is always well above it, so a child that - # has not been flushed yet accepts its events verbatim. +class TimeSegment: + """Used to track a child proceses' time: either its busy clock or its wait clock. + + `since` is the monotonic start of the currently-open time segment, or None when + the time segment is closed. `accumulated` holds seconds banked but not yet + emitted. + """ + + since: float | None = None + accumulated: float = 0.0 + + def open(self, now: float) -> None: + """Start a segment, keeping the earlier start if one is already open.""" + if self.since is None: + self.since = now + + def close(self, now: float) -> None: + """Bank the open segment up to `now` and close it. No-op if closed.""" + if self.since is not None: + self.accumulated += max(0.0, now - self.since) + self.since = None + + def drain(self, now: float) -> float: + """Return banked seconds and reset, leaving an open time segment open. + + A still-open time segment is folded in up to `now` and restarted there, so a + task spanning several intervals contributes to each one. + """ + if self.since is not None: + self.accumulated += max(0.0, now - self.since) + self.since = now + banked = self.accumulated + self.accumulated = 0.0 + return banked + + +@dataclass +class ChildTimeAccounting: + """Time-weighted busy/wait accounting for one child. + + A running child is always in exactly one of the two states, so over any + interval `drain_busy` + `drain_wait` must sum to that interval's width. + + Wait time is measured rather than inferred as `elapsed - busy`, which only holds + for children that ran for the whole interval. + """ + + busy: TimeSegment = field(default_factory=TimeSegment) + wait: TimeSegment = field(default_factory=TimeSegment) last_drained_at: float = 0.0 def _clamp(self, now: float) -> float: """Never let a segment boundary land inside an already-emitted interval. - 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* - the drain that already accounted for that time. Honouring the stale - stamp would re-bill those seconds: `mark_busy` would clip the wait - closure to zero, leaving the emitted wait in place, and then open a - busy segment starting back inside it. Both counters then bill the same - wall clock, which is unbounded when the event backlog grows. + Only child-supplied timestamps need this. The time segment drains are driven by the + metrics thread's own monotonic clock, which never runs backwards. """ return max(now, self.last_drained_at) def mark_running(self, now: float) -> None: """Start the wait clock: a `pending` child is importing, not starving.""" - now = self._clamp(now) - if self.busy_since is None and self.wait_since is None: - self.wait_since = now + if self.busy.since is None and self.wait.since is None: + self.wait.open(self._clamp(now)) def mark_busy(self, now: float) -> None: - """Close the open wait segment and open a busy one. - - `busy`/`idle` strictly alternate per child today, so a busy segment - should never already be open; the guard is defensive and keeps the - original start time if that invariant ever drifts. - """ + """Close the open wait segment and open a busy one.""" now = self._clamp(now) - if self.wait_since is not None: - self.wait_accumulated += max(0.0, now - self.wait_since) - self.wait_since = None - if self.busy_since is None: - self.busy_since = now + self.wait.close(now) + self.busy.open(now) def mark_idle(self, now: float) -> None: - """Close the open busy segment and open a wait one. - - Guarded so an unexpected `idle` with no open segment is a no-op rather - than a crash. - """ + """Close the open busy segment and open a wait one.""" now = self._clamp(now) - if self.busy_since is not None: - self.busy_accumulated += max(0.0, now - self.busy_since) - self.busy_since = None - if self.wait_since is None: - self.wait_since = now + self.busy.close(now) + self.wait.open(now) def mark_stopped(self, now: float) -> None: """Close both segments so a released child stops folding wait forward.""" now = self._clamp(now) - if self.busy_since is not None: - self.busy_accumulated += max(0.0, now - self.busy_since) - self.busy_since = None - if self.wait_since is not None: - self.wait_accumulated += max(0.0, now - self.wait_since) - self.wait_since = None + self.busy.close(now) + self.wait.close(now) def drain_busy(self, now: float) -> float: - """Return busy seconds since the last drain and reset the counter. - - Any segment still open is folded in up to `now` and left open (its - start advanced to `now`) so a task spanning multiple intervals keeps - contributing to each one. - """ - if self.busy_since is not None: - self.busy_accumulated += max(0.0, now - self.busy_since) - self.busy_since = now + """Return busy seconds since the last drain and reset the counter.""" + banked = self.busy.drain(now) self.last_drained_at = now - banked = self.busy_accumulated - self.busy_accumulated = 0.0 return banked def drain_wait(self, now: float) -> float: """Mirror of `drain_busy`, so a long block counts in every interval it spans.""" - if self.wait_since is not None: - self.wait_accumulated += max(0.0, now - self.wait_since) - self.wait_since = now + banked = self.wait.drain(now) self.last_drained_at = now - banked = self.wait_accumulated - self.wait_accumulated = 0.0 return banked +@dataclass +class TrackedChild: + process: BaseProcess + state: ChildState + release: Event + timing: ChildTimeAccounting = field(default_factory=ChildTimeAccounting) + + class PushTaskWorker: _mp_context: ForkContext | SpawnContext | ForkServerContext @@ -1057,8 +1061,8 @@ def _emit_periodic_metrics(self) -> None: if child.state != "running": continue - busy_time += child.drain_busy(now) - wait_time += child.drain_wait(now) + busy_time += child.timing.drain_busy(now) + wait_time += child.timing.drain_wait(now) exiting_children = len(self._exiting_children) @@ -1309,7 +1313,7 @@ def spawn_children_thread() -> None: # This child is now running if message.event == "running": child.state = "running" - child.mark_running(message.timestamp) + child.timing.mark_running(message.timestamp) # This child wants to exit, but we may not have enough running children to shut down right away elif message.event == "exiting": @@ -1319,12 +1323,12 @@ def spawn_children_thread() -> None: # child's timestamp: this loop drains on a 100ms sleep, # so stamping here credits work to the wrong interval. elif message.event == "busy": - child.mark_busy(message.timestamp) + child.timing.mark_busy(message.timestamp) # This child finished a task: close the open busy segment # and bank the elapsed time. elif message.event == "idle": - child.mark_idle(message.timestamp) + child.timing.mark_idle(message.timestamp) while True: # Compute how many children are still running @@ -1346,7 +1350,7 @@ def spawn_children_thread() -> None: continue child.state = "exiting" - child.mark_stopped(time.monotonic()) + child.timing.mark_stopped(time.monotonic()) child.release.set() spawned = sum(1 for c in self._children.values() if c.state != "exiting") diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 5cb3f073..6efa8a04 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -44,10 +44,12 @@ from taskbroker_client.state import current_task from taskbroker_client.types import InflightTaskActivation, ProcessingResult from taskbroker_client.worker.worker import ( + ChildTimeAccounting, PushTaskWorker, ShutdownSignal, TaskWorker, TaskWorkerProcessingPool, + TimeSegment, TrackedChild, WorkerServicer, ) @@ -1287,10 +1289,10 @@ def _make_tracked_child( process=mock.Mock(), state=state, # type: ignore[arg-type] release=mock.Mock(), - busy_since=busy_since, - busy_accumulated=busy_accumulated, - wait_since=wait_since, - wait_accumulated=wait_accumulated, + timing=ChildTimeAccounting( + busy=TimeSegment(since=busy_since, accumulated=busy_accumulated), + wait=TimeSegment(since=wait_since, accumulated=wait_accumulated), + ), ) @@ -1354,9 +1356,9 @@ def test_emit_periodic_metrics_time_weights_busy_over_the_interval() -> None: assert occupancy_calls[0].args[1] == pytest.approx(1.24 / 3) # The open segment is carried into the next interval; banks are drained. - assert pool._children[child_b].busy_since == pytest.approx(11.0) + assert pool._children[child_b].timing.busy.since == pytest.approx(11.0) for child in pool._children.values(): - assert child.busy_accumulated == 0.0 + assert child.timing.busy.accumulated == 0.0 assert pool._last_occupancy_flush_at == pytest.approx(11.0) @@ -1461,13 +1463,13 @@ def test_spawn_children_tracks_busy_and_idle_transitions() -> None: # "busy" opens a segment. messages.put(ChildMessage(child_id, "busy")) - _wait_for(lambda: pool._children[child_id].busy_since is not None) + _wait_for(lambda: pool._children[child_id].timing.busy.since is not None) # "idle" closes it and banks a positive amount of busy-time. messages.put(ChildMessage(child_id, "idle")) _wait_for( - lambda: pool._children[child_id].busy_since is None - and pool._children[child_id].busy_accumulated > 0 + lambda: pool._children[child_id].timing.busy.since is None + and pool._children[child_id].timing.busy.accumulated > 0 ) finally: pool.shutdown() @@ -1478,14 +1480,14 @@ def test_tracked_child_records_real_widths_for_events_in_one_batch() -> None: # every segment in a batch to zero width. Two 50ms tasks, 10ms apart: child = _make_tracked_child("running", wait_since=100.00) - child.mark_busy(100.00) - child.mark_idle(100.05) - child.mark_busy(100.06) - child.mark_idle(100.11) + child.timing.mark_busy(100.00) + child.timing.mark_idle(100.05) + child.timing.mark_busy(100.06) + child.timing.mark_idle(100.11) # 0.05 + 0.05 of work, and the 0.01 gap between them counted as waiting. - assert child.busy_accumulated == pytest.approx(0.10) - assert child.wait_accumulated == pytest.approx(0.01) + assert child.timing.busy.accumulated == pytest.approx(0.10) + assert child.timing.wait.accumulated == pytest.approx(0.01) def test_tracked_child_busy_and_wait_partition_the_interval() -> None: @@ -1493,17 +1495,17 @@ def test_tracked_child_busy_and_wait_partition_the_interval() -> None: # to the interval width. child = _make_tracked_child("running", wait_since=10.0) - child.mark_busy(10.4) - busy = child.drain_busy(11.0) - wait = child.drain_wait(11.0) + child.timing.mark_busy(10.4) + busy = child.timing.drain_busy(11.0) + wait = child.timing.drain_wait(11.0) assert busy == pytest.approx(0.6) assert wait == pytest.approx(0.4) assert busy + wait == pytest.approx(1.0) # Both open segments are carried forward rather than restarted at zero. - assert child.busy_since == pytest.approx(11.0) - assert child.wait_since is None + assert child.timing.busy.since == pytest.approx(11.0) + assert child.timing.wait.since is None def test_tracked_child_ignores_events_older_than_the_last_drain() -> None: @@ -1511,10 +1513,10 @@ def test_tracked_child_ignores_events_older_than_the_last_drain() -> None: # before that and processed just after must not subtract credited time. child = _make_tracked_child("running", busy_since=10.0) - child.drain_busy(11.0) # credits 1.0s, advances busy_since to 11.0 - child.mark_idle(10.95) # stamped before the drain, delivered after + child.timing.drain_busy(11.0) # credits 1.0s, advances busy_since to 11.0 + child.timing.mark_idle(10.95) # stamped before the drain, delivered after - assert child.busy_accumulated == pytest.approx(0.0) + assert child.timing.busy.accumulated == pytest.approx(0.0) def test_tracked_child_stale_event_cannot_bill_an_interval_twice() -> None: @@ -1527,13 +1529,13 @@ def test_tracked_child_stale_event_cannot_bill_an_interval_twice() -> None: # physical ceiling, which the occupancy clamp turned into a healthy 1.0. child = _make_tracked_child("running", wait_since=10.0) - assert child.drain_wait(11.0) == pytest.approx(1.0) - assert child.drain_busy(11.0) == pytest.approx(0.0) + assert child.timing.drain_wait(11.0) == pytest.approx(1.0) + assert child.timing.drain_busy(11.0) == pytest.approx(0.0) - child.mark_busy(10.2) # stamped before the drain, delivered after it + child.timing.mark_busy(10.2) # stamped before the drain, delivered after it - busy = child.drain_busy(12.0) - wait = child.drain_wait(12.0) + busy = child.timing.drain_busy(12.0) + wait = child.timing.drain_wait(12.0) # The second interval is 1s wide and cannot yield more than 1s of credit. assert busy == pytest.approx(1.0) @@ -1545,10 +1547,10 @@ def test_tracked_child_accepts_events_predating_its_first_drain() -> None: # records real segment widths rather than collapsing them to the drain time. child = _make_tracked_child("running", wait_since=10.0) - child.mark_busy(10.4) + child.timing.mark_busy(10.4) - assert child.drain_wait(11.0) == pytest.approx(0.4) - assert child.drain_busy(11.0) == pytest.approx(0.6) + assert child.timing.drain_wait(11.0) == pytest.approx(0.4) + assert child.timing.drain_busy(11.0) == pytest.approx(0.6) def test_tracked_child_stops_accruing_wait_once_released() -> None: @@ -1556,20 +1558,20 @@ def test_tracked_child_stops_accruing_wait_once_released() -> None: # fold forward forever and make a recycling pool look starved. child = _make_tracked_child("running", wait_since=10.0) - child.mark_stopped(10.5) - assert child.drain_wait(20.0) == pytest.approx(0.5) - assert child.drain_wait(30.0) == pytest.approx(0.0) + child.timing.mark_stopped(10.5) + assert child.timing.drain_wait(20.0) == pytest.approx(0.5) + assert child.timing.drain_wait(30.0) == pytest.approx(0.0) def test_tracked_child_pending_accrues_neither_busy_nor_wait() -> None: # Warmup is not starvation: a child importing the app has no slot to fill. child = _make_tracked_child("pending") - assert child.drain_busy(11.0) == pytest.approx(0.0) - assert child.drain_wait(11.0) == pytest.approx(0.0) + assert child.timing.drain_busy(11.0) == pytest.approx(0.0) + assert child.timing.drain_wait(11.0) == pytest.approx(0.0) - child.mark_running(11.0) - assert child.drain_wait(12.0) == pytest.approx(1.0) + child.timing.mark_running(11.0) + assert child.timing.drain_wait(12.0) == pytest.approx(1.0) def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: @@ -1631,11 +1633,11 @@ def test_spawn_children_uses_the_child_timestamp_not_the_drain_time() -> None: stamped_at = time.monotonic() - 5.0 messages.put(ChildMessage(child_id, "busy", timestamp=stamped_at)) - _wait_for(lambda: pool._children[child_id].busy_since is not None) + _wait_for(lambda: pool._children[child_id].timing.busy.since is not None) # The drain lands up to 100ms later on another thread; the segment has # to start when the child said it did. - assert pool._children[child_id].busy_since == pytest.approx(stamped_at) + assert pool._children[child_id].timing.busy.since == pytest.approx(stamped_at) finally: pool.shutdown() @@ -1654,19 +1656,19 @@ def test_spawn_children_tracks_wait_between_tasks() -> None: # Reporting in opens a wait segment: available, blocked in get(). messages.put(ChildMessage(child_id, "running", timestamp=base)) - _wait_for(lambda: pool._children[child_id].wait_since == pytest.approx(base)) + _wait_for(lambda: pool._children[child_id].timing.wait.since == pytest.approx(base)) # 2s of waiting, then 1s of work, then waiting again. messages.put(ChildMessage(child_id, "busy", timestamp=base + 2.0)) messages.put(ChildMessage(child_id, "idle", timestamp=base + 3.0)) # `wait_since` is already set by "running" above, so wait on banked busy. - _wait_for(lambda: pool._children[child_id].busy_accumulated > 0) + _wait_for(lambda: pool._children[child_id].timing.busy.accumulated > 0) child = pool._children[child_id] - assert child.wait_accumulated == pytest.approx(2.0) - assert child.busy_accumulated == pytest.approx(1.0) - assert child.busy_since is None - assert child.wait_since == pytest.approx(base + 3.0) + assert child.timing.wait.accumulated == pytest.approx(2.0) + assert child.timing.busy.accumulated == pytest.approx(1.0) + assert child.timing.busy.since is None + assert child.timing.wait.since == pytest.approx(base + 3.0) finally: pool.shutdown() From bbac43bcc31fcc3eb0a8ce3e32ebf347248e398e Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Wed, 2 Sep 2026 11:21:57 -0400 Subject: [PATCH 05/17] comments --- .../src/taskbroker_client/worker/worker.py | 211 ++++++++---------- .../taskbroker_client/worker/workerchild.py | 20 +- 2 files changed, 110 insertions(+), 121 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 630d6aa2..0885e70e 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -1,5 +1,6 @@ from __future__ import annotations +import ctypes import logging import multiprocessing import os @@ -9,7 +10,7 @@ import time from collections import deque from concurrent.futures import ThreadPoolExecutor -from dataclasses import dataclass, field +from dataclasses import dataclass from multiprocessing.context import ForkContext, ForkServerContext, SpawnContext from multiprocessing.process import BaseProcess from multiprocessing.synchronize import Event @@ -40,6 +41,12 @@ ) from taskbroker_client.metrics import MetricsBackend from taskbroker_client.types import InflightTaskActivation, ProcessingResult +from taskbroker_client.worker.childtiming import ( + NO_SLOT, + SLOT_WIDTH, + ChildTimeAccounting, + slot_count, +) from taskbroker_client.worker.client import ( HealthCheckSettings, HostTemporarilyUnavailable, @@ -224,108 +231,14 @@ class RequeueException(Exception): ChildState = Literal["pending", "running", "exiting"] -@dataclass -class TimeSegment: - """Used to track a child proceses' time: either its busy clock or its wait clock. - - `since` is the monotonic start of the currently-open time segment, or None when - the time segment is closed. `accumulated` holds seconds banked but not yet - emitted. - """ - - since: float | None = None - accumulated: float = 0.0 - - def open(self, now: float) -> None: - """Start a segment, keeping the earlier start if one is already open.""" - if self.since is None: - self.since = now - - def close(self, now: float) -> None: - """Bank the open segment up to `now` and close it. No-op if closed.""" - if self.since is not None: - self.accumulated += max(0.0, now - self.since) - self.since = None - - def drain(self, now: float) -> float: - """Return banked seconds and reset, leaving an open time segment open. - - A still-open time segment is folded in up to `now` and restarted there, so a - task spanning several intervals contributes to each one. - """ - if self.since is not None: - self.accumulated += max(0.0, now - self.since) - self.since = now - banked = self.accumulated - self.accumulated = 0.0 - return banked - - -@dataclass -class ChildTimeAccounting: - """Time-weighted busy/wait accounting for one child. - - A running child is always in exactly one of the two states, so over any - interval `drain_busy` + `drain_wait` must sum to that interval's width. - - Wait time is measured rather than inferred as `elapsed - busy`, which only holds - for children that ran for the whole interval. - """ - - busy: TimeSegment = field(default_factory=TimeSegment) - wait: TimeSegment = field(default_factory=TimeSegment) - last_drained_at: float = 0.0 - - def _clamp(self, now: float) -> float: - """Never let a segment boundary land inside an already-emitted interval. - - Only child-supplied timestamps need this. The time segment drains are driven by the - metrics thread's own monotonic clock, which never runs backwards. - """ - return max(now, self.last_drained_at) - - def mark_running(self, now: float) -> None: - """Start the wait clock: a `pending` child is importing, not starving.""" - if self.busy.since is None and self.wait.since is None: - self.wait.open(self._clamp(now)) - - def mark_busy(self, now: float) -> None: - """Close the open wait segment and open a busy one.""" - now = self._clamp(now) - self.wait.close(now) - self.busy.open(now) - - def mark_idle(self, now: float) -> None: - """Close the open busy segment and open a wait one.""" - now = self._clamp(now) - self.busy.close(now) - self.wait.open(now) - - def mark_stopped(self, now: float) -> None: - """Close both segments so a released child stops folding wait forward.""" - now = self._clamp(now) - self.busy.close(now) - self.wait.close(now) - - def drain_busy(self, now: float) -> float: - """Return busy seconds since the last drain and reset the counter.""" - banked = self.busy.drain(now) - self.last_drained_at = now - return banked - - def drain_wait(self, now: float) -> float: - """Mirror of `drain_busy`, so a long block counts in every interval it spans.""" - banked = self.wait.drain(now) - self.last_drained_at = now - return banked - - @dataclass class TrackedChild: process: BaseProcess state: ChildState release: Event - timing: ChildTimeAccounting = field(default_factory=ChildTimeAccounting) + # Bound to this child's shared-memory slot at spawn time, so there is no + # sensible default: an accountant with no slot silently measures nothing. + timing: ChildTimeAccounting class PushTaskWorker: @@ -998,6 +911,18 @@ def __init__( ) self._children: Dict[UUID, TrackedChild] = {} self._exiting_children: Deque[UUID] = deque() + + # Children write their own busy/wait totals here and the parent diffs + # them once a second. Sized for two generations because + # `spawn_children_thread` ignores exiting children when deciding how + # many to spawn, so a full set of unreaped children can briefly overlap + # a full set of replacements. Slots are handed out and returned under + # `_children_lock`. + self._timing_slots: int = slot_count(concurrency) + self._timing_shm: ctypes.Array[ctypes.c_double] = self._mp_context.RawArray( + "d", SLOT_WIDTH * self._timing_slots + ) + self._free_timing_slots: Deque[int] = deque(range(self._timing_slots)) self._children_lock = threading.Lock() self._last_occupancy_flush_at = time.monotonic() self._shutdown_event = self._mp_context.Event() @@ -1007,6 +932,50 @@ def __init__( self._metrics_thread: threading.Thread | None = None self._spawn_children_thread: threading.Thread | None = None + def _acquire_timing_slot(self) -> int: + """Take a zeroed shared-memory slot for a new child. + + `NO_SLOT` means the pool ran out, which the two-generation sizing is + meant to make impossible. That child then contributes to neither the + occupancy numerator nor `running_count`, so the ratio stays consistent + across the children that are accounted for, and the metric below says + the sizing was wrong. + """ + with self._children_lock: + if not self._free_timing_slots: + slot = NO_SLOT + else: + slot = self._free_timing_slots.popleft() + + if slot == NO_SLOT: + logger.error( + "taskworker.child.timing_slot_exhausted", + extra={ + "slots": self._timing_slots, + "processing_pool": self._processing_pool_name, + }, + ) + self._metrics.incr( + "taskworker.worker.child.timing_slot_exhausted", + tags={"processing_pool": self._processing_pool_name}, + ) + return NO_SLOT + + base = slot * SLOT_WIDTH + for offset in range(SLOT_WIDTH): + self._timing_shm[base + offset] = 0.0 + + return slot + + def _release_timing_slot(self, slot: int) -> None: + """Return a slot whose child never started. The reap path returns slots + inline because it already holds `_children_lock`.""" + if slot == NO_SLOT: + return + + with self._children_lock: + self._free_timing_slots.append(slot) + @property def ready_count(self) -> int: """Number of children that have finished warming up and are consuming.""" @@ -1055,14 +1024,15 @@ def _emit_periodic_metrics(self) -> None: # Running children only: occupancy divides by `running_count`, # so folding a `pending` or `exiting` child into the numerator # measures one population against another. Neither has time to - # lose here. A `pending` child has not opened a segment yet, - # and `mark_stopped` deliberately closes an `exiting` child's - # segments so its tail stops counting against the live pool. + # lose here. A `pending` child is not being accounted yet, and + # `mark_stopped` deliberately stops accounting an `exiting` + # child so its tail does not count against the live pool. if child.state != "running": continue - busy_time += child.timing.drain_busy(now) - wait_time += child.timing.drain_wait(now) + busy, wait = child.timing.sample(now) + busy_time += busy + wait_time += wait exiting_children = len(self._exiting_children) @@ -1283,6 +1253,13 @@ def spawn_children_thread() -> None: c.process.join(timeout=0) self._children.pop(cid) + # Reclaim here rather than on the `exiting` transition: + # a released child can still publish once before it + # breaks out of its loop, and handing that slot to a + # replacement would mix two children's totals. + if c.timing.slot != NO_SLOT: + self._free_timing_slots.append(c.timing.slot) + logger.info( "taskworker.child.exited", extra={ @@ -1310,26 +1287,18 @@ def spawn_children_thread() -> None: continue - # This child is now running + # This child is now running. Baseline against the slot + # as it stands rather than the child's timestamp: the + # child only enters `running_count` here, so starting + # the numerator here keeps the ratio consistent. if message.event == "running": child.state = "running" - child.timing.mark_running(message.timestamp) + child.timing.mark_running(time.monotonic()) # This child wants to exit, but we may not have enough running children to shut down right away elif message.event == "exiting": self._exiting_children.append(message.child_id) - # Close the wait segment and open a busy one, at the - # child's timestamp: this loop drains on a 100ms sleep, - # so stamping here credits work to the wrong interval. - elif message.event == "busy": - child.timing.mark_busy(message.timestamp) - - # This child finished a task: close the open busy segment - # and bank the elapsed time. - elif message.event == "idle": - child.timing.mark_idle(message.timestamp) - while True: # Compute how many children are still running running = sum(1 for c in self._children.values() if c.state == "running") @@ -1350,7 +1319,7 @@ def spawn_children_thread() -> None: continue child.state = "exiting" - child.timing.mark_stopped(time.monotonic()) + child.timing.mark_stopped() child.release.set() spawned = sum(1 for c in self._children.values() if c.state != "exiting") @@ -1361,6 +1330,7 @@ def spawn_children_thread() -> None: for _ in range(needed): child_id = uuid4() release = self._mp_context.Event() + timing_slot = self._acquire_timing_slot() process = self._mp_context.Process( name=f"taskworker-child-{child_id}", @@ -1378,6 +1348,8 @@ def spawn_children_thread() -> None: self._future_checking_frequency, messages, release, + self._timing_shm, + timing_slot, ), ) @@ -1389,10 +1361,15 @@ def spawn_children_thread() -> None: process=process, state="pending", release=release, + timing=ChildTimeAccounting(shm=self._timing_shm, slot=timing_slot), ) self._children[child_id] = child except Exception as e: + # The child never came up, so nothing will ever write + # to its slot. + self._release_timing_slot(timing_slot) + logger.exception( "taskworker.child.spawn.failed", extra={ diff --git a/clients/python/src/taskbroker_client/worker/workerchild.py b/clients/python/src/taskbroker_client/worker/workerchild.py index 3229132e..20fadf4a 100644 --- a/clients/python/src/taskbroker_client/worker/workerchild.py +++ b/clients/python/src/taskbroker_client/worker/workerchild.py @@ -1,6 +1,7 @@ from __future__ import annotations import contextlib +import ctypes import logging import multiprocessing import queue @@ -40,6 +41,7 @@ from taskbroker_client.state import clear_current_task, current_task, set_current_task from taskbroker_client.task import Task from taskbroker_client.types import ContextHook, InflightTaskActivation, ProcessingResult +from taskbroker_client.worker.childtiming import ChildTimeWriter logger = logging.getLogger(__name__) @@ -169,7 +171,7 @@ def _log_task_retry_exhausted( @dataclass(frozen=True) class ChildMessage: child_id: UUID - event: Literal["running", "exiting", "busy", "idle"] + event: Literal["running", "exiting"] # Stamped at the event, not when the parent drains it 100ms later. # CLOCK_MONOTONIC is system-wide, so a child's stamp is valid in the parent. # compare=False: the timestamp is payload, not identity. @@ -189,6 +191,8 @@ def child_process( future_checking_frequency: float, messages: multiprocessing.Queue[ChildMessage], parent_release: Event, + timing_shm: ctypes.Array[ctypes.c_double] | None, + timing_slot: int, ) -> None: """ The entrypoint for spawned worker children. @@ -200,6 +204,13 @@ def child_process( app = import_app(app_module) app.load_modules() metrics = app.metrics + + # Busy/wait accounting goes straight into shared memory rather than over + # `messages`. The parent's drain thread competes for CPU with the children + # it measures, so at two events per task it falls behind under saturation + # and occupancy goes stale. This costs the parent one read per child per + # second instead. + timing = ChildTimeWriter(timing_shm, timing_slot) # Signals when the parent worker pool terminates the child local_shutdown = threading.Event() @@ -381,7 +392,7 @@ def check_task_future_completion( # the child did since its last dequeue has finished, and what follows # is waiting for the next task. if is_busy: - messages.put_nowait(ChildMessage(child_id, "idle")) + timing.mark_idle(time.monotonic()) is_busy = False if max_task_count and processed_task_count >= max_task_count: @@ -441,7 +452,7 @@ def check_task_future_completion( # Open the busy segment as soon as we have a task. The slot is now # unavailable for new work, whatever stage of handling it is in. - messages.put_nowait(ChildMessage(child_id, "busy")) + timing.mark_busy(time.monotonic()) is_busy = True task_func = _get_known_task(inflight.activation) @@ -629,7 +640,7 @@ def check_task_future_completion( # signal can land while a segment is still open. Close it so a child that # is going away doesn't keep contributing busy time to the pool's occupancy. if is_busy: - messages.put_nowait(ChildMessage(child_id, "idle")) + timing.close(time.monotonic()) is_busy = False # Once we get the shutdown signal, drain any pending futures @@ -889,6 +900,7 @@ def _task_execution_complete( ) # Tell the parent that this child has warmed up and is ready to consume tasks + timing.mark_running(time.monotonic()) messages.put_nowait(ChildMessage(child_id, "running")) # Run the worker loop From abccb485ef9efb320f9cc1aa9b0aa39eab1d9238 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Wed, 2 Sep 2026 12:58:48 -0400 Subject: [PATCH 06/17] Move child busy/wait accounting into shared memory 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) --- .../taskbroker_client/worker/childtiming.py | 228 +++++++++ .../src/taskbroker_client/worker/worker.py | 15 +- clients/python/tests/worker/test_worker.py | 437 ++++++++++++------ 3 files changed, 530 insertions(+), 150 deletions(-) create mode 100644 clients/python/src/taskbroker_client/worker/childtiming.py diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py new file mode 100644 index 00000000..34d9a50d --- /dev/null +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -0,0 +1,228 @@ +"""Shared-memory busy/wait accounting for worker children. + +Once a second the parent needs to know how many seconds each child spent +executing versus waiting for work. To accomplish that each child owns a slot +in a ``RawArray`` of doubles and writes its own cumulative totals there. The +parent reads and diffs the slots at flush time. + +Slot layout, five doubles per child:: + + 0 version seqlock; odd means a write is in progress + 1 busy_total cumulative seconds closed into busy + 2 wait_total cumulative seconds closed into wait + 3 segment_start time.monotonic() when the currently-open segment began + 4 segment_kind KIND_NONE, KIND_WAIT or KIND_BUSY + +Two properties carry the design. + +Every value is absolute and cumulative rather than a delta, which is what makes +a torn read survivable: a bad sample is transient and the next one re-derives +the truth from the slot, so error cannot accumulate. + +``KIND_NONE`` is zero, so a freshly zeroed slot reads as "this child has not +accounted for anything yet" rather than as an open segment starting at time +zero. + +``time.monotonic()`` is CLOCK_MONOTONIC, which is system-wide, so a child's +timestamps are directly comparable in the parent. +""" + +from __future__ import annotations + +import ctypes +from dataclasses import dataclass + +# Offsets within a slot, and the slot stride. +SLOT_VERSION = 0 +SLOT_BUSY_TOTAL = 1 +SLOT_WAIT_TOTAL = 2 +SLOT_SEGMENT_START = 3 +SLOT_SEGMENT_KIND = 4 +SLOT_WIDTH = 5 + +# Kind values. NONE must be 0.0 so that a zeroed slot means "nothing open". +KIND_NONE = 0.0 +KIND_WAIT = 1.0 +KIND_BUSY = 2.0 + +# Slot index handed to a child when the pool has none left. Every read and +# write becomes a no-op and the parent leaves that child out of occupancy. +NO_SLOT = -1 + +# A writer holds the seqlock for four stores, so a reader that loses three +# races in a row is seeing something other than ordinary contention. +SEQLOCK_READ_ATTEMPTS = 3 + + +def slot_count(concurrency: int) -> int: + """How many slots a pool of `concurrency` children needs. + + Twice concurrency. `spawn_children_thread` counts only non-exiting children + when deciding how many to spawn, so a full generation of exiting-but-unreaped + children can briefly coexist with a full generation of replacements. + """ + return max(1, concurrency * 2) + + +class ChildTimeWriter: + """Child-side writer for one slot. + + The child is the only writer for its slot, so it keeps the authoritative + totals as plain Python floats and republishes the whole slot on each + transition. That avoids a read-modify-write against shared memory. + """ + + __slots__ = ("_shm", "_slot", "_base", "_busy_total", "_wait_total", "_start", "_kind") + + def __init__(self, shm: ctypes.Array[ctypes.c_double] | None, slot: int) -> None: + self._shm = shm + self._slot = NO_SLOT if shm is None else slot + self._base = slot * SLOT_WIDTH + self._busy_total = 0.0 + self._wait_total = 0.0 + self._start = 0.0 + self._kind = KIND_NONE + + def _publish(self) -> None: + if self._slot == NO_SLOT or self._shm is None: + return + + shm = self._shm + base = self._base + + version = shm[base + SLOT_VERSION] + # Odd version: a reader that sees this discards what it read. + shm[base + SLOT_VERSION] = version + 1.0 + shm[base + SLOT_BUSY_TOTAL] = self._busy_total + shm[base + SLOT_WAIT_TOTAL] = self._wait_total + shm[base + SLOT_SEGMENT_START] = self._start + shm[base + SLOT_SEGMENT_KIND] = self._kind + shm[base + SLOT_VERSION] = version + 2.0 + + def _close_open(self, now: float) -> None: + if self._kind == KIND_BUSY: + self._busy_total += max(0.0, now - self._start) + elif self._kind == KIND_WAIT: + self._wait_total += max(0.0, now - self._start) + self._kind = KIND_NONE + + def mark_running(self, now: float) -> None: + """Open the wait clock. A warmed-up child with no task yet is waiting.""" + if self._kind != KIND_NONE: + return + + self._start = now + self._kind = KIND_WAIT + self._publish() + + def mark_busy(self, now: float) -> None: + """Close the open wait segment and open a busy one.""" + self._close_open(now) + self._start = now + self._kind = KIND_BUSY + self._publish() + + def mark_idle(self, now: float) -> None: + """Close the open busy segment and open a wait one.""" + self._close_open(now) + self._start = now + self._kind = KIND_WAIT + self._publish() + + def close(self, now: float) -> None: + """Close whatever is open so a departing child stops folding time forward.""" + self._close_open(now) + self._publish() + + +@dataclass +class ChildTimeAccounting: + """Parent-side reader for one child's slot. + + Holds the previous absolute reading and returns deltas. A child sitting in a + long task therefore contributes to every interval it spans, instead of + dumping its whole duration into the interval it happens to finish in. + """ + + shm: ctypes.Array[ctypes.c_double] | None + slot: int = NO_SLOT + _prev_busy: float = 0.0 + _prev_wait: float = 0.0 + _accounted: bool = False + + def mark_running(self, now: float) -> None: + """Start counting this child, baselining against the slot as it stands. + + Baselining rather than zeroing means whatever the child banked between + spawning and the parent seeing its `running` message is not credited + retroactively. The child is excluded from `running_count` over that same + window, so the numerator and the denominator start together. + """ + reading = self._read(now) + if reading is None: + # Slots are zeroed at allocation, so a failed first read costs at + # most the few microseconds since the child came up. + self._prev_busy = 0.0 + self._prev_wait = 0.0 + else: + self._prev_busy, self._prev_wait = reading + + self._accounted = True + + def mark_stopped(self) -> None: + """Stop counting this child, so an exiting child's tail does not land on + the live pool's occupancy.""" + self._accounted = False + + def sample(self, now: float) -> tuple[float, float]: + """Return (busy, wait) seconds accrued since the previous sample.""" + if not self._accounted: + return (0.0, 0.0) + + reading = self._read(now) + if reading is None: + # Leave the baseline alone: the next sample then covers both + # intervals. Deferring the attribution beats dropping it. + return (0.0, 0.0) + + busy_now, wait_now = reading + busy = max(0.0, busy_now - self._prev_busy) + wait = max(0.0, wait_now - self._prev_wait) + self._prev_busy = busy_now + self._prev_wait = wait_now + return (busy, wait) + + def _read(self, now: float) -> tuple[float, float] | None: + """Seqlock read of absolute busy/wait, including the segment still open. + + None means the read could not be taken cleanly and the caller should + keep whatever baseline it already has. + """ + if self.slot == NO_SLOT or self.shm is None: + return None + + shm = self.shm + base = self.slot * SLOT_WIDTH + + for _ in range(SEQLOCK_READ_ATTEMPTS): + version = shm[base + SLOT_VERSION] + if version % 2.0: + continue + + busy = shm[base + SLOT_BUSY_TOTAL] + wait = shm[base + SLOT_WAIT_TOTAL] + start = shm[base + SLOT_SEGMENT_START] + kind = shm[base + SLOT_SEGMENT_KIND] + + if shm[base + SLOT_VERSION] != version: + continue + + # Fold in the segment the child is in right now. + if kind == KIND_BUSY: + busy += max(0.0, now - start) + elif kind == KIND_WAIT: + wait += max(0.0, now - start) + + return (busy, wait) + + return None diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 0885e70e..a70d85b5 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -1018,6 +1018,7 @@ def _emit_periodic_metrics(self) -> None: busy_time = 0.0 wait_time = 0.0 + accounted_running = 0 for child in self._children.values(): state_counts[child.state] += 1 @@ -1030,6 +1031,14 @@ def _emit_periodic_metrics(self) -> None: if child.state != "running": continue + # A child with no slot reports nothing, so leaving it in the + # denominator would read as an idle child rather than as a + # missing measurement. `timing_slot_exhausted` is what + # surfaces it instead. + if child.timing.slot == NO_SLOT: + continue + + accounted_running += 1 busy, wait = child.timing.sample(now) busy_time += busy wait_time += wait @@ -1061,7 +1070,11 @@ def _emit_periodic_metrics(self) -> None: max(0.0, wait_time) ) - running_count = state_counts["running"] + # Children the pool could not give a slot to are excluded on both + # sides, so occupancy stays a consistent ratio over the children that + # are actually accounted for. `state_counts` still reports every + # running child to the `children` gauge. + running_count = accounted_running if running_count > 0 and elapsed > 0: # A child cannot be busy for longer than the interval, so this is a # hard physical bound on both counters. Exceeding it means the diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 6efa8a04..7b06155f 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1,6 +1,8 @@ import contextlib +import itertools import os import queue +import random import signal import threading import time @@ -43,13 +45,26 @@ from taskbroker_client.retry import NoRetriesRemainingError from taskbroker_client.state import current_task from taskbroker_client.types import InflightTaskActivation, ProcessingResult -from taskbroker_client.worker.worker import ( +from taskbroker_client.worker.childtiming import ( + KIND_BUSY, + KIND_NONE, + KIND_WAIT, + NO_SLOT, + SLOT_BUSY_TOTAL, + SLOT_SEGMENT_KIND, + SLOT_SEGMENT_START, + SLOT_VERSION, + SLOT_WAIT_TOTAL, + SLOT_WIDTH, ChildTimeAccounting, + ChildTimeWriter, + slot_count, +) +from taskbroker_client.worker.worker import ( PushTaskWorker, ShutdownSignal, TaskWorker, TaskWorkerProcessingPool, - TimeSegment, TrackedChild, WorkerServicer, ) @@ -316,6 +331,8 @@ def child_process( future_checking_frequency, messages, parent_release, + ctx.RawArray("d", SLOT_WIDTH), + 0, ) @@ -412,6 +429,9 @@ def Process(self, *args: Any, **kwargs: Any) -> _FakeProcess: self.processes.append(process) return process + def RawArray(self, typecode: str, size: int) -> Any: + return get_context("fork").RawArray(typecode, size) + def _make_fake_context_pool( fake_context: _FakeContext, @@ -1277,6 +1297,13 @@ def ready_count() -> int: pool_shutdown.assert_called_once_with() +# Slots for children built by `_make_tracked_child`. Independent of any pool: +# the flush reads through `child.timing.shm`, not the pool's array. +_TEST_SLOTS = 512 +_TEST_TIMING_SHM = get_context("fork").RawArray("d", SLOT_WIDTH * _TEST_SLOTS) +_TEST_SLOT_SEQ = itertools.count() + + def _make_tracked_child( state: str, *, @@ -1285,14 +1312,41 @@ def _make_tracked_child( wait_since: float | None = None, wait_accumulated: float = 0.0, ) -> TrackedChild: + """Seed a child's slot so its next sample reports the given time. + + `*_accumulated` is time the child has already closed; `*_since` leaves a + segment open at that monotonic time, which the parent folds forward at + sample time exactly as it would for a task still running. + """ + slot = next(_TEST_SLOT_SEQ) % _TEST_SLOTS + base = slot * SLOT_WIDTH + + for offset in range(SLOT_WIDTH): + _TEST_TIMING_SHM[base + offset] = 0.0 + + timing = ChildTimeAccounting(shm=_TEST_TIMING_SHM, slot=slot) + # Baseline against the zeroed slot, so everything seeded below lands in + # the first sample. + timing.mark_running(0.0) + + if busy_since is not None: + kind, start = KIND_BUSY, busy_since + elif wait_since is not None: + kind, start = KIND_WAIT, wait_since + else: + kind, start = KIND_NONE, 0.0 + + _TEST_TIMING_SHM[base + SLOT_VERSION] = 2.0 + _TEST_TIMING_SHM[base + SLOT_BUSY_TOTAL] = busy_accumulated + _TEST_TIMING_SHM[base + SLOT_WAIT_TOTAL] = wait_accumulated + _TEST_TIMING_SHM[base + SLOT_SEGMENT_START] = start + _TEST_TIMING_SHM[base + SLOT_SEGMENT_KIND] = kind + return TrackedChild( process=mock.Mock(), state=state, # type: ignore[arg-type] release=mock.Mock(), - timing=ChildTimeAccounting( - busy=TimeSegment(since=busy_since, accumulated=busy_accumulated), - wait=TimeSegment(since=wait_since, accumulated=wait_accumulated), - ), + timing=timing, ) @@ -1355,10 +1409,12 @@ def test_emit_periodic_metrics_time_weights_busy_over_the_interval() -> None: assert len(occupancy_calls) == 1 assert occupancy_calls[0].args[1] == pytest.approx(1.24 / 3) - # The open segment is carried into the next interval; banks are drained. - assert pool._children[child_b].timing.busy.since == pytest.approx(11.0) + # B's segment is still open, so the next interval picks up where this one + # stopped rather than re-reporting the 0.60 already credited. + assert pool._children[child_b].timing.sample(12.0) == pytest.approx((1.0, 0.0)) for child in pool._children.values(): - assert child.timing.busy.accumulated == 0.0 + if child.state == "running": + assert child.timing.sample(12.0)[0] == pytest.approx(0.0) assert pool._last_occupancy_flush_at == pytest.approx(11.0) @@ -1425,6 +1481,39 @@ def test_emit_periodic_metrics_does_not_flag_a_legitimately_full_pool() -> None: assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] +def test_emit_periodic_metrics_excludes_slotless_children_from_occupancy() -> None: + # A child the pool could not give a slot to reports nothing. Leaving it in + # the denominator would read as a genuinely idle child and halve occupancy, + # which is the sort of quiet undercount this whole change exists to remove. + # It still belongs in the `children` gauge: the pod really does have it. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + slotless = _make_tracked_child("running") + slotless.timing.slot = NO_SLOT + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = slotless + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + # One accounted child, busy for the whole interval. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( + 1.0 + ) + assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] + + running_gauges = [ + c + for c in pool._metrics.gauge.call_args_list + if c.args[0] == "taskworker.worker.children" and c.kwargs["tags"]["state"] == "running" + ] + assert running_gauges[0].args[1] == 2.0 + + def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: # occupancy divides by running_count, so the counters have to sum over the # same population. An exiting child folded into the numerator inflates both @@ -1448,130 +1537,195 @@ def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: ) -def test_spawn_children_tracks_busy_and_idle_transitions() -> None: +def test_spawn_children_binds_each_child_to_its_own_timing_slot() -> None: + # The parent hands the slot to the child at spawn and reads the same slot + # at flush. If those ever disagree the pool measures nothing. fake_context = _FakeContext() - pool = _make_fake_context_pool(fake_context, concurrency=1) + pool = _make_fake_context_pool(fake_context, concurrency=2) pool.start_spawn_children_thread() try: - _wait_for(lambda: len(fake_context.processes) == 1) + _wait_for(lambda: len(fake_context.processes) == 2) messages = fake_context.queues[-1] - child_id = fake_context.processes[0].args[0] - messages.put(ChildMessage(child_id, "running")) - _wait_for(lambda: pool.ready_count == 1) - - # "busy" opens a segment. - messages.put(ChildMessage(child_id, "busy")) - _wait_for(lambda: pool._children[child_id].timing.busy.since is not None) - - # "idle" closes it and banks a positive amount of busy-time. - messages.put(ChildMessage(child_id, "idle")) - _wait_for( - lambda: pool._children[child_id].timing.busy.since is None - and pool._children[child_id].timing.busy.accumulated > 0 - ) + slots: set[int] = set() + for process in fake_context.processes: + child_id = process.args[0] + shm, slot = process.args[-2], process.args[-1] + slots.add(slot) + + messages.put(ChildMessage(child_id, "running")) + # _wait_for blocks here, so the closure is resolved inside the + # iteration and does not need a default-argument capture. + _wait_for(lambda: pool._children[child_id].state == "running") + assert pool._children[child_id].timing.slot == slot + assert shm is pool._timing_shm + + # Two children, two distinct slots. + assert len(slots) == 2 finally: pool.shutdown() -def test_tracked_child_records_real_widths_for_events_in_one_batch() -> None: - # The regression this change exists for: stamping at drain time collapsed - # every segment in a batch to zero width. Two 50ms tasks, 10ms apart: - child = _make_tracked_child("running", wait_since=100.00) +def _writer_and_reader(slot: int = 0) -> tuple[ChildTimeWriter, ChildTimeAccounting]: + shm = get_context("fork").RawArray("d", SLOT_WIDTH * (slot + 1)) + return ChildTimeWriter(shm, slot), ChildTimeAccounting(shm=shm, slot=slot) + + +def test_child_timing_round_trips_through_shared_memory() -> None: + # The whole point of the slot: the child records the transition itself, so + # nothing has to survive a queue to be counted correctly. + writer, reader = _writer_and_reader() + + writer.mark_running(0.0) + reader.mark_running(0.0) + writer.mark_busy(1.0) + + assert reader.sample(2.0) == pytest.approx((1.0, 1.0)) + + +def test_child_timing_credits_a_long_task_to_every_interval_it_spans() -> None: + # A child only knows a segment's width when it ends. Folding the open + # segment forward at read time is what stops a 60s task reporting zero for + # 60 flushes and then 60s at once. + writer, reader = _writer_and_reader() + + writer.mark_running(0.0) + reader.mark_running(0.0) + writer.mark_busy(0.0) + + assert reader.sample(1.0) == pytest.approx((1.0, 0.0)) + assert reader.sample(2.0) == pytest.approx((1.0, 0.0)) + + writer.mark_idle(2.5) + assert reader.sample(3.0) == pytest.approx((0.5, 0.5)) + + +def test_child_timing_busy_and_wait_partition_every_interval() -> None: + # A running child is always in exactly one state, so busy + wait over any + # sequence of samples has to equal the wall time. This is the invariant + # `occupancy.accounting_overflow` guards in production. + writer, reader = _writer_and_reader() + writer.mark_running(0.0) + reader.mark_running(0.0) + + rng = random.Random(20260902) + now = 0.0 + busy = False + total_busy = total_wait = 0.0 + + for i in range(500): + now += rng.uniform(0.001, 0.05) + busy = not busy + (writer.mark_busy if busy else writer.mark_idle)(now) + + if i % 7 == 0: + b, w = reader.sample(now) + total_busy += b + total_wait += w + + b, w = reader.sample(now) + total_busy += b + total_wait += w - child.timing.mark_busy(100.00) - child.timing.mark_idle(100.05) - child.timing.mark_busy(100.06) - child.timing.mark_idle(100.11) + assert total_busy + total_wait == pytest.approx(now) - # 0.05 + 0.05 of work, and the 0.01 gap between them counted as waiting. - assert child.timing.busy.accumulated == pytest.approx(0.10) - assert child.timing.wait.accumulated == pytest.approx(0.01) +def test_child_timing_defers_rather_than_drops_a_torn_read() -> None: + # An odd version means the child was mid-publish. Returning zero without + # advancing the baseline means the next sample covers both intervals, so a + # torn read delays attribution instead of losing it. + writer, reader = _writer_and_reader() + writer.mark_running(0.0) + reader.mark_running(0.0) + writer.mark_busy(0.0) -def test_tracked_child_busy_and_wait_partition_the_interval() -> None: - # A running child is always in exactly one state, so the drains must sum - # to the interval width. - child = _make_tracked_child("running", wait_since=10.0) + assert reader.sample(1.0) == pytest.approx((1.0, 0.0)) - child.timing.mark_busy(10.4) - busy = child.timing.drain_busy(11.0) - wait = child.timing.drain_wait(11.0) + reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + assert reader.sample(2.0) == pytest.approx((0.0, 0.0)) - assert busy == pytest.approx(0.6) - assert wait == pytest.approx(0.4) - assert busy + wait == pytest.approx(1.0) + reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + assert reader.sample(3.0) == pytest.approx((2.0, 0.0)) - # Both open segments are carried forward rather than restarted at zero. - assert child.timing.busy.since == pytest.approx(11.0) - assert child.timing.wait.since is None +def test_child_timing_stops_accruing_once_the_child_is_released() -> None: + # A released child keeps its wait segment open until it dies. Without this + # the segment folds forward forever and a recycling pool looks starved. + writer, reader = _writer_and_reader() + writer.mark_running(0.0) + reader.mark_running(0.0) -def test_tracked_child_ignores_events_older_than_the_last_drain() -> None: - # drain_busy folds forward to the parent's clock, so a message stamped just - # before that and processed just after must not subtract credited time. - child = _make_tracked_child("running", busy_since=10.0) + assert reader.sample(0.5)[1] == pytest.approx(0.5) - child.timing.drain_busy(11.0) # credits 1.0s, advances busy_since to 11.0 - child.timing.mark_idle(10.95) # stamped before the drain, delivered after + reader.mark_stopped() + assert reader.sample(20.0) == pytest.approx((0.0, 0.0)) - assert child.timing.busy.accumulated == pytest.approx(0.0) +def test_child_timing_ignores_a_child_with_no_slot() -> None: + # Degraded mode when the pool runs out of slots. It must report nothing + # rather than raise, since the parent also leaves it out of running_count. + shm = get_context("fork").RawArray("d", SLOT_WIDTH) + writer = ChildTimeWriter(shm, NO_SLOT) + reader = ChildTimeAccounting(shm=shm, slot=NO_SLOT) -def test_tracked_child_stale_event_cannot_bill_an_interval_twice() -> None: - # The regression found in the sandbox sweep. The parent reads child events - # on a 100ms loop while the metrics thread drains on a 1s cadence, so a - # `busy` stamped at 10.2 can arrive after the 11.0 drain has already billed - # 10.2-11.0 as wait. Backdating busy_since to 10.2 then bills those same - # 0.8s again as busy, and the error grows with the event backlog: the sweep - # measured 580 busy-seconds per 1s flush across 24 children, 24x the - # physical ceiling, which the occupancy clamp turned into a healthy 1.0. - child = _make_tracked_child("running", wait_since=10.0) + writer.mark_running(0.0) + writer.mark_busy(1.0) + reader.mark_running(0.0) - assert child.timing.drain_wait(11.0) == pytest.approx(1.0) - assert child.timing.drain_busy(11.0) == pytest.approx(0.0) + assert reader.sample(10.0) == pytest.approx((0.0, 0.0)) + assert shm[SLOT_SEGMENT_KIND] == KIND_NONE - child.timing.mark_busy(10.2) # stamped before the drain, delivered after it - busy = child.timing.drain_busy(12.0) - wait = child.timing.drain_wait(12.0) +def test_child_timing_excludes_time_banked_before_the_parent_saw_running() -> None: + # The child opens its wait clock at warmup, but the parent only counts it in + # running_count once the `running` message lands. Baselining at that moment + # keeps the numerator and the denominator starting together. + writer, reader = _writer_and_reader() - # The second interval is 1s wide and cannot yield more than 1s of credit. - assert busy == pytest.approx(1.0) - assert wait == pytest.approx(0.0) + writer.mark_running(0.0) + reader.mark_running(5.0) # parent drained the message 5s later + assert reader.sample(6.0) == pytest.approx((0.0, 1.0)) -def test_tracked_child_accepts_events_predating_its_first_drain() -> None: - # The watermark starts at 0.0 so a child that has never been flushed still - # records real segment widths rather than collapsing them to the drain time. - child = _make_tracked_child("running", wait_since=10.0) - child.timing.mark_busy(10.4) +def test_acquire_timing_slot_zeroes_a_recycled_slot() -> None: + # Slots outlive children. A replacement must not inherit its predecessor's + # totals, or its first sample reports the dead child's whole lifetime. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) - assert child.timing.drain_wait(11.0) == pytest.approx(0.4) - assert child.timing.drain_busy(11.0) == pytest.approx(0.6) + # Drain the free list so the release below is the only slot available. Reuse + # is FIFO, which deliberately leaves the longest possible gap between a slot + # being returned and handed out again. + slot = pool._acquire_timing_slot() + rest = [pool._acquire_timing_slot() for _ in range(slot_count(1) - 1)] + assert NO_SLOT not in rest + writer = ChildTimeWriter(pool._timing_shm, slot) + writer.mark_running(0.0) + writer.mark_busy(0.0) + writer.mark_idle(30.0) -def test_tracked_child_stops_accruing_wait_once_released() -> None: - # A released child stops sending messages, so an open wait segment would - # fold forward forever and make a recycling pool look starved. - child = _make_tracked_child("running", wait_since=10.0) + pool._release_timing_slot(slot) + recycled = pool._acquire_timing_slot() + assert recycled == slot - child.timing.mark_stopped(10.5) - assert child.timing.drain_wait(20.0) == pytest.approx(0.5) - assert child.timing.drain_wait(30.0) == pytest.approx(0.0) + reader = ChildTimeAccounting(shm=pool._timing_shm, slot=recycled) + reader.mark_running(0.0) + assert reader.sample(1.0) == pytest.approx((0.0, 0.0)) -def test_tracked_child_pending_accrues_neither_busy_nor_wait() -> None: - # Warmup is not starvation: a child importing the app has no slot to fill. - child = _make_tracked_child("pending") +def test_acquire_timing_slot_reports_exhaustion_instead_of_raising() -> None: + # Sizing should make this unreachable, so if it ever fires the metric is how + # we find out. The pool has to keep spawning either way. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) + pool._metrics = mock.Mock() - assert child.timing.drain_busy(11.0) == pytest.approx(0.0) - assert child.timing.drain_wait(11.0) == pytest.approx(0.0) + taken = [pool._acquire_timing_slot() for _ in range(slot_count(1))] + assert NO_SLOT not in taken - child.timing.mark_running(11.0) - assert child.timing.drain_wait(12.0) == pytest.approx(1.0) + assert pool._acquire_timing_slot() == NO_SLOT + assert len(_incr_calls(pool._metrics, "taskworker.worker.child.timing_slot_exhausted")) == 1 def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: @@ -1618,7 +1772,10 @@ def test_emit_periodic_metrics_emits_counters_during_warmup() -> None: assert len(_distribution_calls(pool._metrics, "taskworker.worker.child_wait_seconds")) == 1 -def test_spawn_children_uses_the_child_timestamp_not_the_drain_time() -> None: +def test_spawn_children_reads_transitions_the_child_wrote() -> None: + # End to end through the real handoff: the child publishes into the slot + # it was given, and the parent's accountant reports that split without a + # single message crossing the queue. fake_context = _FakeContext() pool = _make_fake_context_pool(fake_context, concurrency=1) @@ -1626,49 +1783,24 @@ def test_spawn_children_uses_the_child_timestamp_not_the_drain_time() -> None: try: _wait_for(lambda: len(fake_context.processes) == 1) messages = fake_context.queues[-1] - child_id = fake_context.processes[0].args[0] + process = fake_context.processes[0] + child_id = process.args[0] + writer = ChildTimeWriter(process.args[-2], process.args[-1]) + writer.mark_running(0.0) messages.put(ChildMessage(child_id, "running")) _wait_for(lambda: pool.ready_count == 1) - stamped_at = time.monotonic() - 5.0 - messages.put(ChildMessage(child_id, "busy", timestamp=stamped_at)) - _wait_for(lambda: pool._children[child_id].timing.busy.since is not None) - - # The drain lands up to 100ms later on another thread; the segment has - # to start when the child said it did. - assert pool._children[child_id].timing.busy.since == pytest.approx(stamped_at) - finally: - pool.shutdown() - - -def test_spawn_children_tracks_wait_between_tasks() -> None: - fake_context = _FakeContext() - pool = _make_fake_context_pool(fake_context, concurrency=1) - - pool.start_spawn_children_thread() - try: - _wait_for(lambda: len(fake_context.processes) == 1) - messages = fake_context.queues[-1] - child_id = fake_context.processes[0].args[0] - - base = time.monotonic() - 10.0 - - # Reporting in opens a wait segment: available, blocked in get(). - messages.put(ChildMessage(child_id, "running", timestamp=base)) - _wait_for(lambda: pool._children[child_id].timing.wait.since == pytest.approx(base)) + child = pool._children[child_id] + # Rebaseline onto the child's clock; the parent normally does this the + # moment it drains `running`, against its own monotonic reading. + child.timing.mark_running(0.0) - # 2s of waiting, then 1s of work, then waiting again. - messages.put(ChildMessage(child_id, "busy", timestamp=base + 2.0)) - messages.put(ChildMessage(child_id, "idle", timestamp=base + 3.0)) - # `wait_since` is already set by "running" above, so wait on banked busy. - _wait_for(lambda: pool._children[child_id].timing.busy.accumulated > 0) + # 2s waiting, 1s of work, then waiting again. + writer.mark_busy(2.0) + writer.mark_idle(3.0) - child = pool._children[child_id] - assert child.timing.wait.accumulated == pytest.approx(2.0) - assert child.timing.busy.accumulated == pytest.approx(1.0) - assert child.timing.busy.since is None - assert child.timing.wait.since == pytest.approx(base + 3.0) + assert child.timing.sample(4.0) == pytest.approx((1.0, 3.0)) finally: pool.shutdown() @@ -1698,7 +1830,7 @@ def test_spawn_children_releases_draining_child_above_min_concurrency() -> None: messages = fake_context.queues[-1] first_process = fake_context.processes[0] first_child_id = first_process.args[0] - first_release = first_process.args[-1] + first_release = first_process.args[-3] messages.put(ChildMessage(first_child_id, "running")) second_process = fake_context.processes[1] @@ -1724,7 +1856,7 @@ def test_spawn_children_defers_draining_child_at_min_concurrency() -> None: messages = fake_context.queues[-1] first_process = fake_context.processes[0] first_child_id = first_process.args[0] - first_release = first_process.args[-1] + first_release = first_process.args[-3] second_process = fake_context.processes[1] second_child_id = second_process.args[0] @@ -1881,6 +2013,7 @@ def test_child_process_emits_running_message() -> None: ctx = get_context("fork") child_id = uuid4() messages = ctx.Queue() + timing_shm = ctx.RawArray("d", SLOT_WIDTH) parent_release = ctx.Event() parent_release.set() @@ -1898,6 +2031,8 @@ def test_child_process_emits_running_message() -> None: future_checking_frequency=0.1, messages=messages, parent_release=parent_release, + timing_shm=timing_shm, + timing_slot=0, ) # The child signals readiness once warmup is done, before consuming @@ -1915,6 +2050,7 @@ def test_child_process_emits_exiting_once_and_continues_until_release( todo = ctx.Queue() processed = ctx.Queue() messages = ctx.Queue() + timing_shm = ctx.RawArray("d", SLOT_WIDTH) parent_release = ctx.Event() todo.put(SIMPLE_TASK) @@ -1933,25 +2069,20 @@ def test_child_process_emits_exiting_once_and_continues_until_release( 0.1, messages, parent_release, + timing_shm, + 0, ), ) process.start() try: - running_message = messages.get(timeout=5) - busy_message = messages.get(timeout=5) - idle_message = messages.get(timeout=5) - exiting_message = messages.get(timeout=5) - - assert running_message == ChildMessage(child_id, "running") - assert busy_message == ChildMessage(child_id, "busy") - assert idle_message == ChildMessage(child_id, "idle") - assert exiting_message == ChildMessage(child_id, "exiting") + # Only lifecycle events cross the queue now, two per child rather than + # two per task. That reduction is the whole point of the slot. + assert messages.get(timeout=5) == ChildMessage(child_id, "running") + assert messages.get(timeout=5) == ChildMessage(child_id, "exiting") assert processed.get(timeout=5).task_id == SIMPLE_TASK.activation.id todo.put(SIMPLE_TASK) assert processed.get(timeout=5).task_id == SIMPLE_TASK.activation.id - assert messages.get(timeout=5) == ChildMessage(child_id, "busy") - assert messages.get(timeout=5) == ChildMessage(child_id, "idle") time.sleep(0.2) assert process.is_alive() @@ -1968,13 +2099,14 @@ def test_child_process_emits_exiting_once_and_continues_until_release( assert mock_capture_checkin.call_count == 0 -def test_child_process_emits_busy_and_idle_messages() -> None: +def test_child_process_records_busy_and_idle_in_its_slot() -> None: todo: queue.Queue[InflightTaskActivation] = queue.Queue() processed: queue.Queue[ProcessingResult] = queue.Queue() shutdown = Event() ctx = get_context("fork") child_id = uuid4() messages = ctx.Queue() + timing_shm = ctx.RawArray("d", SLOT_WIDTH) parent_release = ctx.Event() parent_release.set() @@ -1992,13 +2124,20 @@ def test_child_process_emits_busy_and_idle_messages() -> None: future_checking_frequency=0.1, messages=messages, parent_release=parent_release, + timing_shm=timing_shm, + timing_slot=0, ) assert messages.get(timeout=1) == ChildMessage(child_id, "running") - assert messages.get(timeout=1) == ChildMessage(child_id, "busy") - assert messages.get(timeout=1) == ChildMessage(child_id, "idle") assert processed.get(timeout=1).task_id == SIMPLE_TASK.activation.id + # One task ran to completion, so the child closed a busy segment into its + # slot and reopened the wait clock behind it. + assert timing_shm[SLOT_BUSY_TOTAL] > 0.0 + assert timing_shm[SLOT_SEGMENT_KIND] == KIND_WAIT + assert timing_shm[SLOT_VERSION] % 2 == 0 + assert timing_shm[SLOT_SEGMENT_START] > 0.0 + def test_child_process_remove_start_time_kwargs() -> None: activation = InflightTaskActivation( From ce505e030e916eca4ea3c571198d9b9839f222c8 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Wed, 2 Sep 2026 16:06:32 -0400 Subject: [PATCH 07/17] Emit queue_wait, and fix the timestamp it is built on 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) --- .../taskbroker_client/worker/workerchild.py | 35 ++++++++- clients/python/tests/worker/test_worker.py | 77 ++++++++++++++++++- 2 files changed, 109 insertions(+), 3 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/workerchild.py b/clients/python/src/taskbroker_client/worker/workerchild.py index 20fadf4a..ee70d3aa 100644 --- a/clients/python/src/taskbroker_client/worker/workerchild.py +++ b/clients/python/src/taskbroker_client/worker/workerchild.py @@ -687,7 +687,9 @@ def _execute_activation( transaction.set_data("taskworker-task.args", args) transaction.set_data("taskworker-task.kwargs", kwargs) - task_added_time = activation.received_at.ToDatetime().timestamp() + # See the note in record_task_execution: ToDatetime().timestamp() + # misreads a naive UTC datetime as local time. + task_added_time = activation.received_at.seconds + activation.received_at.nanos / 1e9 # latency attribute needs to be in milliseconds latency = (time.time() - task_added_time) * 1000 @@ -739,9 +741,28 @@ def record_task_execution( taskbroker_host: str, futures_enqueued_time: float | None = None, ) -> None: - task_added_time = activation.received_at.ToDatetime().timestamp() + # seconds+nanos rather than ToDatetime().timestamp(): ToDatetime() + # returns a NAIVE datetime holding UTC, and .timestamp() then reads it + # as local time, so the value is wrong by the host's UTC offset + # anywhere TZ is not UTC. Containers run UTC so this was latent, but it + # silently skewed every latency reading off-cluster. + task_added_time = activation.received_at.seconds + activation.received_at.nanos / 1e9 execution_duration = completion_time - start_time execution_latency = completion_time - task_added_time + # `execution_latency` minus the part that is the task's own cost, i.e. + # how long the activation sat between the broker receiving it and a + # child picking it up. + # + # This is the term that does NOT scale with task duration, which is + # what makes a single threshold meaningful across pools running very + # different work: a backed-up 4ms pool and a backed-up 4s pool read the + # same wait, where total latency would read 4s apart while both are + # healthy. + # + # Clamped because `received_at` is stamped on the broker and + # `start_time` here, so clock skew between pods can otherwise emit a + # negative sample and distort the percentiles this is read on. + queue_wait = max(0.0, start_time - task_added_time) futures_duration = time.time() - futures_enqueued_time if futures_enqueued_time else 0 logger.debug( @@ -783,6 +804,16 @@ def record_task_execution( "taskbroker_host": taskbroker_host, }, ) + metrics.distribution( + "taskworker.worker.queue_wait", + queue_wait, + tags={ + "namespace": activation.namespace, + "taskname": activation.taskname, + "processing_pool": processing_pool_name, + "taskbroker_host": taskbroker_host, + }, + ) if futures_duration != 0: metrics.distribution( "taskworker.worker.future_completion_duration", diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 7b06155f..f3044827 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -8,7 +8,7 @@ import time from collections.abc import Iterator, MutableMapping from concurrent.futures import Future -from datetime import datetime +from datetime import datetime, timezone from multiprocessing import Event, get_context from multiprocessing.synchronize import Event as MultiprocessingEvent from pathlib import Path @@ -2139,6 +2139,81 @@ def test_child_process_records_busy_and_idle_in_its_slot() -> None: assert timing_shm[SLOT_SEGMENT_START] > 0.0 +def _run_one_task_capturing_metrics(received_at_offset: float) -> mock.Mock: + """Run a single task through a child, with `received_at` set relative to now. + + Returns the mocked metrics backend so callers can assert on what was emitted. + """ + from examples.app import app as example_app + + activation = TaskActivation( + id="queue-wait", + taskname="examples.simple_task", + namespace="examples", + parameters_bytes=msgpack.packb({"args": [], "kwargs": {}}, use_bin_type=True), + processing_deadline_duration=2, + ) + activation.received_at.FromDatetime( + datetime.fromtimestamp(time.time() + received_at_offset, tz=timezone.utc) + ) + + todo: queue.Queue[InflightTaskActivation] = queue.Queue() + processed: queue.Queue[ProcessingResult] = queue.Queue() + todo.put( + InflightTaskActivation(host="localhost:50051", receive_timestamp=0, activation=activation) + ) + + # MagicMock, not Mock: the child uses metrics.timer() and + # metrics.track_memory_usage() as context managers. + metrics = mock.MagicMock() + with mock.patch.object(example_app, "metrics", metrics): + child_process( + "examples.app:app", + todo, + processed, + Event(), + 1, + "test", + "fork", + False, + 0.1, + ) + + assert processed.get(timeout=1).task_id == "queue-wait" + return metrics + + +def test_child_process_emits_queue_wait_excluding_execution_time() -> None: + # queue_wait is execution_latency minus the task's own cost. That is the term + # that does not scale with task duration, which is what lets one alert + # threshold cover pools running very different work. + metrics = _run_one_task_capturing_metrics(received_at_offset=-2.0) + + wait = _distribution_calls(metrics, "taskworker.worker.queue_wait") + latency = _distribution_calls(metrics, "taskworker.worker.execution_latency") + duration = _distribution_calls(metrics, "taskworker.worker.execution_duration") + assert len(wait) == 1 and len(latency) == 1 and len(duration) == 1 + + # The activation was stamped 2s ago and picked up immediately. + assert wait[0].args[1] == pytest.approx(2.0, abs=0.5) + # And it partitions the end-to-end latency with the execution itself. + assert wait[0].args[1] + duration[0].args[1] == pytest.approx(latency[0].args[1], abs=0.01) + + assert wait[0].kwargs["tags"]["processing_pool"] == "test" + assert wait[0].kwargs["tags"]["taskname"] == "examples.simple_task" + + +def test_child_process_queue_wait_clamps_negative_clock_skew() -> None: + # `received_at` is stamped on the broker and the start time here, so an + # NTP-skewed pod can make the difference negative. A negative sample would + # distort the percentiles this metric is read on. + metrics = _run_one_task_capturing_metrics(received_at_offset=+5.0) + + wait = _distribution_calls(metrics, "taskworker.worker.queue_wait") + assert len(wait) == 1 + assert wait[0].args[1] == 0.0 + + def test_child_process_remove_start_time_kwargs() -> None: activation = InflightTaskActivation( host="localhost:50051", From eb8c97587263020097765c5cd9108056ed0c344e Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Wed, 2 Sep 2026 16:14:28 -0400 Subject: [PATCH 08/17] Trim comments to one line Co-Authored-By: Claude Opus 5 (1M context) --- .../taskbroker_client/worker/childtiming.py | 70 +++++--------- .../src/taskbroker_client/worker/worker.py | 65 +++---------- .../taskbroker_client/worker/workerchild.py | 31 +----- clients/python/tests/worker/test_worker.py | 94 ++++++------------- 4 files changed, 67 insertions(+), 193 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py index 34d9a50d..3f6501d0 100644 --- a/clients/python/src/taskbroker_client/worker/childtiming.py +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -1,30 +1,20 @@ """Shared-memory busy/wait accounting for worker children. -Once a second the parent needs to know how many seconds each child spent -executing versus waiting for work. To accomplish that each child owns a slot -in a ``RawArray`` of doubles and writes its own cumulative totals there. The -parent reads and diffs the slots at flush time. +Children write their own cumulative totals into a slot; the parent diffs them at +flush. Costs O(children) per second rather than O(tasks) per second, and there is +no queue to fall behind. Slot layout, five doubles per child:: 0 version seqlock; odd means a write is in progress 1 busy_total cumulative seconds closed into busy 2 wait_total cumulative seconds closed into wait - 3 segment_start time.monotonic() when the currently-open segment began + 3 segment_start time.monotonic() when the open segment began 4 segment_kind KIND_NONE, KIND_WAIT or KIND_BUSY -Two properties carry the design. - -Every value is absolute and cumulative rather than a delta, which is what makes -a torn read survivable: a bad sample is transient and the next one re-derives -the truth from the slot, so error cannot accumulate. - -``KIND_NONE`` is zero, so a freshly zeroed slot reads as "this child has not -accounted for anything yet" rather than as an open segment starting at time -zero. - -``time.monotonic()`` is CLOCK_MONOTONIC, which is system-wide, so a child's -timestamps are directly comparable in the parent. +Values are absolute and cumulative, so a torn read costs one transient sample +that the next flush re-derives. time.monotonic() is CLOCK_MONOTONIC, which is +system-wide, so a child's timestamps are valid in the parent. """ from __future__ import annotations @@ -32,7 +22,6 @@ import ctypes from dataclasses import dataclass -# Offsets within a slot, and the slot stride. SLOT_VERSION = 0 SLOT_BUSY_TOTAL = 1 SLOT_WAIT_TOTAL = 2 @@ -40,36 +29,28 @@ SLOT_SEGMENT_KIND = 4 SLOT_WIDTH = 5 -# Kind values. NONE must be 0.0 so that a zeroed slot means "nothing open". +# NONE must be 0.0 so a zeroed slot reads as "nothing open". KIND_NONE = 0.0 KIND_WAIT = 1.0 KIND_BUSY = 2.0 -# Slot index handed to a child when the pool has none left. Every read and -# write becomes a no-op and the parent leaves that child out of occupancy. +# Handed to a child when the pool has no slot left. Reads and writes are no-ops. NO_SLOT = -1 -# A writer holds the seqlock for four stores, so a reader that loses three -# races in a row is seeing something other than ordinary contention. SEQLOCK_READ_ATTEMPTS = 3 def slot_count(concurrency: int) -> int: - """How many slots a pool of `concurrency` children needs. - - Twice concurrency. `spawn_children_thread` counts only non-exiting children - when deciding how many to spawn, so a full generation of exiting-but-unreaped - children can briefly coexist with a full generation of replacements. - """ + """Twice concurrency, so a generation of unreaped exiting children can + overlap a generation of replacements.""" return max(1, concurrency * 2) class ChildTimeWriter: """Child-side writer for one slot. - The child is the only writer for its slot, so it keeps the authoritative - totals as plain Python floats and republishes the whole slot on each - transition. That avoids a read-modify-write against shared memory. + Sole writer, so it keeps authoritative totals as plain floats and + republishes the whole slot on each transition. """ __slots__ = ("_shm", "_slot", "_base", "_busy_total", "_wait_total", "_start", "_kind") @@ -91,7 +72,7 @@ def _publish(self) -> None: base = self._base version = shm[base + SLOT_VERSION] - # Odd version: a reader that sees this discards what it read. + # Odd: a reader that sees this discards what it read. shm[base + SLOT_VERSION] = version + 1.0 shm[base + SLOT_BUSY_TOTAL] = self._busy_total shm[base + SLOT_WAIT_TOTAL] = self._wait_total @@ -139,9 +120,8 @@ def close(self, now: float) -> None: class ChildTimeAccounting: """Parent-side reader for one child's slot. - Holds the previous absolute reading and returns deltas. A child sitting in a - long task therefore contributes to every interval it spans, instead of - dumping its whole duration into the interval it happens to finish in. + Holds the previous absolute reading and returns deltas, so a child in a long + task contributes to every interval it spans. """ shm: ctypes.Array[ctypes.c_double] | None @@ -153,15 +133,12 @@ class ChildTimeAccounting: def mark_running(self, now: float) -> None: """Start counting this child, baselining against the slot as it stands. - Baselining rather than zeroing means whatever the child banked between - spawning and the parent seeing its `running` message is not credited - retroactively. The child is excluded from `running_count` over that same - window, so the numerator and the denominator start together. + Baselining rather than zeroing drops whatever the child banked before the + parent saw its `running` message, which is the same window over which it + is absent from `running_count`. """ reading = self._read(now) if reading is None: - # Slots are zeroed at allocation, so a failed first read costs at - # most the few microseconds since the child came up. self._prev_busy = 0.0 self._prev_wait = 0.0 else: @@ -170,8 +147,7 @@ def mark_running(self, now: float) -> None: self._accounted = True def mark_stopped(self) -> None: - """Stop counting this child, so an exiting child's tail does not land on - the live pool's occupancy.""" + """Stop counting, so an exiting child's tail misses the live pool.""" self._accounted = False def sample(self, now: float) -> tuple[float, float]: @@ -181,8 +157,7 @@ def sample(self, now: float) -> tuple[float, float]: reading = self._read(now) if reading is None: - # Leave the baseline alone: the next sample then covers both - # intervals. Deferring the attribution beats dropping it. + # Baseline untouched, so the next sample covers both intervals. return (0.0, 0.0) busy_now, wait_now = reading @@ -195,8 +170,7 @@ def sample(self, now: float) -> tuple[float, float]: def _read(self, now: float) -> tuple[float, float] | None: """Seqlock read of absolute busy/wait, including the segment still open. - None means the read could not be taken cleanly and the caller should - keep whatever baseline it already has. + None means the read could not be taken cleanly. """ if self.slot == NO_SLOT or self.shm is None: return None diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index a70d85b5..d2823d7d 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -139,8 +139,7 @@ def __init__( registry=self.registry, ) - # Additive and unclamped, unlike the gauge above: the scaler sums across - # pods and divides once, and no interval clips at 1.0. + # Additive and unclamped: the scaler sums across pods and divides once. self.child_busy_seconds = prometheus_client.Counter( "taskworker_worker_child_busy_seconds", "Cumulative child-seconds spent executing tasks.", @@ -148,8 +147,7 @@ def __init__( registry=self.registry, ) - # What occupancy cannot express: slots that are free with nothing to do. - # Near zero under a backlog means saturated, so more pods help. + # What occupancy cannot express: free slots with nothing to do. self.child_wait_seconds = prometheus_client.Counter( "taskworker_worker_child_wait_seconds", "Cumulative child-seconds spent blocked waiting for a task to arrive.", @@ -236,8 +234,7 @@ class TrackedChild: process: BaseProcess state: ChildState release: Event - # Bound to this child's shared-memory slot at spawn time, so there is no - # sensible default: an accountant with no slot silently measures nothing. + # No default: an accountant with no slot silently measures nothing. timing: ChildTimeAccounting @@ -912,12 +909,7 @@ def __init__( self._children: Dict[UUID, TrackedChild] = {} self._exiting_children: Deque[UUID] = deque() - # Children write their own busy/wait totals here and the parent diffs - # them once a second. Sized for two generations because - # `spawn_children_thread` ignores exiting children when deciding how - # many to spawn, so a full set of unreaped children can briefly overlap - # a full set of replacements. Slots are handed out and returned under - # `_children_lock`. + # Two generations: unreaped exiting children overlap their replacements. self._timing_slots: int = slot_count(concurrency) self._timing_shm: ctypes.Array[ctypes.c_double] = self._mp_context.RawArray( "d", SLOT_WIDTH * self._timing_slots @@ -1022,19 +1014,11 @@ def _emit_periodic_metrics(self) -> None: for child in self._children.values(): state_counts[child.state] += 1 - # Running children only: occupancy divides by `running_count`, - # so folding a `pending` or `exiting` child into the numerator - # measures one population against another. Neither has time to - # lose here. A `pending` child is not being accounted yet, and - # `mark_stopped` deliberately stops accounting an `exiting` - # child so its tail does not count against the live pool. + # Running only: the numerator must match occupancy's divisor. if child.state != "running": continue - # A child with no slot reports nothing, so leaving it in the - # denominator would read as an idle child rather than as a - # missing measurement. `timing_slot_exhausted` is what - # surfaces it instead. + # A slotless child reports nothing; counting it would read as idle. if child.timing.slot == NO_SLOT: continue @@ -1048,8 +1032,7 @@ def _emit_periodic_metrics(self) -> None: elapsed = now - self._last_occupancy_flush_at self._last_occupancy_flush_at = now - # Emitted during warmup too: zero is correct for a counter, unlike for - # the occupancy gauge below where it drags the fleet average down. + # Emitted during warmup too: zero is correct for a counter. self._metrics.distribution( "taskworker.worker.child_busy_seconds", busy_time, @@ -1061,8 +1044,7 @@ def _emit_periodic_metrics(self) -> None: tags=tags, ) if self._prom is not None: - # inc(0.0) registers the series on the first flush, so a new pod - # reads as idle rather than as missing. + # inc(0.0) registers the series, so a new pod reads idle not missing. self._prom.child_busy_seconds.labels(processing_pool=self._processing_pool_name).inc( max(0.0, busy_time) ) @@ -1070,17 +1052,10 @@ def _emit_periodic_metrics(self) -> None: max(0.0, wait_time) ) - # Children the pool could not give a slot to are excluded on both - # sides, so occupancy stays a consistent ratio over the children that - # are actually accounted for. `state_counts` still reports every - # running child to the `children` gauge. + # Slotless children are out of both sides; the gauge still counts them. running_count = accounted_running if running_count > 0 and elapsed > 0: - # A child cannot be busy for longer than the interval, so this is a - # hard physical bound on both counters. Exceeding it means the - # accounting is double billing, and the clamp below would hide that - # behind a healthy-looking 1.0. Emit it so the metric cannot lie - # silently again. + # Physical bound. Exceeding it means the clamp below is hiding a bug. ceiling = elapsed * running_count if busy_time > ceiling or wait_time > ceiling: self._metrics.incr( @@ -1239,12 +1214,7 @@ def spawn_children_thread() -> None: except queue.Empty: break - # How stale the events we are about to apply are. The clamp in - # `TrackedChild._clamp` keeps busy + wait conserved when this - # loop falls behind, but it cannot recover *when* the work - # happened, so occupancy lags by roughly this age. Flat and - # sub-second is healthy; a rising line means this thread is not - # keeping up with the children and the signal is going stale. + # Lifecycle-queue lag. A rising line means this thread is behind. if received: drain_at = time.monotonic() self._metrics.distribution( @@ -1266,10 +1236,7 @@ def spawn_children_thread() -> None: c.process.join(timeout=0) self._children.pop(cid) - # Reclaim here rather than on the `exiting` transition: - # a released child can still publish once before it - # breaks out of its loop, and handing that slot to a - # replacement would mix two children's totals. + # Not at `exiting`: a released child can still publish once. if c.timing.slot != NO_SLOT: self._free_timing_slots.append(c.timing.slot) @@ -1300,10 +1267,7 @@ def spawn_children_thread() -> None: continue - # This child is now running. Baseline against the slot - # as it stands rather than the child's timestamp: the - # child only enters `running_count` here, so starting - # the numerator here keeps the ratio consistent. + # Baseline here, where it also enters `running_count`. if message.event == "running": child.state = "running" child.timing.mark_running(time.monotonic()) @@ -1379,8 +1343,7 @@ def spawn_children_thread() -> None: self._children[child_id] = child except Exception as e: - # The child never came up, so nothing will ever write - # to its slot. + # Never came up, so nothing will write to its slot. self._release_timing_slot(timing_slot) logger.exception( diff --git a/clients/python/src/taskbroker_client/worker/workerchild.py b/clients/python/src/taskbroker_client/worker/workerchild.py index ee70d3aa..3e71ef8a 100644 --- a/clients/python/src/taskbroker_client/worker/workerchild.py +++ b/clients/python/src/taskbroker_client/worker/workerchild.py @@ -172,8 +172,6 @@ def _log_task_retry_exhausted( class ChildMessage: child_id: UUID event: Literal["running", "exiting"] - # Stamped at the event, not when the parent drains it 100ms later. - # CLOCK_MONOTONIC is system-wide, so a child's stamp is valid in the parent. # compare=False: the timestamp is payload, not identity. timestamp: float = field(default_factory=time.monotonic, compare=False) @@ -205,11 +203,7 @@ def child_process( app.load_modules() metrics = app.metrics - # Busy/wait accounting goes straight into shared memory rather than over - # `messages`. The parent's drain thread competes for CPU with the children - # it measures, so at two events per task it falls behind under saturation - # and occupancy goes stale. This costs the parent one read per child per - # second instead. + # Straight to shared memory: `messages` cannot keep up at two events per task. timing = ChildTimeWriter(timing_shm, timing_slot) # Signals when the parent worker pool terminates the child local_shutdown = threading.Event() @@ -687,8 +681,7 @@ def _execute_activation( transaction.set_data("taskworker-task.args", args) transaction.set_data("taskworker-task.kwargs", kwargs) - # See the note in record_task_execution: ToDatetime().timestamp() - # misreads a naive UTC datetime as local time. + # ToDatetime().timestamp() misreads a naive UTC datetime as local. task_added_time = activation.received_at.seconds + activation.received_at.nanos / 1e9 # latency attribute needs to be in milliseconds latency = (time.time() - task_added_time) * 1000 @@ -741,27 +734,11 @@ def record_task_execution( taskbroker_host: str, futures_enqueued_time: float | None = None, ) -> None: - # seconds+nanos rather than ToDatetime().timestamp(): ToDatetime() - # returns a NAIVE datetime holding UTC, and .timestamp() then reads it - # as local time, so the value is wrong by the host's UTC offset - # anywhere TZ is not UTC. Containers run UTC so this was latent, but it - # silently skewed every latency reading off-cluster. + # ToDatetime().timestamp() reads a naive UTC datetime as local time. task_added_time = activation.received_at.seconds + activation.received_at.nanos / 1e9 execution_duration = completion_time - start_time execution_latency = completion_time - task_added_time - # `execution_latency` minus the part that is the task's own cost, i.e. - # how long the activation sat between the broker receiving it and a - # child picking it up. - # - # This is the term that does NOT scale with task duration, which is - # what makes a single threshold meaningful across pools running very - # different work: a backed-up 4ms pool and a backed-up 4s pool read the - # same wait, where total latency would read 4s apart while both are - # healthy. - # - # Clamped because `received_at` is stamped on the broker and - # `start_time` here, so clock skew between pods can otherwise emit a - # negative sample and distort the percentiles this is read on. + # Latency minus the task's own cost, so it does not scale with duration. queue_wait = max(0.0, start_time - task_added_time) futures_duration = time.time() - futures_enqueued_time if futures_enqueued_time else 0 diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index f3044827..4c034bff 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1297,8 +1297,7 @@ def ready_count() -> int: pool_shutdown.assert_called_once_with() -# Slots for children built by `_make_tracked_child`. Independent of any pool: -# the flush reads through `child.timing.shm`, not the pool's array. +# Independent of any pool: the flush reads through `child.timing.shm`. _TEST_SLOTS = 512 _TEST_TIMING_SHM = get_context("fork").RawArray("d", SLOT_WIDTH * _TEST_SLOTS) _TEST_SLOT_SEQ = itertools.count() @@ -1325,8 +1324,7 @@ def _make_tracked_child( _TEST_TIMING_SHM[base + offset] = 0.0 timing = ChildTimeAccounting(shm=_TEST_TIMING_SHM, slot=slot) - # Baseline against the zeroed slot, so everything seeded below lands in - # the first sample. + # Baseline against the zeroed slot, so the seeding below lands in sample 1. timing.mark_running(0.0) if busy_since is not None: @@ -1409,8 +1407,7 @@ def test_emit_periodic_metrics_time_weights_busy_over_the_interval() -> None: assert len(occupancy_calls) == 1 assert occupancy_calls[0].args[1] == pytest.approx(1.24 / 3) - # B's segment is still open, so the next interval picks up where this one - # stopped rather than re-reporting the 0.60 already credited. + # B's segment is still open, so the next interval resumes, not re-reports. assert pool._children[child_b].timing.sample(12.0) == pytest.approx((1.0, 0.0)) for child in pool._children.values(): if child.state == "running": @@ -1441,10 +1438,7 @@ def test_emit_periodic_metrics_divides_by_running_children() -> None: def test_emit_periodic_metrics_clamps_occupancy_and_flags_the_overflow() -> None: - # A child cannot be busy for longer than the interval, so 1.5s of busy over - # a 1s interval is an accounting fault, not a busy pool. Occupancy still has - # to clamp for KEDA, but the fault must be visible: reading a healthy 1.0 - # while the numerator is nonsense is how the double-billing bug hid. + # 1.5s of busy in a 1s interval is a fault; the clamp must not hide it. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() pool._last_occupancy_flush_at = 10.0 @@ -1482,10 +1476,7 @@ def test_emit_periodic_metrics_does_not_flag_a_legitimately_full_pool() -> None: def test_emit_periodic_metrics_excludes_slotless_children_from_occupancy() -> None: - # A child the pool could not give a slot to reports nothing. Leaving it in - # the denominator would read as a genuinely idle child and halve occupancy, - # which is the sort of quiet undercount this whole change exists to remove. - # It still belongs in the `children` gauge: the pod really does have it. + # A slotless child in the denominator would read as idle and halve occupancy. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() pool._last_occupancy_flush_at = 10.0 @@ -1515,9 +1506,7 @@ def test_emit_periodic_metrics_excludes_slotless_children_from_occupancy() -> No def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: - # occupancy divides by running_count, so the counters have to sum over the - # same population. An exiting child folded into the numerator inflates both - # the counters and the gauge against slots that are no longer taking work. + # The counters must sum over the same population occupancy divides by. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() pool._last_occupancy_flush_at = 10.0 @@ -1538,8 +1527,7 @@ def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: def test_spawn_children_binds_each_child_to_its_own_timing_slot() -> None: - # The parent hands the slot to the child at spawn and reads the same slot - # at flush. If those ever disagree the pool measures nothing. + # If spawn and flush disagree on the slot, the pool measures nothing. fake_context = _FakeContext() pool = _make_fake_context_pool(fake_context, concurrency=2) @@ -1555,8 +1543,7 @@ def test_spawn_children_binds_each_child_to_its_own_timing_slot() -> None: slots.add(slot) messages.put(ChildMessage(child_id, "running")) - # _wait_for blocks here, so the closure is resolved inside the - # iteration and does not need a default-argument capture. + # _wait_for blocks, so the closure resolves inside the iteration. _wait_for(lambda: pool._children[child_id].state == "running") assert pool._children[child_id].timing.slot == slot assert shm is pool._timing_shm @@ -1573,8 +1560,7 @@ def _writer_and_reader(slot: int = 0) -> tuple[ChildTimeWriter, ChildTimeAccount def test_child_timing_round_trips_through_shared_memory() -> None: - # The whole point of the slot: the child records the transition itself, so - # nothing has to survive a queue to be counted correctly. + # The child records the transition itself; nothing crosses a queue. writer, reader = _writer_and_reader() writer.mark_running(0.0) @@ -1585,9 +1571,7 @@ def test_child_timing_round_trips_through_shared_memory() -> None: def test_child_timing_credits_a_long_task_to_every_interval_it_spans() -> None: - # A child only knows a segment's width when it ends. Folding the open - # segment forward at read time is what stops a 60s task reporting zero for - # 60 flushes and then 60s at once. + # Without this a 60s task reports zero for 60 flushes, then 60s at once. writer, reader = _writer_and_reader() writer.mark_running(0.0) @@ -1602,9 +1586,7 @@ def test_child_timing_credits_a_long_task_to_every_interval_it_spans() -> None: def test_child_timing_busy_and_wait_partition_every_interval() -> None: - # A running child is always in exactly one state, so busy + wait over any - # sequence of samples has to equal the wall time. This is the invariant - # `occupancy.accounting_overflow` guards in production. + # The invariant `occupancy.accounting_overflow` guards in production. writer, reader = _writer_and_reader() writer.mark_running(0.0) reader.mark_running(0.0) @@ -1632,9 +1614,7 @@ def test_child_timing_busy_and_wait_partition_every_interval() -> None: def test_child_timing_defers_rather_than_drops_a_torn_read() -> None: - # An odd version means the child was mid-publish. Returning zero without - # advancing the baseline means the next sample covers both intervals, so a - # torn read delays attribution instead of losing it. + # Leaving the baseline alone delays attribution instead of losing it. writer, reader = _writer_and_reader() writer.mark_running(0.0) reader.mark_running(0.0) @@ -1650,8 +1630,7 @@ def test_child_timing_defers_rather_than_drops_a_torn_read() -> None: def test_child_timing_stops_accruing_once_the_child_is_released() -> None: - # A released child keeps its wait segment open until it dies. Without this - # the segment folds forward forever and a recycling pool looks starved. + # Otherwise the segment folds forward forever and a recycling pool looks starved. writer, reader = _writer_and_reader() writer.mark_running(0.0) reader.mark_running(0.0) @@ -1663,8 +1642,7 @@ def test_child_timing_stops_accruing_once_the_child_is_released() -> None: def test_child_timing_ignores_a_child_with_no_slot() -> None: - # Degraded mode when the pool runs out of slots. It must report nothing - # rather than raise, since the parent also leaves it out of running_count. + # Degraded mode: report nothing rather than raise. shm = get_context("fork").RawArray("d", SLOT_WIDTH) writer = ChildTimeWriter(shm, NO_SLOT) reader = ChildTimeAccounting(shm=shm, slot=NO_SLOT) @@ -1678,9 +1656,7 @@ def test_child_timing_ignores_a_child_with_no_slot() -> None: def test_child_timing_excludes_time_banked_before_the_parent_saw_running() -> None: - # The child opens its wait clock at warmup, but the parent only counts it in - # running_count once the `running` message lands. Baselining at that moment - # keeps the numerator and the denominator starting together. + # Numerator and denominator must start together, at the `running` message. writer, reader = _writer_and_reader() writer.mark_running(0.0) @@ -1690,13 +1666,10 @@ def test_child_timing_excludes_time_banked_before_the_parent_saw_running() -> No def test_acquire_timing_slot_zeroes_a_recycled_slot() -> None: - # Slots outlive children. A replacement must not inherit its predecessor's - # totals, or its first sample reports the dead child's whole lifetime. + # A replacement must not inherit its predecessor's totals. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) - # Drain the free list so the release below is the only slot available. Reuse - # is FIFO, which deliberately leaves the longest possible gap between a slot - # being returned and handed out again. + # Drain the free list: reuse is FIFO, so a release is not reused next. slot = pool._acquire_timing_slot() rest = [pool._acquire_timing_slot() for _ in range(slot_count(1) - 1)] assert NO_SLOT not in rest @@ -1716,8 +1689,7 @@ def test_acquire_timing_slot_zeroes_a_recycled_slot() -> None: def test_acquire_timing_slot_reports_exhaustion_instead_of_raising() -> None: - # Sizing should make this unreachable, so if it ever fires the metric is how - # we find out. The pool has to keep spawning either way. + # Should be unreachable; the pool has to keep spawning either way. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) pool._metrics = mock.Mock() @@ -1749,16 +1721,14 @@ def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: assert busy[0].args[1] == pytest.approx(1.75) assert wait[0].args[1] == pytest.approx(0.25) - # The scaler divides the pair, recovering occupancy without needing the - # flush interval or the running-child count. + # The scaler divides the pair, needing neither interval nor child count. assert busy[0].args[1] / (busy[0].args[1] + wait[0].args[1]) == pytest.approx(0.875) occupancy_calls = _gauge_calls(pool._metrics, "taskworker.worker.occupancy") assert occupancy_calls[0].args[1] == pytest.approx(1.75 / 2) def test_emit_periodic_metrics_emits_counters_during_warmup() -> None: - # Emitted with no running children, unlike occupancy: zero is correct for a - # counter and separates "idle" from "not reporting". + # Unlike occupancy: zero separates "idle" from "not reporting". pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() @@ -1773,9 +1743,7 @@ def test_emit_periodic_metrics_emits_counters_during_warmup() -> None: def test_spawn_children_reads_transitions_the_child_wrote() -> None: - # End to end through the real handoff: the child publishes into the slot - # it was given, and the parent's accountant reports that split without a - # single message crossing the queue. + # End to end through the real handoff, with no message crossing the queue. fake_context = _FakeContext() pool = _make_fake_context_pool(fake_context, concurrency=1) @@ -1792,8 +1760,7 @@ def test_spawn_children_reads_transitions_the_child_wrote() -> None: _wait_for(lambda: pool.ready_count == 1) child = pool._children[child_id] - # Rebaseline onto the child's clock; the parent normally does this the - # moment it drains `running`, against its own monotonic reading. + # Rebaseline onto the child's clock; normally done when draining `running`. child.timing.mark_running(0.0) # 2s waiting, 1s of work, then waiting again. @@ -2075,8 +2042,7 @@ def test_child_process_emits_exiting_once_and_continues_until_release( ) process.start() try: - # Only lifecycle events cross the queue now, two per child rather than - # two per task. That reduction is the whole point of the slot. + # Lifecycle only now: two per child rather than two per task. assert messages.get(timeout=5) == ChildMessage(child_id, "running") assert messages.get(timeout=5) == ChildMessage(child_id, "exiting") assert processed.get(timeout=5).task_id == SIMPLE_TASK.activation.id @@ -2131,8 +2097,7 @@ def test_child_process_records_busy_and_idle_in_its_slot() -> None: assert messages.get(timeout=1) == ChildMessage(child_id, "running") assert processed.get(timeout=1).task_id == SIMPLE_TASK.activation.id - # One task ran to completion, so the child closed a busy segment into its - # slot and reopened the wait clock behind it. + # One task completed, so a busy segment closed and the wait clock reopened. assert timing_shm[SLOT_BUSY_TOTAL] > 0.0 assert timing_shm[SLOT_SEGMENT_KIND] == KIND_WAIT assert timing_shm[SLOT_VERSION] % 2 == 0 @@ -2163,8 +2128,7 @@ def _run_one_task_capturing_metrics(received_at_offset: float) -> mock.Mock: InflightTaskActivation(host="localhost:50051", receive_timestamp=0, activation=activation) ) - # MagicMock, not Mock: the child uses metrics.timer() and - # metrics.track_memory_usage() as context managers. + # MagicMock: the child uses metrics.timer() as a context manager. metrics = mock.MagicMock() with mock.patch.object(example_app, "metrics", metrics): child_process( @@ -2184,9 +2148,7 @@ def _run_one_task_capturing_metrics(received_at_offset: float) -> mock.Mock: def test_child_process_emits_queue_wait_excluding_execution_time() -> None: - # queue_wait is execution_latency minus the task's own cost. That is the term - # that does not scale with task duration, which is what lets one alert - # threshold cover pools running very different work. + # Latency minus the task's own cost, so one threshold covers every pool. metrics = _run_one_task_capturing_metrics(received_at_offset=-2.0) wait = _distribution_calls(metrics, "taskworker.worker.queue_wait") @@ -2204,9 +2166,7 @@ def test_child_process_emits_queue_wait_excluding_execution_time() -> None: def test_child_process_queue_wait_clamps_negative_clock_skew() -> None: - # `received_at` is stamped on the broker and the start time here, so an - # NTP-skewed pod can make the difference negative. A negative sample would - # distort the percentiles this metric is read on. + # An NTP-skewed pod would otherwise emit a negative sample. metrics = _run_one_task_capturing_metrics(received_at_offset=+5.0) wait = _distribution_calls(metrics, "taskworker.worker.queue_wait") From ccc6326bfdbf516cebabf431179ffe2530428b4b Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Wed, 2 Sep 2026 16:40:28 -0400 Subject: [PATCH 09/17] Add observability for occupancy under-reporting 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) --- .../taskbroker_client/worker/childtiming.py | 39 ++++- .../src/taskbroker_client/worker/worker.py | 54 ++++++- clients/python/tests/worker/test_worker.py | 139 +++++++++++++++--- 3 files changed, 204 insertions(+), 28 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py index 3f6501d0..1bf26446 100644 --- a/clients/python/src/taskbroker_client/worker/childtiming.py +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -40,6 +40,21 @@ SEQLOCK_READ_ATTEMPTS = 3 +@dataclass(frozen=True) +class SampleResult: + """One child's contribution to a flush, plus why it may be short. + + `eligible` is how much of the interval this child could have accrued in at + all. It differs from the interval width for a child baselined part-way + through, which the `elapsed * running_count` ceiling treats as whole. + """ + + busy: float = 0.0 + wait: float = 0.0 + eligible: float = 0.0 + reason: str = "ok" + + def slot_count(concurrency: int) -> int: """Twice concurrency, so a generation of unreaped exiting children can overlap a generation of replacements.""" @@ -129,6 +144,9 @@ class ChildTimeAccounting: _prev_busy: float = 0.0 _prev_wait: float = 0.0 _accounted: bool = False + # When this child started being counted, so a flush can tell a short + # sample apart from a child that was only eligible for part of it. + _baselined_at: float = 0.0 def mark_running(self, now: float) -> None: """Start counting this child, baselining against the slot as it stands. @@ -145,27 +163,34 @@ def mark_running(self, now: float) -> None: self._prev_busy, self._prev_wait = reading self._accounted = True + self._baselined_at = now def mark_stopped(self) -> None: """Stop counting, so an exiting child's tail misses the live pool.""" self._accounted = False - def sample(self, now: float) -> tuple[float, float]: - """Return (busy, wait) seconds accrued since the previous sample.""" + def sample(self, now: float, interval_start: float = 0.0) -> SampleResult: + """Return this child's busy/wait since the previous sample.""" if not self._accounted: - return (0.0, 0.0) + return SampleResult(reason="not_accounted") + + eligible = max(0.0, now - max(interval_start, self._baselined_at)) reading = self._read(now) if reading is None: # Baseline untouched, so the next sample covers both intervals. - return (0.0, 0.0) + return SampleResult(eligible=eligible, reason="read_failed") busy_now, wait_now = reading - busy = max(0.0, busy_now - self._prev_busy) - wait = max(0.0, wait_now - self._prev_wait) + raw_busy = busy_now - self._prev_busy + raw_wait = wait_now - self._prev_wait + # A total going backwards means a torn read or a reused slot, and the + # clamp below silently drops that time. + reason = "clamped" if raw_busy < 0.0 or raw_wait < 0.0 else "ok" + self._prev_busy = busy_now self._prev_wait = wait_now - return (busy, wait) + return SampleResult(max(0.0, raw_busy), max(0.0, raw_wait), eligible, reason) def _read(self, now: float) -> tuple[float, float] | None: """Seqlock read of absolute busy/wait, including the segment still open. diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index d2823d7d..c2c1803b 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -1011,6 +1011,9 @@ def _emit_periodic_metrics(self) -> None: busy_time = 0.0 wait_time = 0.0 accounted_running = 0 + eligible_time = 0.0 + outcomes: dict[str, int] = {} + interval_start = self._last_occupancy_flush_at for child in self._children.values(): state_counts[child.state] += 1 @@ -1023,9 +1026,11 @@ def _emit_periodic_metrics(self) -> None: continue accounted_running += 1 - busy, wait = child.timing.sample(now) - busy_time += busy - wait_time += wait + result = child.timing.sample(now, interval_start) + busy_time += result.busy + wait_time += result.wait + eligible_time += result.eligible + outcomes[result.reason] = outcomes.get(result.reason, 0) + 1 exiting_children = len(self._exiting_children) @@ -1074,6 +1079,49 @@ def _emit_periodic_metrics(self) -> None: }, ) + # How much of the ceiling the counters actually account for. The + # overflow guard above is one-sided; this is the other direction, + # where occupancy reads low because time went missing rather than + # because the pool was idle. + self._metrics.gauge( + "taskworker.worker.occupancy.accounting_ratio", + (busy_time + wait_time) / ceiling, + tags=tags, + ) + # Same numerator against the time children were actually eligible + # for. A child baselined mid-interval counts whole in `ceiling` but + # only partly here, so if this reads ~1.0 while the ratio above + # reads low, the denominator is the fault, not the accounting. + if eligible_time > 0: + self._metrics.gauge( + "taskworker.worker.occupancy.eligible_ratio", + (busy_time + wait_time) / eligible_time, + tags=tags, + ) + for reason, count in outcomes.items(): + self._metrics.incr( + "taskworker.worker.occupancy.sample_outcome", + count, + tags={**tags, "reason": reason}, + ) + if busy_time + wait_time < ceiling * 0.9: + self._metrics.incr( + "taskworker.worker.occupancy.accounting_deficit", + tags=tags, + ) + logger.warning( + "taskworker.worker.occupancy.accounting_deficit", + extra={ + "busy_time": busy_time, + "wait_time": wait_time, + "eligible_time": eligible_time, + "running_count": running_count, + "elapsed": elapsed, + "outcomes": outcomes, + "processing_pool": self._processing_pool_name, + }, + ) + occupancy = busy_time / ceiling occupancy = min(occupancy, 1.0) self._metrics.gauge( diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 4c034bff..33a79c88 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1310,6 +1310,7 @@ def _make_tracked_child( busy_accumulated: float = 0.0, wait_since: float | None = None, wait_accumulated: float = 0.0, + baselined_at: float | None = None, ) -> TrackedChild: """Seed a child's slot so its next sample reports the given time. @@ -1325,7 +1326,7 @@ def _make_tracked_child( timing = ChildTimeAccounting(shm=_TEST_TIMING_SHM, slot=slot) # Baseline against the zeroed slot, so the seeding below lands in sample 1. - timing.mark_running(0.0) + timing.mark_running(0.0 if baselined_at is None else baselined_at) if busy_since is not None: kind, start = KIND_BUSY, busy_since @@ -1348,6 +1349,11 @@ def _make_tracked_child( ) +def _bw(result: Any) -> tuple[float, float]: + """The (busy, wait) pair from a SampleResult, dropping the diagnostics.""" + return (result.busy, result.wait) + + def _distribution_calls(metrics: mock.Mock, name: str) -> list[Any]: return [c for c in metrics.distribution.call_args_list if c.args[0] == name] @@ -1408,10 +1414,10 @@ def test_emit_periodic_metrics_time_weights_busy_over_the_interval() -> None: assert occupancy_calls[0].args[1] == pytest.approx(1.24 / 3) # B's segment is still open, so the next interval resumes, not re-reports. - assert pool._children[child_b].timing.sample(12.0) == pytest.approx((1.0, 0.0)) + assert _bw(pool._children[child_b].timing.sample(12.0)) == pytest.approx((1.0, 0.0)) for child in pool._children.values(): if child.state == "running": - assert child.timing.sample(12.0)[0] == pytest.approx(0.0) + assert child.timing.sample(12.0).busy == pytest.approx(0.0) assert pool._last_occupancy_flush_at == pytest.approx(11.0) @@ -1475,6 +1481,103 @@ def test_emit_periodic_metrics_does_not_flag_a_legitimately_full_pool() -> None: assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] +def test_emit_periodic_metrics_separates_a_short_sample_from_a_short_interval() -> None: + # The discriminator for the cell-6 deficit. A child baselined mid-interval can + # only accrue over part of it, but `elapsed * running_count` counts it whole, + # so occupancy reads low with no time actually missing. eligible_ratio near 1.0 + # while accounting_ratio reads low means the denominator is at fault. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.5, baselined_at=10.5) + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + # 1.0 + 0.5 busy-seconds against a ceiling of 2.0. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ + 1 + ] == pytest.approx(0.75) + # But only 1.5 child-seconds were ever available. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.eligible_ratio")[0].args[ + 1 + ] == pytest.approx(1.0) + # Nothing went missing, so every sample is clean. + reasons = { + c.kwargs["tags"]["reason"] + for c in _incr_calls(pool._metrics, "taskworker.worker.occupancy.sample_outcome") + } + assert reasons == {"ok"} + + +def test_emit_periodic_metrics_flags_a_deficit_and_names_the_reason() -> None: + # The mirror of accounting_overflow. Occupancy reading low because time went + # missing is the exact failure this project started from, and the overflow + # guard is blind to it. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + stalled = _make_tracked_child("running", busy_since=10.0) + stalled.timing.mark_stopped() + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = stalled + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + assert len(_incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit")) == 1 + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ + 1 + ] == pytest.approx(0.5) + reasons = { + c.kwargs["tags"]["reason"] + for c in _incr_calls(pool._metrics, "taskworker.worker.occupancy.sample_outcome") + } + assert reasons == {"ok", "not_accounted"} + + +def test_emit_periodic_metrics_does_not_flag_a_deficit_when_time_is_all_there() -> None: + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = _make_tracked_child("running", wait_since=10.0) + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit") == [] + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ + 1 + ] == pytest.approx(1.0) + + +def test_sample_reports_a_clamped_read_rather_than_hiding_it() -> None: + # A total going backwards means a torn read or a reused slot. The clamp keeps + # the number sane but drops real time, so the drop has to be visible. + writer, reader = _writer_and_reader() + writer.mark_running(0.0) + reader.mark_running(0.0) + writer.mark_busy(0.0) + assert reader.sample(1.0).reason == "ok" + + # Rewind the slot underneath the reader, as slot reuse would. + reader.shm[SLOT_BUSY_TOTAL] = 0.0 # type: ignore[index] + reader.shm[SLOT_SEGMENT_START] = 2.0 # type: ignore[index] + + result = reader.sample(2.0) + assert result.reason == "clamped" + assert result.busy == 0.0 + + def test_emit_periodic_metrics_excludes_slotless_children_from_occupancy() -> None: # A slotless child in the denominator would read as idle and halve occupancy. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) @@ -1567,7 +1670,7 @@ def test_child_timing_round_trips_through_shared_memory() -> None: reader.mark_running(0.0) writer.mark_busy(1.0) - assert reader.sample(2.0) == pytest.approx((1.0, 1.0)) + assert _bw(reader.sample(2.0)) == pytest.approx((1.0, 1.0)) def test_child_timing_credits_a_long_task_to_every_interval_it_spans() -> None: @@ -1578,11 +1681,11 @@ def test_child_timing_credits_a_long_task_to_every_interval_it_spans() -> None: reader.mark_running(0.0) writer.mark_busy(0.0) - assert reader.sample(1.0) == pytest.approx((1.0, 0.0)) - assert reader.sample(2.0) == pytest.approx((1.0, 0.0)) + assert _bw(reader.sample(1.0)) == pytest.approx((1.0, 0.0)) + assert _bw(reader.sample(2.0)) == pytest.approx((1.0, 0.0)) writer.mark_idle(2.5) - assert reader.sample(3.0) == pytest.approx((0.5, 0.5)) + assert _bw(reader.sample(3.0)) == pytest.approx((0.5, 0.5)) def test_child_timing_busy_and_wait_partition_every_interval() -> None: @@ -1602,11 +1705,11 @@ def test_child_timing_busy_and_wait_partition_every_interval() -> None: (writer.mark_busy if busy else writer.mark_idle)(now) if i % 7 == 0: - b, w = reader.sample(now) + b, w = _bw(reader.sample(now)) total_busy += b total_wait += w - b, w = reader.sample(now) + b, w = _bw(reader.sample(now)) total_busy += b total_wait += w @@ -1620,13 +1723,13 @@ def test_child_timing_defers_rather_than_drops_a_torn_read() -> None: reader.mark_running(0.0) writer.mark_busy(0.0) - assert reader.sample(1.0) == pytest.approx((1.0, 0.0)) + assert _bw(reader.sample(1.0)) == pytest.approx((1.0, 0.0)) reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] - assert reader.sample(2.0) == pytest.approx((0.0, 0.0)) + assert _bw(reader.sample(2.0)) == pytest.approx((0.0, 0.0)) reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] - assert reader.sample(3.0) == pytest.approx((2.0, 0.0)) + assert _bw(reader.sample(3.0)) == pytest.approx((2.0, 0.0)) def test_child_timing_stops_accruing_once_the_child_is_released() -> None: @@ -1635,10 +1738,10 @@ def test_child_timing_stops_accruing_once_the_child_is_released() -> None: writer.mark_running(0.0) reader.mark_running(0.0) - assert reader.sample(0.5)[1] == pytest.approx(0.5) + assert reader.sample(0.5).wait == pytest.approx(0.5) reader.mark_stopped() - assert reader.sample(20.0) == pytest.approx((0.0, 0.0)) + assert _bw(reader.sample(20.0)) == pytest.approx((0.0, 0.0)) def test_child_timing_ignores_a_child_with_no_slot() -> None: @@ -1651,7 +1754,7 @@ def test_child_timing_ignores_a_child_with_no_slot() -> None: writer.mark_busy(1.0) reader.mark_running(0.0) - assert reader.sample(10.0) == pytest.approx((0.0, 0.0)) + assert _bw(reader.sample(10.0)) == pytest.approx((0.0, 0.0)) assert shm[SLOT_SEGMENT_KIND] == KIND_NONE @@ -1662,7 +1765,7 @@ def test_child_timing_excludes_time_banked_before_the_parent_saw_running() -> No writer.mark_running(0.0) reader.mark_running(5.0) # parent drained the message 5s later - assert reader.sample(6.0) == pytest.approx((0.0, 1.0)) + assert _bw(reader.sample(6.0)) == pytest.approx((0.0, 1.0)) def test_acquire_timing_slot_zeroes_a_recycled_slot() -> None: @@ -1685,7 +1788,7 @@ def test_acquire_timing_slot_zeroes_a_recycled_slot() -> None: reader = ChildTimeAccounting(shm=pool._timing_shm, slot=recycled) reader.mark_running(0.0) - assert reader.sample(1.0) == pytest.approx((0.0, 0.0)) + assert _bw(reader.sample(1.0)) == pytest.approx((0.0, 0.0)) def test_acquire_timing_slot_reports_exhaustion_instead_of_raising() -> None: @@ -1767,7 +1870,7 @@ def test_spawn_children_reads_transitions_the_child_wrote() -> None: writer.mark_busy(2.0) writer.mark_idle(3.0) - assert child.timing.sample(4.0) == pytest.approx((1.0, 3.0)) + assert _bw(child.timing.sample(4.0)) == pytest.approx((1.0, 3.0)) finally: pool.shutdown() From 0715691b4a43f5a35710b0d99eb8c800ba45e6a8 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Thu, 3 Sep 2026 11:05:39 -0400 Subject: [PATCH 10/17] Divide occupancy by eligible time, not headcount `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) --- .../taskbroker_client/worker/childtiming.py | 29 +++-- .../src/taskbroker_client/worker/worker.py | 25 +++-- clients/python/tests/worker/test_worker.py | 106 +++++++++++++++--- 3 files changed, 120 insertions(+), 40 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py index 1bf26446..3b6472ea 100644 --- a/clients/python/src/taskbroker_client/worker/childtiming.py +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -44,9 +44,9 @@ class SampleResult: """One child's contribution to a flush, plus why it may be short. - `eligible` is how much of the interval this child could have accrued in at - all. It differs from the interval width for a child baselined part-way - through, which the `elapsed * running_count` ceiling treats as whole. + `eligible` is the window this child's busy and wait were measured over, and + the pool sums it to get occupancy's denominator. A headcount times the flush + interval would instead bill a child baselined part-way through as whole. """ busy: float = 0.0 @@ -144,9 +144,10 @@ class ChildTimeAccounting: _prev_busy: float = 0.0 _prev_wait: float = 0.0 _accounted: bool = False - # When this child started being counted, so a flush can tell a short - # sample apart from a child that was only eligible for part of it. - _baselined_at: float = 0.0 + # Start of the window the next delta will cover. Advances only on a + # successful read, so a deferred sample carries its eligibility forward with + # it and `busy + wait <= eligible` survives a seqlock retry. + _measured_from: float = 0.0 def mark_running(self, now: float) -> None: """Start counting this child, baselining against the slot as it stands. @@ -163,22 +164,27 @@ def mark_running(self, now: float) -> None: self._prev_busy, self._prev_wait = reading self._accounted = True - self._baselined_at = now + self._measured_from = now def mark_stopped(self) -> None: """Stop counting, so an exiting child's tail misses the live pool.""" self._accounted = False - def sample(self, now: float, interval_start: float = 0.0) -> SampleResult: - """Return this child's busy/wait since the previous sample.""" + def sample(self, now: float) -> SampleResult: + """Return this child's busy/wait since the previous sample. + + `eligible` is the width of that same window, so it is the honest ceiling + on what this child could have contributed. It is shorter than the flush + interval for a child baselined part-way through one. + """ if not self._accounted: return SampleResult(reason="not_accounted") - eligible = max(0.0, now - max(interval_start, self._baselined_at)) + eligible = max(0.0, now - self._measured_from) reading = self._read(now) if reading is None: - # Baseline untouched, so the next sample covers both intervals. + # Neither baseline advances, so the next sample covers both windows. return SampleResult(eligible=eligible, reason="read_failed") busy_now, wait_now = reading @@ -190,6 +196,7 @@ def sample(self, now: float, interval_start: float = 0.0) -> SampleResult: self._prev_busy = busy_now self._prev_wait = wait_now + self._measured_from = now return SampleResult(max(0.0, raw_busy), max(0.0, raw_wait), eligible, reason) def _read(self, now: float) -> tuple[float, float] | None: diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index c2c1803b..567e93e6 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -1013,7 +1013,6 @@ def _emit_periodic_metrics(self) -> None: accounted_running = 0 eligible_time = 0.0 outcomes: dict[str, int] = {} - interval_start = self._last_occupancy_flush_at for child in self._children.values(): state_counts[child.state] += 1 @@ -1026,7 +1025,7 @@ def _emit_periodic_metrics(self) -> None: continue accounted_running += 1 - result = child.timing.sample(now, interval_start) + result = child.timing.sample(now) busy_time += result.busy wait_time += result.wait eligible_time += result.eligible @@ -1059,9 +1058,12 @@ def _emit_periodic_metrics(self) -> None: # Slotless children are out of both sides; the gauge still counts them. running_count = accounted_running - if running_count > 0 and elapsed > 0: - # Physical bound. Exceeding it means the clamp below is hiding a bug. - ceiling = elapsed * running_count + if running_count > 0 and eligible_time > 0: + # Sum of the windows the children were each measured over, not a + # headcount times the interval: one baselined part-way through a + # flush could never have filled it, and billing it whole reads as + # idle time the pool never had. + ceiling = eligible_time if busy_time > ceiling or wait_time > ceiling: self._metrics.incr( "taskworker.worker.occupancy.accounting_overflow", @@ -1082,20 +1084,19 @@ def _emit_periodic_metrics(self) -> None: # How much of the ceiling the counters actually account for. The # overflow guard above is one-sided; this is the other direction, # where occupancy reads low because time went missing rather than - # because the pool was idle. + # because the pool was idle. Should sit at 1.0. self._metrics.gauge( "taskworker.worker.occupancy.accounting_ratio", (busy_time + wait_time) / ceiling, tags=tags, ) - # Same numerator against the time children were actually eligible - # for. A child baselined mid-interval counts whole in `ceiling` but - # only partly here, so if this reads ~1.0 while the ratio above - # reads low, the denominator is the fault, not the accounting. - if eligible_time > 0: + # Size of the correction the ceiling above applies. Below 1.0 means + # children were baselined part-way through this flush, which is what + # a headcount denominator would have mistaken for idle time. + if elapsed > 0: self._metrics.gauge( "taskworker.worker.occupancy.eligible_ratio", - (busy_time + wait_time) / eligible_time, + eligible_time / (elapsed * running_count), tags=tags, ) for reason, count in outcomes.items(): diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 33a79c88..24490525 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1310,7 +1310,7 @@ def _make_tracked_child( busy_accumulated: float = 0.0, wait_since: float | None = None, wait_accumulated: float = 0.0, - baselined_at: float | None = None, + measured_from: float = 10.0, ) -> TrackedChild: """Seed a child's slot so its next sample reports the given time. @@ -1326,7 +1326,10 @@ def _make_tracked_child( timing = ChildTimeAccounting(shm=_TEST_TIMING_SHM, slot=slot) # Baseline against the zeroed slot, so the seeding below lands in sample 1. - timing.mark_running(0.0 if baselined_at is None else baselined_at) + # The default matches the `_last_occupancy_flush_at = 10.0` every occupancy + # test sets, so a child is measurable for the whole interval unless told + # otherwise. + timing.mark_running(measured_from) if busy_since is not None: kind, start = KIND_BUSY, busy_since @@ -1481,30 +1484,35 @@ def test_emit_periodic_metrics_does_not_flag_a_legitimately_full_pool() -> None: assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] -def test_emit_periodic_metrics_separates_a_short_sample_from_a_short_interval() -> None: - # The discriminator for the cell-6 deficit. A child baselined mid-interval can - # only accrue over part of it, but `elapsed * running_count` counts it whole, - # so occupancy reads low with no time actually missing. eligible_ratio near 1.0 - # while accounting_ratio reads low means the denominator is at fault. +def test_emit_periodic_metrics_bills_a_mid_interval_child_only_for_its_own_window() -> None: + # Interval [10.0, 11.0]. One child measurable throughout, one baselined at + # 10.5 and busy from then. Both were busy every second they were counted, so + # occupancy is 1.0. A headcount ceiling would have read 1.5/2.0 = 0.75 and + # invented half a second of idle that never existed. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) - pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.5, baselined_at=10.5) + pool._children[uuid4()] = _make_tracked_child( + "running", busy_since=10.5, measured_from=10.5 + ) with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): pool._emit_periodic_metrics() - # 1.0 + 0.5 busy-seconds against a ceiling of 2.0. + # 1.5 busy-seconds over the 1.5 child-seconds that were available. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( + 1.0 + ) assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ 1 - ] == pytest.approx(0.75) - # But only 1.5 child-seconds were ever available. + ] == pytest.approx(1.0) + # 1.5 available against the 2.0 a headcount would have claimed. assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.eligible_ratio")[0].args[ 1 - ] == pytest.approx(1.0) + ] == pytest.approx(0.75) # Nothing went missing, so every sample is clean. reasons = { c.kwargs["tags"]["reason"] @@ -1514,9 +1522,46 @@ def test_emit_periodic_metrics_separates_a_short_sample_from_a_short_interval() def test_emit_periodic_metrics_flags_a_deficit_and_names_the_reason() -> None: - # The mirror of accounting_overflow. Occupancy reading low because time went - # missing is the exact failure this project started from, and the overflow - # guard is blind to it. + # The mirror of accounting_overflow. Now that the ceiling is the summed + # eligible window, a deficit can only mean a measurable child reported less + # than its own window, which is time genuinely lost rather than a + # denominator artifact. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + pool._last_occupancy_flush_at = 10.0 + + # Baseline at 5.0, then drop the slot's total: a reused slot or a torn read. + lost = _make_tracked_child("running", busy_accumulated=5.0) + lost.timing.sample(10.0) + _TEST_TIMING_SHM[lost.timing.slot * SLOT_WIDTH + SLOT_BUSY_TOTAL] = 0.2 + + with pool._children_lock: + pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) + pool._children[uuid4()] = lost + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + assert len(_incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit")) == 1 + # 1.0 busy-second reported against the 2.0 both children were eligible for. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ + 1 + ] == pytest.approx(0.5) + # The denominator is honest, so this stays at 1.0 and does not mask the loss. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.eligible_ratio")[0].args[ + 1 + ] == pytest.approx(1.0) + reasons = { + c.kwargs["tags"]["reason"] + for c in _incr_calls(pool._metrics, "taskworker.worker.occupancy.sample_outcome") + } + assert reasons == {"ok", "clamped"} + + +def test_emit_periodic_metrics_reports_an_unmeasurable_child_through_eligible_ratio() -> None: + # A running child whose accounting is switched off supplies no window, so it + # cannot drag occupancy down the way a headcount denominator would have made + # it. eligible_ratio is what says the headcount exceeded the measured set. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() pool._last_occupancy_flush_at = 10.0 @@ -1531,8 +1576,13 @@ def test_emit_periodic_metrics_flags_a_deficit_and_names_the_reason() -> None: with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): pool._emit_periodic_metrics() - assert len(_incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit")) == 1 - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ + # The one child that could be measured was busy throughout. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( + 1.0 + ) + assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit") == [] + # Half the counted children supplied no window at all. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.eligible_ratio")[0].args[ 1 ] == pytest.approx(0.5) reasons = { @@ -1732,6 +1782,28 @@ def test_child_timing_defers_rather_than_drops_a_torn_read() -> None: assert _bw(reader.sample(3.0)) == pytest.approx((2.0, 0.0)) +def test_child_timing_carries_eligibility_across_a_deferred_sample() -> None: + # The recovering sample reports two intervals of busy, so it must report two + # intervals of eligible with it. Otherwise 2.0 busy lands against a 1.0 + # ceiling and the pool trips accounting_overflow every time a read retries. + writer, reader = _writer_and_reader() + writer.mark_running(0.0) + reader.mark_running(0.0) + writer.mark_busy(0.0) + + assert reader.sample(1.0).eligible == pytest.approx(1.0) + + reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + deferred = reader.sample(2.0) + assert deferred.reason == "read_failed" + + reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + recovered = reader.sample(3.0) + assert recovered.busy == pytest.approx(2.0) + assert recovered.eligible == pytest.approx(2.0) + assert recovered.busy <= recovered.eligible + + def test_child_timing_stops_accruing_once_the_child_is_released() -> None: # Otherwise the segment folds forward forever and a recycling pool looks starved. writer, reader = _writer_and_reader() From 8dee8d4908004e1822d86efcde20320478729c14 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Thu, 3 Sep 2026 11:17:53 -0400 Subject: [PATCH 11/17] Cut the diagnostic metrics back to the two that matter 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) --- .../taskbroker_client/worker/childtiming.py | 93 +++++++-------- .../src/taskbroker_client/worker/worker.py | 106 ++++++------------ .../taskbroker_client/worker/workerchild.py | 2 +- clients/python/tests/worker/test_worker.py | 100 +++++------------ 4 files changed, 115 insertions(+), 186 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py index 3b6472ea..1785dc0a 100644 --- a/clients/python/src/taskbroker_client/worker/childtiming.py +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -1,8 +1,14 @@ """Shared-memory busy/wait accounting for worker children. -Children write their own cumulative totals into a slot; the parent diffs them at -flush. Costs O(children) per second rather than O(tasks) per second, and there is -no queue to fall behind. +Each child owns a slot and writes its own cumulative totals into it. The parent +reads every slot once per flush and diffs against its previous reading, so the +cost is O(children) per second rather than O(tasks) per second. + +The parent reads rather than having children emit their own metrics because a +child only knows a segment's length once it ends: a child sitting in a 30s task +would report nothing for 30 flushes and then 30s at once. The parent folds the +open segment forward at read time instead, so that child contributes to every +interval it spans. Slot layout, five doubles per child:: @@ -12,9 +18,10 @@ 3 segment_start time.monotonic() when the open segment began 4 segment_kind KIND_NONE, KIND_WAIT or KIND_BUSY -Values are absolute and cumulative, so a torn read costs one transient sample -that the next flush re-derives. time.monotonic() is CLOCK_MONOTONIC, which is -system-wide, so a child's timestamps are valid in the parent. +Every value is absolute, so a torn read costs one transient sample that the next +flush re-derives from the totals rather than accumulating drift. +`time.monotonic()` is CLOCK_MONOTONIC, which is system-wide, so a child's +timestamps are directly comparable in the parent. """ from __future__ import annotations @@ -29,7 +36,8 @@ SLOT_SEGMENT_KIND = 4 SLOT_WIDTH = 5 -# NONE must be 0.0 so a zeroed slot reads as "nothing open". +# NONE must be 0.0 so a freshly zeroed slot reads as "nothing open". Any other +# value and the parent would fold `now - 0.0` forward as elapsed time. KIND_NONE = 0.0 KIND_WAIT = 1.0 KIND_BUSY = 2.0 @@ -42,17 +50,15 @@ @dataclass(frozen=True) class SampleResult: - """One child's contribution to a flush, plus why it may be short. + """One child's busy and wait, and the window they were measured over. - `eligible` is the window this child's busy and wait were measured over, and - the pool sums it to get occupancy's denominator. A headcount times the flush - interval would instead bill a child baselined part-way through as whole. + `busy + wait` should equal `eligible`. The pool sums all three and compares + them to catch time that was double-counted or dropped. """ busy: float = 0.0 wait: float = 0.0 eligible: float = 0.0 - reason: str = "ok" def slot_count(concurrency: int) -> int: @@ -64,8 +70,8 @@ def slot_count(concurrency: int) -> int: class ChildTimeWriter: """Child-side writer for one slot. - Sole writer, so it keeps authoritative totals as plain floats and - republishes the whole slot on each transition. + The child is the only writer, so it keeps authoritative totals as plain + floats and republishes the whole slot on each transition. """ __slots__ = ("_shm", "_slot", "_base", "_busy_total", "_wait_total", "_start", "_kind") @@ -80,6 +86,12 @@ def __init__(self, shm: ctypes.Array[ctypes.c_double] | None, slot: int) -> None self._kind = KIND_NONE def _publish(self) -> None: + """Write the slot behind an odd version, so a reader can tell it raced. + + The five stores are not atomic together, and a reader that caught a new + `busy_total` beside a stale `segment_start` would count the same span + twice. Bracketing them makes that detectable. + """ if self._slot == NO_SLOT or self._shm is None: return @@ -87,7 +99,6 @@ def _publish(self) -> None: base = self._base version = shm[base + SLOT_VERSION] - # Odd: a reader that sees this discards what it read. shm[base + SLOT_VERSION] = version + 1.0 shm[base + SLOT_BUSY_TOTAL] = self._busy_total shm[base + SLOT_WAIT_TOTAL] = self._wait_total @@ -133,28 +144,21 @@ def close(self, now: float) -> None: @dataclass class ChildTimeAccounting: - """Parent-side reader for one child's slot. - - Holds the previous absolute reading and returns deltas, so a child in a long - task contributes to every interval it spans. - """ + """Parent-side reader for one child's slot.""" shm: ctypes.Array[ctypes.c_double] | None slot: int = NO_SLOT _prev_busy: float = 0.0 _prev_wait: float = 0.0 _accounted: bool = False - # Start of the window the next delta will cover. Advances only on a - # successful read, so a deferred sample carries its eligibility forward with - # it and `busy + wait <= eligible` survives a seqlock retry. _measured_from: float = 0.0 def mark_running(self, now: float) -> None: """Start counting this child, baselining against the slot as it stands. - Baselining rather than zeroing drops whatever the child banked before the - parent saw its `running` message, which is the same window over which it - is absent from `running_count`. + Baselining rather than zeroing discards whatever the child banked before + the parent saw its `running` message, which is the same window over + which it is absent from the pool's running count. """ reading = self._read(now) if reading is None: @@ -171,38 +175,35 @@ def mark_stopped(self) -> None: self._accounted = False def sample(self, now: float) -> SampleResult: - """Return this child's busy/wait since the previous sample. - - `eligible` is the width of that same window, so it is the honest ceiling - on what this child could have contributed. It is shorter than the flush - interval for a child baselined part-way through one. - """ + """Return this child's busy and wait since the previous sample.""" if not self._accounted: - return SampleResult(reason="not_accounted") - - eligible = max(0.0, now - self._measured_from) + return SampleResult() reading = self._read(now) if reading is None: - # Neither baseline advances, so the next sample covers both windows. - return SampleResult(eligible=eligible, reason="read_failed") + # Advance nothing. The next sample then covers both windows, and its + # busy and eligible grow together instead of one outrunning the other. + return SampleResult() busy_now, wait_now = reading - raw_busy = busy_now - self._prev_busy - raw_wait = wait_now - self._prev_wait - # A total going backwards means a torn read or a reused slot, and the - # clamp below silently drops that time. - reason = "clamped" if raw_busy < 0.0 or raw_wait < 0.0 else "ok" + eligible = max(0.0, now - self._measured_from) + # A total going backwards means a torn read or a slot reused under a + # live writer. Clamping drops that time, which the pool then sees as a + # deficit against `eligible`. + busy = max(0.0, busy_now - self._prev_busy) + wait = max(0.0, wait_now - self._prev_wait) self._prev_busy = busy_now self._prev_wait = wait_now self._measured_from = now - return SampleResult(max(0.0, raw_busy), max(0.0, raw_wait), eligible, reason) + return SampleResult(busy, wait, eligible) def _read(self, now: float) -> tuple[float, float] | None: """Seqlock read of absolute busy/wait, including the segment still open. - None means the read could not be taken cleanly. + Retries on an odd version (a write is in progress) or a changed one (a + write started and finished mid-read). Returns None if it never got a + clean pass, which the caller treats as "defer", not "zero". """ if self.slot == NO_SLOT or self.shm is None: return None @@ -223,7 +224,9 @@ def _read(self, now: float) -> tuple[float, float] | None: if shm[base + SLOT_VERSION] != version: continue - # Fold in the segment the child is in right now. + # Fold in the segment the child is in right now, so a long task + # contributes to every interval it spans instead of landing all at + # once when it finally ends. if kind == KIND_BUSY: busy += max(0.0, now - start) elif kind == KIND_WAIT: diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 567e93e6..a5619b83 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -916,7 +916,6 @@ def __init__( ) self._free_timing_slots: Deque[int] = deque(range(self._timing_slots)) self._children_lock = threading.Lock() - self._last_occupancy_flush_at = time.monotonic() self._shutdown_event = self._mp_context.Event() self._prometheus_port = prometheus_port self._prom: WorkerPrometheusMetrics | None = None @@ -927,21 +926,17 @@ def __init__( def _acquire_timing_slot(self) -> int: """Take a zeroed shared-memory slot for a new child. - `NO_SLOT` means the pool ran out, which the two-generation sizing is - meant to make impossible. That child then contributes to neither the - occupancy numerator nor `running_count`, so the ratio stays consistent - across the children that are accounted for, and the metric below says - the sizing was wrong. + `NO_SLOT` means the pool ran out, which the two-generation sizing should + make impossible. That child is then left out of both the occupancy + numerator and its divisor, so occupancy stays honest over the children + that are measured and the metric says the sizing was wrong. """ with self._children_lock: - if not self._free_timing_slots: - slot = NO_SLOT - else: - slot = self._free_timing_slots.popleft() + slot = self._free_timing_slots.popleft() if self._free_timing_slots else NO_SLOT if slot == NO_SLOT: logger.error( - "taskworker.child.timing_slot_exhausted", + "taskworker.worker.child.timing_slot_exhausted", extra={ "slots": self._timing_slots, "processing_pool": self._processing_pool_name, @@ -953,6 +948,8 @@ def _acquire_timing_slot(self) -> int: ) return NO_SLOT + # Zero on the way out, not on release: a released child can still write + # once before it breaks out of its loop. base = slot * SLOT_WIDTH for offset in range(SLOT_WIDTH): self._timing_shm[base + offset] = 0.0 @@ -960,8 +957,8 @@ def _acquire_timing_slot(self) -> int: return slot def _release_timing_slot(self, slot: int) -> None: - """Return a slot whose child never started. The reap path returns slots - inline because it already holds `_children_lock`.""" + """Return a slot whose child never started. The reap path appends + directly, since it already holds `_children_lock`.""" if slot == NO_SLOT: return @@ -974,6 +971,17 @@ def ready_count(self) -> int: with self._children_lock: return sum(1 for c in self._children.values() if c.state == "running") + def _accounting_log( + self, busy_time: float, wait_time: float, ceiling: float, running_count: int + ) -> dict[str, float | int | str]: + return { + "busy_time": busy_time, + "wait_time": wait_time, + "ceiling": ceiling, + "running_count": running_count, + "processing_pool": self._processing_pool_name, + } + def _emit_periodic_metrics(self) -> None: tags = { "processing_pool": self._processing_pool_name, @@ -1010,9 +1018,8 @@ def _emit_periodic_metrics(self) -> None: busy_time = 0.0 wait_time = 0.0 - accounted_running = 0 eligible_time = 0.0 - outcomes: dict[str, int] = {} + accounted_running = 0 for child in self._children.values(): state_counts[child.state] += 1 @@ -1029,13 +1036,9 @@ def _emit_periodic_metrics(self) -> None: busy_time += result.busy wait_time += result.wait eligible_time += result.eligible - outcomes[result.reason] = outcomes.get(result.reason, 0) + 1 exiting_children = len(self._exiting_children) - elapsed = now - self._last_occupancy_flush_at - self._last_occupancy_flush_at = now - # Emitted during warmup too: zero is correct for a counter. self._metrics.distribution( "taskworker.worker.child_busy_seconds", @@ -1056,14 +1059,20 @@ def _emit_periodic_metrics(self) -> None: max(0.0, wait_time) ) - # Slotless children are out of both sides; the gauge still counts them. + # Children the loop above skipped are absent here too, so occupancy is a + # ratio over the measured set. The `children` gauge still counts them all. running_count = accounted_running if running_count > 0 and eligible_time > 0: - # Sum of the windows the children were each measured over, not a - # headcount times the interval: one baselined part-way through a - # flush could never have filled it, and billing it whole reads as - # idle time the pool never had. + # Sum of the windows each child was measured over. `elapsed * + # running_count` would instead bill a child baselined part-way + # through this flush as if it had been here all along, which reads + # as idle time the pool never had. ceiling = eligible_time + # busy and wait partition every measured window, so the pair must + # land on the ceiling. Over means time was counted twice; under + # means a child's totals went backwards and time was dropped. Both + # should stay at zero, and occupancy is not trustworthy while either + # is firing. if busy_time > ceiling or wait_time > ceiling: self._metrics.incr( "taskworker.worker.occupancy.accounting_overflow", @@ -1071,60 +1080,19 @@ def _emit_periodic_metrics(self) -> None: ) logger.warning( "taskworker.worker.occupancy.accounting_overflow", - extra={ - "busy_time": busy_time, - "wait_time": wait_time, - "ceiling": ceiling, - "running_count": running_count, - "elapsed": elapsed, - "processing_pool": self._processing_pool_name, - }, + extra=self._accounting_log(busy_time, wait_time, ceiling, running_count), ) - - # How much of the ceiling the counters actually account for. The - # overflow guard above is one-sided; this is the other direction, - # where occupancy reads low because time went missing rather than - # because the pool was idle. Should sit at 1.0. - self._metrics.gauge( - "taskworker.worker.occupancy.accounting_ratio", - (busy_time + wait_time) / ceiling, - tags=tags, - ) - # Size of the correction the ceiling above applies. Below 1.0 means - # children were baselined part-way through this flush, which is what - # a headcount denominator would have mistaken for idle time. - if elapsed > 0: - self._metrics.gauge( - "taskworker.worker.occupancy.eligible_ratio", - eligible_time / (elapsed * running_count), - tags=tags, - ) - for reason, count in outcomes.items(): - self._metrics.incr( - "taskworker.worker.occupancy.sample_outcome", - count, - tags={**tags, "reason": reason}, - ) - if busy_time + wait_time < ceiling * 0.9: + elif busy_time + wait_time < ceiling * 0.9: self._metrics.incr( "taskworker.worker.occupancy.accounting_deficit", tags=tags, ) logger.warning( "taskworker.worker.occupancy.accounting_deficit", - extra={ - "busy_time": busy_time, - "wait_time": wait_time, - "eligible_time": eligible_time, - "running_count": running_count, - "elapsed": elapsed, - "outcomes": outcomes, - "processing_pool": self._processing_pool_name, - }, + extra=self._accounting_log(busy_time, wait_time, ceiling, running_count), ) - occupancy = busy_time / ceiling - occupancy = min(occupancy, 1.0) + occupancy = min(busy_time / ceiling, 1.0) self._metrics.gauge( "taskworker.worker.occupancy", occupancy, diff --git a/clients/python/src/taskbroker_client/worker/workerchild.py b/clients/python/src/taskbroker_client/worker/workerchild.py index 3e71ef8a..070afe1a 100644 --- a/clients/python/src/taskbroker_client/worker/workerchild.py +++ b/clients/python/src/taskbroker_client/worker/workerchild.py @@ -681,7 +681,7 @@ def _execute_activation( transaction.set_data("taskworker-task.args", args) transaction.set_data("taskworker-task.kwargs", kwargs) - # ToDatetime().timestamp() misreads a naive UTC datetime as local. + # ToDatetime().timestamp() reads a naive UTC datetime as local time. task_added_time = activation.received_at.seconds + activation.received_at.nanos / 1e9 # latency attribute needs to be in milliseconds latency = (time.time() - task_added_time) * 1000 diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 24490525..ac7d38c3 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1326,9 +1326,8 @@ def _make_tracked_child( timing = ChildTimeAccounting(shm=_TEST_TIMING_SHM, slot=slot) # Baseline against the zeroed slot, so the seeding below lands in sample 1. - # The default matches the `_last_occupancy_flush_at = 10.0` every occupancy - # test sets, so a child is measurable for the whole interval unless told - # otherwise. + # Defaults to the start of the [10.0, 11.0] interval the occupancy tests + # use, so a child is measurable throughout unless told otherwise. timing.mark_running(measured_from) if busy_since is not None: @@ -1399,7 +1398,6 @@ def test_emit_periodic_metrics_time_weights_busy_over_the_interval() -> None: # busy_time = 0.19 + 0.60 + 0.45 = 1.24 -> occupancy = 1.24 / (1.0 * 3) pool = _make_result_thread_pool(_SendResultCapture(), concurrency=8) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 child_b = uuid4() with pool._children_lock: @@ -1421,14 +1419,12 @@ def test_emit_periodic_metrics_time_weights_busy_over_the_interval() -> None: for child in pool._children.values(): if child.state == "running": assert child.timing.sample(12.0).busy == pytest.approx(0.0) - assert pool._last_occupancy_flush_at == pytest.approx(11.0) def test_emit_periodic_metrics_divides_by_running_children() -> None: # Two children busy for the whole 1s interval, one idle, one still warming. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=8) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_accumulated=1.0) @@ -1450,7 +1446,6 @@ def test_emit_periodic_metrics_clamps_occupancy_and_flags_the_overflow() -> None # 1.5s of busy in a 1s interval is a fault; the clamp must not hide it. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_accumulated=1.5) @@ -1469,7 +1464,6 @@ def test_emit_periodic_metrics_does_not_flag_a_legitimately_full_pool() -> None: # The guard must not fire on a pool that is simply saturated, or it is noise. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) @@ -1491,7 +1485,6 @@ def test_emit_periodic_metrics_bills_a_mid_interval_child_only_for_its_own_windo # invented half a second of idle that never existed. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) @@ -1506,29 +1499,17 @@ def test_emit_periodic_metrics_bills_a_mid_interval_child_only_for_its_own_windo assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( 1.0 ) - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ - 1 - ] == pytest.approx(1.0) - # 1.5 available against the 2.0 a headcount would have claimed. - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.eligible_ratio")[0].args[ - 1 - ] == pytest.approx(0.75) - # Nothing went missing, so every sample is clean. - reasons = { - c.kwargs["tags"]["reason"] - for c in _incr_calls(pool._metrics, "taskworker.worker.occupancy.sample_outcome") - } - assert reasons == {"ok"} - - -def test_emit_periodic_metrics_flags_a_deficit_and_names_the_reason() -> None: - # The mirror of accounting_overflow. Now that the ceiling is the summed - # eligible window, a deficit can only mean a measurable child reported less - # than its own window, which is time genuinely lost rather than a - # denominator artifact. + # Nothing was double-counted or dropped, so neither guard fires. + assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] + assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit") == [] + + +def test_emit_periodic_metrics_flags_a_deficit_when_a_child_loses_time() -> None: + # The mirror of accounting_overflow. A deficit means a measurable child + # reported less than its own window, so time was dropped rather than the + # pool merely being idle. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 # Baseline at 5.0, then drop the slot's total: a reused slot or a torn read. lost = _make_tracked_child("running", busy_accumulated=5.0) @@ -1544,27 +1525,17 @@ def test_emit_periodic_metrics_flags_a_deficit_and_names_the_reason() -> None: assert len(_incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit")) == 1 # 1.0 busy-second reported against the 2.0 both children were eligible for. - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ - 1 - ] == pytest.approx(0.5) - # The denominator is honest, so this stays at 1.0 and does not mask the loss. - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.eligible_ratio")[0].args[ - 1 - ] == pytest.approx(1.0) - reasons = { - c.kwargs["tags"]["reason"] - for c in _incr_calls(pool._metrics, "taskworker.worker.occupancy.sample_outcome") - } - assert reasons == {"ok", "clamped"} - - -def test_emit_periodic_metrics_reports_an_unmeasurable_child_through_eligible_ratio() -> None: - # A running child whose accounting is switched off supplies no window, so it - # cannot drag occupancy down the way a headcount denominator would have made - # it. eligible_ratio is what says the headcount exceeded the measured set. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( + 0.5 + ) + + +def test_emit_periodic_metrics_ignores_a_running_child_that_is_not_accounted() -> None: + # A child whose accounting is switched off supplies no window, so it lands in + # neither the numerator nor the ceiling. A headcount denominator would have + # counted it whole and halved occupancy. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 stalled = _make_tracked_child("running", busy_since=10.0) stalled.timing.mark_stopped() @@ -1581,21 +1552,11 @@ def test_emit_periodic_metrics_reports_an_unmeasurable_child_through_eligible_ra 1.0 ) assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit") == [] - # Half the counted children supplied no window at all. - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.eligible_ratio")[0].args[ - 1 - ] == pytest.approx(0.5) - reasons = { - c.kwargs["tags"]["reason"] - for c in _incr_calls(pool._metrics, "taskworker.worker.occupancy.sample_outcome") - } - assert reasons == {"ok", "not_accounted"} def test_emit_periodic_metrics_does_not_flag_a_deficit_when_time_is_all_there() -> None: pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) @@ -1605,34 +1566,32 @@ def test_emit_periodic_metrics_does_not_flag_a_deficit_when_time_is_all_there() pool._emit_periodic_metrics() assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_deficit") == [] - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy.accounting_ratio")[0].args[ - 1 - ] == pytest.approx(1.0) + assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] -def test_sample_reports_a_clamped_read_rather_than_hiding_it() -> None: - # A total going backwards means a torn read or a reused slot. The clamp keeps - # the number sane but drops real time, so the drop has to be visible. +def test_sample_clamps_a_backwards_total_and_leaves_the_window_intact() -> None: + # A total going backwards means a torn read or a reused slot. Clamping keeps + # the number sane but drops real time, and `eligible` must still report the + # full window so the pool sees the shortfall as a deficit. writer, reader = _writer_and_reader() writer.mark_running(0.0) reader.mark_running(0.0) writer.mark_busy(0.0) - assert reader.sample(1.0).reason == "ok" + assert reader.sample(1.0).busy == pytest.approx(1.0) # Rewind the slot underneath the reader, as slot reuse would. reader.shm[SLOT_BUSY_TOTAL] = 0.0 # type: ignore[index] reader.shm[SLOT_SEGMENT_START] = 2.0 # type: ignore[index] result = reader.sample(2.0) - assert result.reason == "clamped" assert result.busy == 0.0 + assert result.eligible == pytest.approx(1.0) def test_emit_periodic_metrics_excludes_slotless_children_from_occupancy() -> None: # A slotless child in the denominator would read as idle and halve occupancy. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 slotless = _make_tracked_child("running") slotless.timing.slot = NO_SLOT @@ -1662,7 +1621,6 @@ def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: # The counters must sum over the same population occupancy divides by. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) @@ -1793,9 +1751,10 @@ def test_child_timing_carries_eligibility_across_a_deferred_sample() -> None: assert reader.sample(1.0).eligible == pytest.approx(1.0) + # A failed read reports nothing at all, not zero busy against a full window. reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] deferred = reader.sample(2.0) - assert deferred.reason == "read_failed" + assert (deferred.busy, deferred.wait, deferred.eligible) == (0.0, 0.0, 0.0) reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] recovered = reader.sample(3.0) @@ -1879,7 +1838,6 @@ def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: # Interval [10.0, 11.0]: one child busy throughout, one waiting 0.25s. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - pool._last_occupancy_flush_at = 10.0 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) From 8559519fbad7c2fa656b904b89dfa907b9c61c61 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Thu, 3 Sep 2026 15:51:11 -0400 Subject: [PATCH 12/17] clock read per child inside loop --- clients/python/src/taskbroker_client/worker/worker.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index a5619b83..77731506 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -1009,7 +1009,6 @@ def _emit_periodic_metrics(self) -> None: ) with self._children_lock: - now = time.monotonic() state_counts: dict[ChildState, int] = { "pending": 0, "running": 0, @@ -1032,7 +1031,7 @@ def _emit_periodic_metrics(self) -> None: continue accounted_running += 1 - result = child.timing.sample(now) + result = child.timing.sample(time.monotonic()) busy_time += result.busy wait_time += result.wait eligible_time += result.eligible From 5d1007eeca3539d63232e2d0a03f2f9449ef95d6 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Tue, 8 Sep 2026 10:57:20 -0400 Subject: [PATCH 13/17] Derive free timing slots from tracked children 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) --- .../src/taskbroker_client/worker/worker.py | 55 +++++++------- clients/python/tests/worker/test_worker.py | 75 ++++++++++++++++--- 2 files changed, 88 insertions(+), 42 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 77731506..4045fff3 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -914,7 +914,6 @@ def __init__( self._timing_shm: ctypes.Array[ctypes.c_double] = self._mp_context.RawArray( "d", SLOT_WIDTH * self._timing_slots ) - self._free_timing_slots: Deque[int] = deque(range(self._timing_slots)) self._children_lock = threading.Lock() self._shutdown_event = self._mp_context.Event() self._prometheus_port = prometheus_port @@ -923,18 +922,23 @@ def __init__( self._metrics_thread: threading.Thread | None = None self._spawn_children_thread: threading.Thread | None = None - def _acquire_timing_slot(self) -> int: - """Take a zeroed shared-memory slot for a new child. - - `NO_SLOT` means the pool ran out, which the two-generation sizing should - make impossible. That child is then left out of both the occupancy - numerator and its divisor, so occupancy stays honest over the children - that are measured and the metric says the sizing was wrong. + def _available_timing_slots(self) -> Deque[int]: + """Slots no tracked child holds, derived rather than kept in a free list. + Called with `_children_lock` held. """ - with self._children_lock: - slot = self._free_timing_slots.popleft() if self._free_timing_slots else NO_SLOT + taken = {c.timing.slot for c in self._children.values()} + return deque(slot for slot in range(self._timing_slots) if slot not in taken) + + def _take_timing_slot(self, available: Deque[int]) -> int: + """Claim and zero one slot out of this batch's available set. - if slot == NO_SLOT: + Each child holds one slot, and the pool has twice as many slots as it + has children, so running out means a whole generation was told to shut + down and never exited. That child still spawns and runs tasks; occupancy + just leaves it out of both the busy total and the child count, so the + number stays right for the rest. + """ + if not available: logger.error( "taskworker.worker.child.timing_slot_exhausted", extra={ @@ -948,23 +952,16 @@ def _acquire_timing_slot(self) -> int: ) return NO_SLOT - # Zero on the way out, not on release: a released child can still write - # once before it breaks out of its loop. + slot = available.popleft() + + # Zero on acquire, not on release: a child released at `exiting` can + # still publish once before it breaks out of its loop. base = slot * SLOT_WIDTH for offset in range(SLOT_WIDTH): self._timing_shm[base + offset] = 0.0 return slot - def _release_timing_slot(self, slot: int) -> None: - """Return a slot whose child never started. The reap path appends - directly, since it already holds `_children_lock`.""" - if slot == NO_SLOT: - return - - with self._children_lock: - self._free_timing_slots.append(slot) - @property def ready_count(self) -> int: """Number of children that have finished warming up and are consuming.""" @@ -1252,10 +1249,6 @@ def spawn_children_thread() -> None: c.process.join(timeout=0) self._children.pop(cid) - # Not at `exiting`: a released child can still publish once. - if c.timing.slot != NO_SLOT: - self._free_timing_slots.append(c.timing.slot) - logger.info( "taskworker.child.exited", extra={ @@ -1317,13 +1310,16 @@ def spawn_children_thread() -> None: spawned = sum(1 for c in self._children.values() if c.state != "exiting") + # Same snapshot that sizes the batch, so the two agree. + free_timing_slots = self._available_timing_slots() + # How many children do we need to spawn? needed = max(self._concurrency - spawned, 0) for _ in range(needed): child_id = uuid4() release = self._mp_context.Event() - timing_slot = self._acquire_timing_slot() + timing_slot = self._take_timing_slot(free_timing_slots) process = self._mp_context.Process( name=f"taskworker-child-{child_id}", @@ -1359,9 +1355,8 @@ def spawn_children_thread() -> None: self._children[child_id] = child except Exception as e: - # Never came up, so nothing will write to its slot. - self._release_timing_slot(timing_slot) - + # Nothing to give back: the child never entered + # `_children`, so the next batch re-derives this slot. logger.exception( "taskworker.child.spawn.failed", extra={ diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index ac7d38c3..62b4bd1a 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -6,6 +6,7 @@ import signal import threading import time +from collections import deque from collections.abc import Iterator, MutableMapping from concurrent.futures import Future from datetime import datetime, timezone @@ -1665,6 +1666,37 @@ def test_spawn_children_binds_each_child_to_its_own_timing_slot() -> None: pool.shutdown() +def test_spawn_children_recycles_slots_across_generations() -> None: + # The leak the derived set exists to prevent. concurrency=2 gives 4 slots, + # so a pool that failed to return them would hand out NO_SLOT by the third + # generation and stop measuring for the rest of its life. + fake_context = _FakeContext() + pool = _make_fake_context_pool(fake_context, concurrency=2) + + pool.start_spawn_children_thread() + try: + seen = 0 + for _ in range(4): + _wait_for(lambda: len(fake_context.processes) == seen + 2) + generation = fake_context.processes[seen:] + seen += 2 + + slots = {process.args[-1] for process in generation} + assert NO_SLOT not in slots + assert len(slots) == 2 + + # Nothing hands the slots back. The next scan reaps these children + # out of `_children`, which is all it takes. + for process in generation: + process.alive = False + + with pool._children_lock: + held = {c.timing.slot for c in pool._children.values()} + assert len(held) == len(pool._children) + finally: + pool.shutdown() + + def _writer_and_reader(slot: int = 0) -> tuple[ChildTimeWriter, ChildTimeAccounting]: shm = get_context("fork").RawArray("d", SLOT_WIDTH * (slot + 1)) return ChildTimeWriter(shm, slot), ChildTimeAccounting(shm=shm, slot=slot) @@ -1799,22 +1831,44 @@ def test_child_timing_excludes_time_banked_before_the_parent_saw_running() -> No assert _bw(reader.sample(6.0)) == pytest.approx((0.0, 1.0)) -def test_acquire_timing_slot_zeroes_a_recycled_slot() -> None: +def test_available_timing_slots_follow_the_tracked_children() -> None: + # The property the derived set buys: a slot is in use exactly while its + # child is tracked, so no exit path can lose one by forgetting to give it + # back. Reaping the child is the only bookkeeping there is. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=2) + child_id = uuid4() + + with pool._children_lock: + assert sorted(pool._available_timing_slots()) == list(range(slot_count(2))) + + held = pool._take_timing_slot(pool._available_timing_slots()) + child = _make_tracked_child("running") + child.timing = ChildTimeAccounting(shm=pool._timing_shm, slot=held) + pool._children[child_id] = child + + assert held not in pool._available_timing_slots() + + with pool._children_lock: + pool._children.pop(child_id) + assert held in pool._available_timing_slots() + + +def test_take_timing_slot_zeroes_a_recycled_slot() -> None: # A replacement must not inherit its predecessor's totals. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) - # Drain the free list: reuse is FIFO, so a release is not reused next. - slot = pool._acquire_timing_slot() - rest = [pool._acquire_timing_slot() for _ in range(slot_count(1) - 1)] - assert NO_SLOT not in rest + with pool._children_lock: + slot = pool._take_timing_slot(pool._available_timing_slots()) writer = ChildTimeWriter(pool._timing_shm, slot) writer.mark_running(0.0) writer.mark_busy(0.0) writer.mark_idle(30.0) - pool._release_timing_slot(slot) - recycled = pool._acquire_timing_slot() + # No child ever tracked it, so the next batch offers it straight back. + with pool._children_lock: + assert slot in pool._available_timing_slots() + recycled = pool._take_timing_slot(deque([slot])) assert recycled == slot reader = ChildTimeAccounting(shm=pool._timing_shm, slot=recycled) @@ -1822,15 +1876,12 @@ def test_acquire_timing_slot_zeroes_a_recycled_slot() -> None: assert _bw(reader.sample(1.0)) == pytest.approx((0.0, 0.0)) -def test_acquire_timing_slot_reports_exhaustion_instead_of_raising() -> None: +def test_take_timing_slot_reports_exhaustion_instead_of_raising() -> None: # Should be unreachable; the pool has to keep spawning either way. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) pool._metrics = mock.Mock() - taken = [pool._acquire_timing_slot() for _ in range(slot_count(1))] - assert NO_SLOT not in taken - - assert pool._acquire_timing_slot() == NO_SLOT + assert pool._take_timing_slot(deque()) == NO_SLOT assert len(_incr_calls(pool._metrics, "taskworker.worker.child.timing_slot_exhausted")) == 1 From bcaa254cae538c4e79d6f637eb35244baa082639 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Tue, 8 Sep 2026 11:34:40 -0400 Subject: [PATCH 14/17] Give each child its own timing slot 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. --- .../taskbroker_client/worker/childtiming.py | 86 ++++--- .../src/taskbroker_client/worker/worker.py | 122 +++------- .../taskbroker_client/worker/workerchild.py | 5 +- clients/python/tests/worker/test_worker.py | 211 +++++------------- 4 files changed, 131 insertions(+), 293 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py index 1785dc0a..1292c482 100644 --- a/clients/python/src/taskbroker_client/worker/childtiming.py +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -1,8 +1,9 @@ """Shared-memory busy/wait accounting for worker children. -Each child owns a slot and writes its own cumulative totals into it. The parent -reads every slot once per flush and diffs against its previous reading, so the -cost is O(children) per second rather than O(tasks) per second. +Each child owns its own small shared array and writes its cumulative totals +into it. The parent reads every child's array once per flush and diffs against +its previous reading, so the cost is O(children) per second rather than +O(tasks) per second. The parent reads rather than having children emit their own metrics because a child only knows a segment's length once it ends: a child sitting in a 30s task @@ -10,7 +11,7 @@ open segment forward at read time instead, so that child contributes to every interval it spans. -Slot layout, five doubles per child:: +Slot layout, five doubles:: 0 version seqlock; odd means a write is in progress 1 busy_total cumulative seconds closed into busy @@ -28,6 +29,7 @@ import ctypes from dataclasses import dataclass +from multiprocessing.context import ForkContext, ForkServerContext, SpawnContext SLOT_VERSION = 0 SLOT_BUSY_TOTAL = 1 @@ -42,12 +44,22 @@ KIND_WAIT = 1.0 KIND_BUSY = 2.0 -# Handed to a child when the pool has no slot left. Reads and writes are no-ops. -NO_SLOT = -1 - SEQLOCK_READ_ATTEMPTS = 3 +def new_slot( + mp_context: ForkContext | SpawnContext | ForkServerContext, +) -> ctypes.Array[ctypes.c_double]: + """One child's slot, allocated at spawn and dropped when the child is reaped. + + Giving each child its own array instead of an index into a pool means there + is no free list to hand a slot back to, so no exit path can lose one. + `RawArray` zeroes what it returns, so a recycled block never carries the + previous child's totals into its replacement. + """ + return mp_context.RawArray("d", SLOT_WIDTH) + + @dataclass(frozen=True) class SampleResult: """One child's busy and wait, and the window they were measured over. @@ -61,25 +73,17 @@ class SampleResult: eligible: float = 0.0 -def slot_count(concurrency: int) -> int: - """Twice concurrency, so a generation of unreaped exiting children can - overlap a generation of replacements.""" - return max(1, concurrency * 2) - - class ChildTimeWriter: - """Child-side writer for one slot. + """Child-side writer for its slot. The child is the only writer, so it keeps authoritative totals as plain floats and republishes the whole slot on each transition. """ - __slots__ = ("_shm", "_slot", "_base", "_busy_total", "_wait_total", "_start", "_kind") + __slots__ = ("_shm", "_busy_total", "_wait_total", "_start", "_kind") - def __init__(self, shm: ctypes.Array[ctypes.c_double] | None, slot: int) -> None: + def __init__(self, shm: ctypes.Array[ctypes.c_double]) -> None: self._shm = shm - self._slot = NO_SLOT if shm is None else slot - self._base = slot * SLOT_WIDTH self._busy_total = 0.0 self._wait_total = 0.0 self._start = 0.0 @@ -92,19 +96,14 @@ def _publish(self) -> None: `busy_total` beside a stale `segment_start` would count the same span twice. Bracketing them makes that detectable. """ - if self._slot == NO_SLOT or self._shm is None: - return - shm = self._shm - base = self._base - - version = shm[base + SLOT_VERSION] - shm[base + SLOT_VERSION] = version + 1.0 - shm[base + SLOT_BUSY_TOTAL] = self._busy_total - shm[base + SLOT_WAIT_TOTAL] = self._wait_total - shm[base + SLOT_SEGMENT_START] = self._start - shm[base + SLOT_SEGMENT_KIND] = self._kind - shm[base + SLOT_VERSION] = version + 2.0 + version = shm[SLOT_VERSION] + shm[SLOT_VERSION] = version + 1.0 + shm[SLOT_BUSY_TOTAL] = self._busy_total + shm[SLOT_WAIT_TOTAL] = self._wait_total + shm[SLOT_SEGMENT_START] = self._start + shm[SLOT_SEGMENT_KIND] = self._kind + shm[SLOT_VERSION] = version + 2.0 def _close_open(self, now: float) -> None: if self._kind == KIND_BUSY: @@ -146,8 +145,7 @@ def close(self, now: float) -> None: class ChildTimeAccounting: """Parent-side reader for one child's slot.""" - shm: ctypes.Array[ctypes.c_double] | None - slot: int = NO_SLOT + shm: ctypes.Array[ctypes.c_double] _prev_busy: float = 0.0 _prev_wait: float = 0.0 _accounted: bool = False @@ -162,6 +160,8 @@ def mark_running(self, now: float) -> None: """ reading = self._read(now) if reading is None: + # A torn read at baseline time. Zero is the right guess: the child + # has only just started, so its totals are near enough to zero. self._prev_busy = 0.0 self._prev_wait = 0.0 else: @@ -187,9 +187,8 @@ def sample(self, now: float) -> SampleResult: busy_now, wait_now = reading eligible = max(0.0, now - self._measured_from) - # A total going backwards means a torn read or a slot reused under a - # live writer. Clamping drops that time, which the pool then sees as a - # deficit against `eligible`. + # A total going backwards means a torn read. Clamping drops that time, + # which the pool then sees as a deficit against `eligible`. busy = max(0.0, busy_now - self._prev_busy) wait = max(0.0, wait_now - self._prev_wait) @@ -205,23 +204,18 @@ def _read(self, now: float) -> tuple[float, float] | None: write started and finished mid-read). Returns None if it never got a clean pass, which the caller treats as "defer", not "zero". """ - if self.slot == NO_SLOT or self.shm is None: - return None - shm = self.shm - base = self.slot * SLOT_WIDTH - for _ in range(SEQLOCK_READ_ATTEMPTS): - version = shm[base + SLOT_VERSION] + version = shm[SLOT_VERSION] if version % 2.0: continue - busy = shm[base + SLOT_BUSY_TOTAL] - wait = shm[base + SLOT_WAIT_TOTAL] - start = shm[base + SLOT_SEGMENT_START] - kind = shm[base + SLOT_SEGMENT_KIND] + busy = shm[SLOT_BUSY_TOTAL] + wait = shm[SLOT_WAIT_TOTAL] + start = shm[SLOT_SEGMENT_START] + kind = shm[SLOT_SEGMENT_KIND] - if shm[base + SLOT_VERSION] != version: + if shm[SLOT_VERSION] != version: continue # Fold in the segment the child is in right now, so a long task diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 4045fff3..e8d2a238 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -1,6 +1,5 @@ from __future__ import annotations -import ctypes import logging import multiprocessing import os @@ -41,12 +40,7 @@ ) from taskbroker_client.metrics import MetricsBackend from taskbroker_client.types import InflightTaskActivation, ProcessingResult -from taskbroker_client.worker.childtiming import ( - NO_SLOT, - SLOT_WIDTH, - ChildTimeAccounting, - slot_count, -) +from taskbroker_client.worker.childtiming import ChildTimeAccounting, new_slot from taskbroker_client.worker.client import ( HealthCheckSettings, HostTemporarilyUnavailable, @@ -234,7 +228,7 @@ class TrackedChild: process: BaseProcess state: ChildState release: Event - # No default: an accountant with no slot silently measures nothing. + # Holds the child's slot. Dropping this entry is what frees the memory. timing: ChildTimeAccounting @@ -909,11 +903,6 @@ def __init__( self._children: Dict[UUID, TrackedChild] = {} self._exiting_children: Deque[UUID] = deque() - # Two generations: unreaped exiting children overlap their replacements. - self._timing_slots: int = slot_count(concurrency) - self._timing_shm: ctypes.Array[ctypes.c_double] = self._mp_context.RawArray( - "d", SLOT_WIDTH * self._timing_slots - ) self._children_lock = threading.Lock() self._shutdown_event = self._mp_context.Event() self._prometheus_port = prometheus_port @@ -922,46 +911,6 @@ def __init__( self._metrics_thread: threading.Thread | None = None self._spawn_children_thread: threading.Thread | None = None - def _available_timing_slots(self) -> Deque[int]: - """Slots no tracked child holds, derived rather than kept in a free list. - Called with `_children_lock` held. - """ - taken = {c.timing.slot for c in self._children.values()} - return deque(slot for slot in range(self._timing_slots) if slot not in taken) - - def _take_timing_slot(self, available: Deque[int]) -> int: - """Claim and zero one slot out of this batch's available set. - - Each child holds one slot, and the pool has twice as many slots as it - has children, so running out means a whole generation was told to shut - down and never exited. That child still spawns and runs tasks; occupancy - just leaves it out of both the busy total and the child count, so the - number stays right for the rest. - """ - if not available: - logger.error( - "taskworker.worker.child.timing_slot_exhausted", - extra={ - "slots": self._timing_slots, - "processing_pool": self._processing_pool_name, - }, - ) - self._metrics.incr( - "taskworker.worker.child.timing_slot_exhausted", - tags={"processing_pool": self._processing_pool_name}, - ) - return NO_SLOT - - slot = available.popleft() - - # Zero on acquire, not on release: a child released at `exiting` can - # still publish once before it breaks out of its loop. - base = slot * SLOT_WIDTH - for offset in range(SLOT_WIDTH): - self._timing_shm[base + offset] = 0.0 - - return slot - @property def ready_count(self) -> int: """Number of children that have finished warming up and are consuming.""" @@ -1015,7 +964,7 @@ def _emit_periodic_metrics(self) -> None: busy_time = 0.0 wait_time = 0.0 eligible_time = 0.0 - accounted_running = 0 + running_count = 0 for child in self._children.values(): state_counts[child.state] += 1 @@ -1023,11 +972,7 @@ def _emit_periodic_metrics(self) -> None: if child.state != "running": continue - # A slotless child reports nothing; counting it would read as idle. - if child.timing.slot == NO_SLOT: - continue - - accounted_running += 1 + running_count += 1 result = child.timing.sample(time.monotonic()) busy_time += result.busy wait_time += result.wait @@ -1055,9 +1000,6 @@ def _emit_periodic_metrics(self) -> None: max(0.0, wait_time) ) - # Children the loop above skipped are absent here too, so occupancy is a - # ratio over the measured set. The `children` gauge still counts them all. - running_count = accounted_running if running_count > 0 and eligible_time > 0: # Sum of the windows each child was measured over. `elapsed * # running_count` would instead bill a child baselined part-way @@ -1305,44 +1247,45 @@ def spawn_children_thread() -> None: continue child.state = "exiting" + # Stop counting it, but keep the slot: the child writes + # once more on its way out, and its replacement can be + # handed the same memory the moment this one is freed. child.timing.mark_stopped() child.release.set() spawned = sum(1 for c in self._children.values() if c.state != "exiting") - # Same snapshot that sizes the batch, so the two agree. - free_timing_slots = self._available_timing_slots() - # How many children do we need to spawn? needed = max(self._concurrency - spawned, 0) for _ in range(needed): child_id = uuid4() release = self._mp_context.Event() - timing_slot = self._take_timing_slot(free_timing_slots) - - process = self._mp_context.Process( - name=f"taskworker-child-{child_id}", - target=child_process, - args=( - child_id, - self._app_module, - self._child_tasks, - self._processed_tasks, - self._shutdown_event, - self._max_child_task_count, - self._processing_pool_name, - self._process_type, - self._skip_awaiting_futures, - self._future_checking_frequency, - messages, - release, - self._timing_shm, - timing_slot, - ), - ) try: + # Inside the try so an allocation failure retries next + # pass instead of killing the spawn thread. + timing_shm = new_slot(self._mp_context) + + process = self._mp_context.Process( + name=f"taskworker-child-{child_id}", + target=child_process, + args=( + child_id, + self._app_module, + self._child_tasks, + self._processed_tasks, + self._shutdown_event, + self._max_child_task_count, + self._processing_pool_name, + self._process_type, + self._skip_awaiting_futures, + self._future_checking_frequency, + messages, + release, + timing_shm, + ), + ) process.start() with self._children_lock: @@ -1350,13 +1293,12 @@ def spawn_children_thread() -> None: process=process, state="pending", release=release, - timing=ChildTimeAccounting(shm=self._timing_shm, slot=timing_slot), + timing=ChildTimeAccounting(shm=timing_shm), ) self._children[child_id] = child except Exception as e: - # Nothing to give back: the child never entered - # `_children`, so the next batch re-derives this slot. + # `timing_shm` dies with this frame, so nothing leaks. logger.exception( "taskworker.child.spawn.failed", extra={ diff --git a/clients/python/src/taskbroker_client/worker/workerchild.py b/clients/python/src/taskbroker_client/worker/workerchild.py index 070afe1a..1f65ce0d 100644 --- a/clients/python/src/taskbroker_client/worker/workerchild.py +++ b/clients/python/src/taskbroker_client/worker/workerchild.py @@ -189,8 +189,7 @@ def child_process( future_checking_frequency: float, messages: multiprocessing.Queue[ChildMessage], parent_release: Event, - timing_shm: ctypes.Array[ctypes.c_double] | None, - timing_slot: int, + timing_shm: ctypes.Array[ctypes.c_double], ) -> None: """ The entrypoint for spawned worker children. @@ -204,7 +203,7 @@ def child_process( metrics = app.metrics # Straight to shared memory: `messages` cannot keep up at two events per task. - timing = ChildTimeWriter(timing_shm, timing_slot) + timing = ChildTimeWriter(timing_shm) # Signals when the parent worker pool terminates the child local_shutdown = threading.Event() diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 62b4bd1a..2a139b46 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1,12 +1,12 @@ import contextlib -import itertools +import ctypes +import gc import os import queue import random import signal import threading import time -from collections import deque from collections.abc import Iterator, MutableMapping from concurrent.futures import Future from datetime import datetime, timezone @@ -50,7 +50,6 @@ KIND_BUSY, KIND_NONE, KIND_WAIT, - NO_SLOT, SLOT_BUSY_TOTAL, SLOT_SEGMENT_KIND, SLOT_SEGMENT_START, @@ -59,7 +58,7 @@ SLOT_WIDTH, ChildTimeAccounting, ChildTimeWriter, - slot_count, + new_slot, ) from taskbroker_client.worker.worker import ( PushTaskWorker, @@ -333,7 +332,6 @@ def child_process( messages, parent_release, ctx.RawArray("d", SLOT_WIDTH), - 0, ) @@ -1298,10 +1296,7 @@ def ready_count() -> int: pool_shutdown.assert_called_once_with() -# Independent of any pool: the flush reads through `child.timing.shm`. -_TEST_SLOTS = 512 -_TEST_TIMING_SHM = get_context("fork").RawArray("d", SLOT_WIDTH * _TEST_SLOTS) -_TEST_SLOT_SEQ = itertools.count() +_TEST_CONTEXT = get_context("fork") def _make_tracked_child( @@ -1319,13 +1314,8 @@ def _make_tracked_child( segment open at that monotonic time, which the parent folds forward at sample time exactly as it would for a task still running. """ - slot = next(_TEST_SLOT_SEQ) % _TEST_SLOTS - base = slot * SLOT_WIDTH - - for offset in range(SLOT_WIDTH): - _TEST_TIMING_SHM[base + offset] = 0.0 - - timing = ChildTimeAccounting(shm=_TEST_TIMING_SHM, slot=slot) + shm = new_slot(_TEST_CONTEXT) + timing = ChildTimeAccounting(shm=shm) # Baseline against the zeroed slot, so the seeding below lands in sample 1. # Defaults to the start of the [10.0, 11.0] interval the occupancy tests # use, so a child is measurable throughout unless told otherwise. @@ -1338,11 +1328,11 @@ def _make_tracked_child( else: kind, start = KIND_NONE, 0.0 - _TEST_TIMING_SHM[base + SLOT_VERSION] = 2.0 - _TEST_TIMING_SHM[base + SLOT_BUSY_TOTAL] = busy_accumulated - _TEST_TIMING_SHM[base + SLOT_WAIT_TOTAL] = wait_accumulated - _TEST_TIMING_SHM[base + SLOT_SEGMENT_START] = start - _TEST_TIMING_SHM[base + SLOT_SEGMENT_KIND] = kind + shm[SLOT_VERSION] = 2.0 + shm[SLOT_BUSY_TOTAL] = busy_accumulated + shm[SLOT_WAIT_TOTAL] = wait_accumulated + shm[SLOT_SEGMENT_START] = start + shm[SLOT_SEGMENT_KIND] = kind return TrackedChild( process=mock.Mock(), @@ -1515,7 +1505,7 @@ def test_emit_periodic_metrics_flags_a_deficit_when_a_child_loses_time() -> None # Baseline at 5.0, then drop the slot's total: a reused slot or a torn read. lost = _make_tracked_child("running", busy_accumulated=5.0) lost.timing.sample(10.0) - _TEST_TIMING_SHM[lost.timing.slot * SLOT_WIDTH + SLOT_BUSY_TOTAL] = 0.2 + lost.timing.shm[SLOT_BUSY_TOTAL] = 0.2 with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) @@ -1581,43 +1571,14 @@ def test_sample_clamps_a_backwards_total_and_leaves_the_window_intact() -> None: assert reader.sample(1.0).busy == pytest.approx(1.0) # Rewind the slot underneath the reader, as slot reuse would. - reader.shm[SLOT_BUSY_TOTAL] = 0.0 # type: ignore[index] - reader.shm[SLOT_SEGMENT_START] = 2.0 # type: ignore[index] + reader.shm[SLOT_BUSY_TOTAL] = 0.0 + reader.shm[SLOT_SEGMENT_START] = 2.0 result = reader.sample(2.0) assert result.busy == 0.0 assert result.eligible == pytest.approx(1.0) -def test_emit_periodic_metrics_excludes_slotless_children_from_occupancy() -> None: - # A slotless child in the denominator would read as idle and halve occupancy. - pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) - pool._metrics = mock.Mock() - - slotless = _make_tracked_child("running") - slotless.timing.slot = NO_SLOT - - with pool._children_lock: - pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) - pool._children[uuid4()] = slotless - - with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): - pool._emit_periodic_metrics() - - # One accounted child, busy for the whole interval. - assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( - 1.0 - ) - assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] - - running_gauges = [ - c - for c in pool._metrics.gauge.call_args_list - if c.args[0] == "taskworker.worker.children" and c.kwargs["tags"]["state"] == "running" - ] - assert running_gauges[0].args[1] == 2.0 - - def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: # The counters must sum over the same population occupancy divides by. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) @@ -1648,28 +1609,27 @@ def test_spawn_children_binds_each_child_to_its_own_timing_slot() -> None: _wait_for(lambda: len(fake_context.processes) == 2) messages = fake_context.queues[-1] - slots: set[int] = set() + slots = [] for process in fake_context.processes: child_id = process.args[0] - shm, slot = process.args[-2], process.args[-1] - slots.add(slot) + shm = process.args[-1] + slots.append(shm) messages.put(ChildMessage(child_id, "running")) # _wait_for blocks, so the closure resolves inside the iteration. _wait_for(lambda: pool._children[child_id].state == "running") - assert pool._children[child_id].timing.slot == slot - assert shm is pool._timing_shm + assert pool._children[child_id].timing.shm is shm - # Two children, two distinct slots. + # Two children, two slots, and not the same one twice. assert len(slots) == 2 + assert slots[0] is not slots[1] finally: pool.shutdown() -def test_spawn_children_recycles_slots_across_generations() -> None: - # The leak the derived set exists to prevent. concurrency=2 gives 4 slots, - # so a pool that failed to return them would hand out NO_SLOT by the third - # generation and stop measuring for the rest of its life. +def test_spawn_children_give_each_generation_a_clean_slot() -> None: + # Every generation gets its own slot, and a replacement never picks up the + # totals of the child it replaced. fake_context = _FakeContext() pool = _make_fake_context_pool(fake_context, concurrency=2) @@ -1681,25 +1641,39 @@ def test_spawn_children_recycles_slots_across_generations() -> None: generation = fake_context.processes[seen:] seen += 2 - slots = {process.args[-1] for process in generation} - assert NO_SLOT not in slots - assert len(slots) == 2 - - # Nothing hands the slots back. The next scan reaps these children - # out of `_children`, which is all it takes. for process in generation: - process.alive = False + shm = process.args[-1] + assert list(shm) == [0.0] * SLOT_WIDTH - with pool._children_lock: - held = {c.timing.slot for c in pool._children.values()} - assert len(held) == len(pool._children) + # Dirty it, then kill the child. Reaping is the only thing + # that hands the memory back; nothing releases it by name. + ChildTimeWriter(shm).mark_busy(1.0) + process.alive = False finally: pool.shutdown() -def _writer_and_reader(slot: int = 0) -> tuple[ChildTimeWriter, ChildTimeAccounting]: - shm = get_context("fork").RawArray("d", SLOT_WIDTH * (slot + 1)) - return ChildTimeWriter(shm, slot), ChildTimeAccounting(shm=shm, slot=slot) +def test_new_slot_does_not_inherit_a_recycled_block() -> None: + # Dropping a slot returns its block to multiprocessing's heap, which hands + # the same bytes straight back to the next child. `new_slot` has to give + # that child a clean slate anyway. + ctx = get_context("fork") + + first = new_slot(ctx) + ChildTimeWriter(first).mark_busy(1.0) + address = ctypes.addressof(first) + del first + gc.collect() + + second = new_slot(ctx) + if ctypes.addressof(second) != address: + pytest.skip("allocator did not reuse the block, so nothing to check") + assert list(second) == [0.0] * SLOT_WIDTH + + +def _writer_and_reader() -> tuple[ChildTimeWriter, ChildTimeAccounting]: + shm = new_slot(get_context("fork")) + return ChildTimeWriter(shm), ChildTimeAccounting(shm=shm) def test_child_timing_round_trips_through_shared_memory() -> None: @@ -1765,10 +1739,10 @@ def test_child_timing_defers_rather_than_drops_a_torn_read() -> None: assert _bw(reader.sample(1.0)) == pytest.approx((1.0, 0.0)) - reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + reader.shm[SLOT_VERSION] += 1.0 assert _bw(reader.sample(2.0)) == pytest.approx((0.0, 0.0)) - reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + reader.shm[SLOT_VERSION] += 1.0 assert _bw(reader.sample(3.0)) == pytest.approx((2.0, 0.0)) @@ -1784,11 +1758,11 @@ def test_child_timing_carries_eligibility_across_a_deferred_sample() -> None: assert reader.sample(1.0).eligible == pytest.approx(1.0) # A failed read reports nothing at all, not zero busy against a full window. - reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + reader.shm[SLOT_VERSION] += 1.0 deferred = reader.sample(2.0) assert (deferred.busy, deferred.wait, deferred.eligible) == (0.0, 0.0, 0.0) - reader.shm[SLOT_VERSION] += 1.0 # type: ignore[index] + reader.shm[SLOT_VERSION] += 1.0 recovered = reader.sample(3.0) assert recovered.busy == pytest.approx(2.0) assert recovered.eligible == pytest.approx(2.0) @@ -1807,20 +1781,6 @@ def test_child_timing_stops_accruing_once_the_child_is_released() -> None: assert _bw(reader.sample(20.0)) == pytest.approx((0.0, 0.0)) -def test_child_timing_ignores_a_child_with_no_slot() -> None: - # Degraded mode: report nothing rather than raise. - shm = get_context("fork").RawArray("d", SLOT_WIDTH) - writer = ChildTimeWriter(shm, NO_SLOT) - reader = ChildTimeAccounting(shm=shm, slot=NO_SLOT) - - writer.mark_running(0.0) - writer.mark_busy(1.0) - reader.mark_running(0.0) - - assert _bw(reader.sample(10.0)) == pytest.approx((0.0, 0.0)) - assert shm[SLOT_SEGMENT_KIND] == KIND_NONE - - def test_child_timing_excludes_time_banked_before_the_parent_saw_running() -> None: # Numerator and denominator must start together, at the `running` message. writer, reader = _writer_and_reader() @@ -1831,60 +1791,6 @@ def test_child_timing_excludes_time_banked_before_the_parent_saw_running() -> No assert _bw(reader.sample(6.0)) == pytest.approx((0.0, 1.0)) -def test_available_timing_slots_follow_the_tracked_children() -> None: - # The property the derived set buys: a slot is in use exactly while its - # child is tracked, so no exit path can lose one by forgetting to give it - # back. Reaping the child is the only bookkeeping there is. - pool = _make_result_thread_pool(_SendResultCapture(), concurrency=2) - child_id = uuid4() - - with pool._children_lock: - assert sorted(pool._available_timing_slots()) == list(range(slot_count(2))) - - held = pool._take_timing_slot(pool._available_timing_slots()) - child = _make_tracked_child("running") - child.timing = ChildTimeAccounting(shm=pool._timing_shm, slot=held) - pool._children[child_id] = child - - assert held not in pool._available_timing_slots() - - with pool._children_lock: - pool._children.pop(child_id) - assert held in pool._available_timing_slots() - - -def test_take_timing_slot_zeroes_a_recycled_slot() -> None: - # A replacement must not inherit its predecessor's totals. - pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) - - with pool._children_lock: - slot = pool._take_timing_slot(pool._available_timing_slots()) - - writer = ChildTimeWriter(pool._timing_shm, slot) - writer.mark_running(0.0) - writer.mark_busy(0.0) - writer.mark_idle(30.0) - - # No child ever tracked it, so the next batch offers it straight back. - with pool._children_lock: - assert slot in pool._available_timing_slots() - recycled = pool._take_timing_slot(deque([slot])) - assert recycled == slot - - reader = ChildTimeAccounting(shm=pool._timing_shm, slot=recycled) - reader.mark_running(0.0) - assert _bw(reader.sample(1.0)) == pytest.approx((0.0, 0.0)) - - -def test_take_timing_slot_reports_exhaustion_instead_of_raising() -> None: - # Should be unreachable; the pool has to keep spawning either way. - pool = _make_result_thread_pool(_SendResultCapture(), concurrency=1) - pool._metrics = mock.Mock() - - assert pool._take_timing_slot(deque()) == NO_SLOT - assert len(_incr_calls(pool._metrics, "taskworker.worker.child.timing_slot_exhausted")) == 1 - - def test_emit_periodic_metrics_emits_busy_and_wait_seconds() -> None: # Interval [10.0, 11.0]: one child busy throughout, one waiting 0.25s. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) @@ -1937,7 +1843,7 @@ def test_spawn_children_reads_transitions_the_child_wrote() -> None: messages = fake_context.queues[-1] process = fake_context.processes[0] child_id = process.args[0] - writer = ChildTimeWriter(process.args[-2], process.args[-1]) + writer = ChildTimeWriter(process.args[-1]) writer.mark_running(0.0) messages.put(ChildMessage(child_id, "running")) @@ -1981,7 +1887,7 @@ def test_spawn_children_releases_draining_child_above_min_concurrency() -> None: messages = fake_context.queues[-1] first_process = fake_context.processes[0] first_child_id = first_process.args[0] - first_release = first_process.args[-3] + first_release = first_process.args[-2] messages.put(ChildMessage(first_child_id, "running")) second_process = fake_context.processes[1] @@ -2007,7 +1913,7 @@ def test_spawn_children_defers_draining_child_at_min_concurrency() -> None: messages = fake_context.queues[-1] first_process = fake_context.processes[0] first_child_id = first_process.args[0] - first_release = first_process.args[-3] + first_release = first_process.args[-2] second_process = fake_context.processes[1] second_child_id = second_process.args[0] @@ -2183,7 +2089,6 @@ def test_child_process_emits_running_message() -> None: messages=messages, parent_release=parent_release, timing_shm=timing_shm, - timing_slot=0, ) # The child signals readiness once warmup is done, before consuming @@ -2221,7 +2126,6 @@ def test_child_process_emits_exiting_once_and_continues_until_release( messages, parent_release, timing_shm, - 0, ), ) process.start() @@ -2275,7 +2179,6 @@ def test_child_process_records_busy_and_idle_in_its_slot() -> None: messages=messages, parent_release=parent_release, timing_shm=timing_shm, - timing_slot=0, ) assert messages.get(timeout=1) == ChildMessage(child_id, "running") From 7afcd9e00530539f1b652c5ae2e33c2462f55786 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Tue, 8 Sep 2026 13:22:49 -0400 Subject: [PATCH 15/17] Defer backwards totals, and check busy + wait as a pair --- .../taskbroker_client/worker/childtiming.py | 12 ++-- .../src/taskbroker_client/worker/worker.py | 10 ++-- clients/python/tests/worker/test_worker.py | 58 ++++++++++++++----- 3 files changed, 54 insertions(+), 26 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py index 1292c482..c23b803a 100644 --- a/clients/python/src/taskbroker_client/worker/childtiming.py +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -186,12 +186,14 @@ def sample(self, now: float) -> SampleResult: return SampleResult() busy_now, wait_now = reading - eligible = max(0.0, now - self._measured_from) - # A total going backwards means a torn read. Clamping drops that time, - # which the pool then sees as a deficit against `eligible`. - busy = max(0.0, busy_now - self._prev_busy) - wait = max(0.0, wait_now - self._prev_wait) + busy = busy_now - self._prev_busy + wait = wait_now - self._prev_wait + if busy < 0.0 or wait < 0.0: + # Totals only ever grow, so a fall means a stale read got past the + # seqlock. + return SampleResult() + eligible = max(0.0, now - self._measured_from) self._prev_busy = busy_now self._prev_wait = wait_now self._measured_from = now diff --git a/clients/python/src/taskbroker_client/worker/worker.py b/clients/python/src/taskbroker_client/worker/worker.py index 4db570f1..c4e402a7 100644 --- a/clients/python/src/taskbroker_client/worker/worker.py +++ b/clients/python/src/taskbroker_client/worker/worker.py @@ -1007,11 +1007,9 @@ def _emit_periodic_metrics(self) -> None: # as idle time the pool never had. ceiling = eligible_time # busy and wait partition every measured window, so the pair must - # land on the ceiling. Over means time was counted twice; under - # means a child's totals went backwards and time was dropped. Both - # should stay at zero, and occupancy is not trustworthy while either - # is firing. - if busy_time > ceiling or wait_time > ceiling: + # land on the ceiling. + accounted = busy_time + wait_time + if accounted > ceiling: self._metrics.incr( "taskworker.worker.occupancy.accounting_overflow", tags=tags, @@ -1020,7 +1018,7 @@ def _emit_periodic_metrics(self) -> None: "taskworker.worker.occupancy.accounting_overflow", extra=self._accounting_log(busy_time, wait_time, ceiling, running_count), ) - elif busy_time + wait_time < ceiling * 0.9: + elif accounted < ceiling * 0.9: self._metrics.incr( "taskworker.worker.occupancy.accounting_deficit", tags=tags, diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index fa50754a..6f0dfe14 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1454,6 +1454,28 @@ def test_emit_periodic_metrics_clamps_occupancy_and_flags_the_overflow() -> None assert len(_incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow")) == 1 +def test_emit_periodic_metrics_flags_an_overflow_split_across_busy_and_wait() -> None: + # 2.4 accounted seconds inside a 2.0 second window. Neither counter alone + # clears the ceiling, so testing them one at a time misses it entirely. + pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) + pool._metrics = mock.Mock() + + with pool._children_lock: + for _ in range(2): + pool._children[uuid4()] = _make_tracked_child( + "running", busy_accumulated=0.6, wait_accumulated=0.6 + ) + + with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): + pool._emit_periodic_metrics() + + assert len(_incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow")) == 1 + # A per-counter test read this pool as healthy at 0.6 occupancy. + assert _gauge_calls(pool._metrics, "taskworker.worker.occupancy")[0].args[1] == pytest.approx( + 0.6 + ) + + def test_emit_periodic_metrics_does_not_flag_a_legitimately_full_pool() -> None: # The guard must not fire on a pool that is simply saturated, or it is noise. pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) @@ -1505,14 +1527,14 @@ def test_emit_periodic_metrics_flags_a_deficit_when_a_child_loses_time() -> None pool = _make_result_thread_pool(_SendResultCapture(), concurrency=4) pool._metrics = mock.Mock() - # Baseline at 5.0, then drop the slot's total: a reused slot or a torn read. - lost = _make_tracked_child("running", busy_accumulated=5.0) - lost.timing.sample(10.0) - lost.timing.shm[SLOT_BUSY_TOTAL] = 0.2 + # A child whose slot stopped accruing, as it does between closing its last + # segment and the parent seeing `exiting`. Neither counter moves, but the + # window the pool measured it over still does. + stalled = _make_tracked_child("running") with pool._children_lock: pool._children[uuid4()] = _make_tracked_child("running", busy_since=10.0) - pool._children[uuid4()] = lost + pool._children[uuid4()] = stalled with mock.patch("taskbroker_client.worker.worker.time.monotonic", return_value=11.0): pool._emit_periodic_metrics() @@ -1563,23 +1585,29 @@ def test_emit_periodic_metrics_does_not_flag_a_deficit_when_time_is_all_there() assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] -def test_sample_clamps_a_backwards_total_and_leaves_the_window_intact() -> None: - # A total going backwards means a torn read or a reused slot. Clamping keeps - # the number sane but drops real time, and `eligible` must still report the - # full window so the pool sees the shortfall as a deficit. +def test_sample_defers_a_backwards_total_rather_than_baselining_on_it() -> None: + # Totals only grow, so a fall is a stale read. Taking the smaller value as + # the new baseline would bill the span between it and the real total a + # second time once the real total came back. writer, reader = _writer_and_reader() writer.mark_running(0.0) reader.mark_running(0.0) writer.mark_busy(0.0) assert reader.sample(1.0).busy == pytest.approx(1.0) - # Rewind the slot underneath the reader, as slot reuse would. - reader.shm[SLOT_BUSY_TOTAL] = 0.0 - reader.shm[SLOT_SEGMENT_START] = 2.0 + # Rewind the slot underneath the reader, as a stale read would. + reader.shm[SLOT_BUSY_TOTAL] = 0.5 + reader.shm[SLOT_SEGMENT_KIND] = KIND_NONE - result = reader.sample(2.0) - assert result.busy == 0.0 - assert result.eligible == pytest.approx(1.0) + deferred = reader.sample(2.0) + assert (deferred.busy, deferred.wait, deferred.eligible) == (0.0, 0.0, 0.0) + + # The real total is visible again. One second of busy happened across the + # two windows, and the 1.0 already reported at t=1 is not billed again. + reader.shm[SLOT_BUSY_TOTAL] = 2.0 + recovered = reader.sample(3.0) + assert recovered.busy == pytest.approx(1.0) + assert recovered.eligible == pytest.approx(2.0) def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: From c8621beddd946d5b790083086189c9a4ee97525b Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Tue, 8 Sep 2026 13:44:17 -0400 Subject: [PATCH 16/17] Stop test_run_once_current_task_state enqueueing a second task 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) --- clients/python/tests/worker/test_worker.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index 6f0dfe14..fc2d0331 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -875,8 +875,16 @@ def test_run_once_current_task_state(self) -> None: def update_task_response(*args: Any, **kwargs: Any) -> None: return None + def get_task_response(*args: Any, **kwargs: Any) -> InflightTaskActivation | None: + # Exactly one task. `run_once` is called in a loop below, so a + # standing return_value hands out a second task whenever the + # result thread is slow, and update_task.call_count reaches 2. + if mock_client.get_task.call_count == 1: + return RETRY_STATE_TASK + return None + mock_client.update_task.side_effect = update_task_response - mock_client.get_task.return_value = RETRY_STATE_TASK + mock_client.get_task.side_effect = get_task_response taskworker.worker_pool.start_result_thread() taskworker.worker_pool.start_spawn_children_thread() From 03c5dca707000c7541bdb0fd357346a091de52b8 Mon Sep 17 00:00:00 2001 From: Enoch Tang Date: Tue, 8 Sep 2026 14:04:52 -0400 Subject: [PATCH 17/17] Make the accounted baseline a high-water mark --- .../taskbroker_client/worker/childtiming.py | 17 ++++--- clients/python/tests/worker/test_worker.py | 45 ++++++++++++++----- 2 files changed, 41 insertions(+), 21 deletions(-) diff --git a/clients/python/src/taskbroker_client/worker/childtiming.py b/clients/python/src/taskbroker_client/worker/childtiming.py index c23b803a..772906e9 100644 --- a/clients/python/src/taskbroker_client/worker/childtiming.py +++ b/clients/python/src/taskbroker_client/worker/childtiming.py @@ -186,16 +186,15 @@ def sample(self, now: float) -> SampleResult: return SampleResult() busy_now, wait_now = reading - busy = busy_now - self._prev_busy - wait = wait_now - self._prev_wait - if busy < 0.0 or wait < 0.0: - # Totals only ever grow, so a fall means a stale read got past the - # seqlock. - return SampleResult() - + busy = max(0.0, busy_now - self._prev_busy) + wait = max(0.0, wait_now - self._prev_wait) eligible = max(0.0, now - self._measured_from) - self._prev_busy = busy_now - self._prev_wait = wait_now + + # High-water, not the last value read. The fold above can overshoot the + # timestamp the child publishes for that segment, so a total can land + # under the baseline. Moving it down re-bills the span next sample. + self._prev_busy = max(self._prev_busy, busy_now) + self._prev_wait = max(self._prev_wait, wait_now) self._measured_from = now return SampleResult(busy, wait, eligible) diff --git a/clients/python/tests/worker/test_worker.py b/clients/python/tests/worker/test_worker.py index fc2d0331..dec277a3 100644 --- a/clients/python/tests/worker/test_worker.py +++ b/clients/python/tests/worker/test_worker.py @@ -1593,10 +1593,10 @@ def test_emit_periodic_metrics_does_not_flag_a_deficit_when_time_is_all_there() assert _incr_calls(pool._metrics, "taskworker.worker.occupancy.accounting_overflow") == [] -def test_sample_defers_a_backwards_total_rather_than_baselining_on_it() -> None: - # Totals only grow, so a fall is a stale read. Taking the smaller value as - # the new baseline would bill the span between it and the real total a - # second time once the real total came back. +def test_sample_holds_the_baseline_when_a_total_lands_below_it() -> None: + # The baseline is a high-water mark. A total that comes in under it reports + # nothing, and the baseline stays put so the next clean read is measured + # from it rather than from the low value. writer, reader = _writer_and_reader() writer.mark_running(0.0) reader.mark_running(0.0) @@ -1606,16 +1606,37 @@ def test_sample_defers_a_backwards_total_rather_than_baselining_on_it() -> None: # Rewind the slot underneath the reader, as a stale read would. reader.shm[SLOT_BUSY_TOTAL] = 0.5 reader.shm[SLOT_SEGMENT_KIND] = KIND_NONE + assert reader.sample(2.0).busy == 0.0 - deferred = reader.sample(2.0) - assert (deferred.busy, deferred.wait, deferred.eligible) == (0.0, 0.0, 0.0) - - # The real total is visible again. One second of busy happened across the - # two windows, and the 1.0 already reported at t=1 is not billed again. + # 1.0 was already reported at t=1, so only the second 1.0 is billed here. reader.shm[SLOT_BUSY_TOTAL] = 2.0 - recovered = reader.sample(3.0) - assert recovered.busy == pytest.approx(1.0) - assert recovered.eligible == pytest.approx(2.0) + assert reader.sample(3.0).busy == pytest.approx(1.0) + + +def test_sample_keeps_counting_wait_when_the_fold_overshoots_a_close() -> None: + # The parent folds an open segment to its own `now`, so its baseline can sit + # above the timestamp the child publishes microseconds later. Only busy is + # pinned by that; the child must keep reporting wait rather than dropping + # out of occupancy until its next task. + writer, reader = _writer_and_reader() + writer.mark_running(0.0) + reader.mark_running(0.0) + writer.mark_busy(0.0) + + # Folded to 1.0, so the baseline is 1.0. + assert reader.sample(1.0).busy == pytest.approx(1.0) + # The child read its clock at 0.999 and only publishes now, under that. + writer.mark_idle(0.999) + + first = reader.sample(2.0) + assert first.busy == 0.0 + assert first.wait == pytest.approx(1.001) + assert first.eligible == pytest.approx(1.0) + + second = reader.sample(3.0) + assert second.busy == 0.0 + assert second.wait == pytest.approx(1.0) + assert second.eligible == pytest.approx(1.0) def test_emit_periodic_metrics_counters_exclude_non_running_children() -> None: