Files
app/backend/fluksio/flow/executor.py
T

732 lines
29 KiB
Python

"""The execution service: what turns journaled work into node runs.
A consumer thread claims items from the work queue and hands each one to a
dispatch pool, which drives the wave it starts. It claims only what that pool
can start, so a backlog waits in the queue rather than inside the process.
Node bodies run on a second, separate pool: if cascade drivers and node bodies
shared one, a wave waiting for its own nodes could occupy every thread and
deadlock.
A reaper takes back items claimed by an engine that died before acknowledging
them, which is the mechanism that makes a crash mid-cascade recoverable rather
than lossy.
"""
from __future__ import annotations
import logging
import threading
import time
from collections import Counter, deque
from collections.abc import Callable
from concurrent.futures import Executor, Future, ThreadPoolExecutor
from typing import TYPE_CHECKING, Any, ParamSpec, TypeVar
from fluksio.flow.queue import MAX_DELIVERIES, WorkItem, WorkQueue
if TYPE_CHECKING:
from fluksio.flow.events import EventBus
from fluksio.flow.namespace import Rename
from fluksio.flow.pipeline import Pipeline
logger = logging.getLogger(__name__)
CLAIM_BLOCK_MS = 1000
# Long enough that a busy cascade is not mistaken for a dead one.
RECLAIM_IDLE_MS = 60_000
RECLAIM_INTERVAL_S = 30.0
# How often to tell the queue that what we hold is still being worked on. A
# node may run for as long as it likes, so what marks an item abandoned is this
# stopping — which is what an engine that died does.
TOUCH_INTERVAL_S = 20.0
# The longest the timer thread sleeps with nothing due. It is a housekeeping
# cadence and a backstop for a deadline written by another process, not the
# resolution of a delay: a delayed item is waited for exactly, so what a timer
# fires late by is a wake-up and a promotion rather than up to a whole second.
DELAYED_INTERVAL_S = 1.0
# Extra cascade and node workers reserved for promoted timers. A due item was
# already waited for, so making it queue behind whatever long node happens to
# hold either pool is lateness the sleeping timer thread cannot remove.
DUE_RESERVE = 2
# How long the saturated engine waits on the due lane before going back to
# check whether a cascade slot has freed.
DUE_CLAIM_BLOCK_MS = 200
#: How many cascades may be in flight, unless the service is given a number.
#: Sustained throughput is this over the mean cascade time, so an instance
#: whose nodes wait on a network rather than a CPU may want more of them —
#: `FLOW_MAX_CASCADES` is where that is said.
MAX_CASCADES = 4
#: Node threads, unless the service is given a number. Both this and the one
#: above are taken as written: only ``None`` means "nobody said", so a number
#: that reached here is one somebody chose, and an unusable one is the pool's
#: ``ValueError`` rather than a silent 4.
MAX_WORKERS = 4
# How long a reload waits for claimed work to finish before rebuilding anyway.
DRAIN_TIMEOUT_S = 10.0
# Work waiting in the stream, undelivered. A burst is normal — the pool claims
# only what it can start — so what marks an engine as falling behind is the
# backlog staying up across several checks rather than any one reading.
BACKLOG_INTERVAL_S = 5.0
BACKLOG_DEGRADED = 50
BACKLOG_STRIKES = 3
#: How often an engine hold looks at its abort while it waits.
HOLD_POLL_S = 0.5
_P = ParamSpec("_P")
_T = TypeVar("_T")
def wait_out(
lock: threading.Condition,
busy: Callable[[], list[str]],
abort: threading.Event,
report: Callable[[list[str]], None] | None = None,
) -> bool:
"""Wait until ``busy``, read under ``lock``, names nothing.
Without a limit, because an engine hold waits for as long as the work
takes. ``report`` hears each new set of names, so whoever asked can show
what it waits for, and setting ``abort`` gives up with False.
"""
said: list[str] = []
while True:
with lock:
names = busy()
while names and names == said and not abort.is_set():
lock.wait(HOLD_POLL_S)
names = busy()
if abort.is_set():
return False
if not names:
return True
said = names
if report is not None:
report(names)
class _PoolLane(Executor):
def __init__(self, pool: _ReservedPool, due: bool) -> None:
self._pool = pool
self._due = due
def submit(
self, fn: Callable[_P, _T], /, *args: _P.args, **kwargs: _P.kwargs
) -> Future[_T]:
return self._pool.submit(self._due, fn, *args, **kwargs)
class _ReservedPool:
"""Due work uses idle normal workers, or its own bounded reserve."""
def __init__(
self, workers: int, prefix: str, on_done: Callable[[], None] | None = None
) -> None:
self._limits = (workers, DUE_RESERVE)
self._pools = (
ThreadPoolExecutor(max_workers=workers, thread_name_prefix=prefix),
ThreadPoolExecutor(
max_workers=DUE_RESERVE, thread_name_prefix=f"{prefix}-due"
),
)
self._pending = [0, 0]
self._lock = threading.Lock()
self._on_done = on_done
self.normal = _PoolLane(self, False)
self.due = _PoolLane(self, True)
def available(self) -> tuple[int, int]:
with self._lock:
return (
max(0, self._limits[0] - self._pending[0]),
max(0, self._limits[1] - self._pending[1]),
)
def _done(self, lane: int) -> None:
with self._lock:
self._pending[lane] -= 1
if self._on_done is not None:
self._on_done()
def submit(
self, due: bool, fn: Callable[_P, _T], /, *args: _P.args, **kwargs: _P.kwargs
) -> Future[_T]:
with self._lock:
# Count queued work too: an idle thread with ordinary work already
# waiting is not capacity a timer can use without waiting behind it.
lane = int(due and self._pending[0] >= self._limits[0])
self._pending[lane] += 1
try:
future = self._pools[lane].submit(fn, *args, **kwargs)
except RuntimeError:
self._done(lane)
raise
future.add_done_callback(lambda _: self._done(lane))
return future
def shutdown(self) -> None:
for pool in self._pools:
pool.shutdown(wait=False)
class ExecutionService:
"""Owns the engine's worker threads and the queue they read from."""
def __init__(
self,
queue: WorkQueue,
max_workers: int | None = None,
events: EventBus | None = None,
max_cascades: int | None = None,
) -> None:
self.queue = queue
self._events = events
self.max_cascades = MAX_CASCADES if max_cascades is None else max_cascades
self._pipeline: Pipeline | None = None
self._stop = threading.Event()
# Set when a deadline moves closer, so the timer thread stops waiting
# on the one it read and goes back for the new one.
self._timer_wake = threading.Event()
queue.on_delayed = self._timer_wake.set
self._intake = threading.Event()
self._intake.set()
# Cascades claimed and still running, by the node each came from.
self._running: Counter[str] = Counter()
self._inflight_lock = threading.Condition()
# Entry ids claimed and still running, under _inflight_lock.
self._active: set[str] = set()
# At most one reclaim batch waits here. The timer thread must keep
# promoting and touching work while the consumer waits for capacity.
self._reclaimed: deque[WorkItem] = deque()
self._node_pools = _ReservedPool(
MAX_WORKERS if max_workers is None else max_workers, "node"
)
self.node_pool = self._node_pools.normal
self._cascade_pools = _ReservedPool(
self.max_cascades, "cascade", self._capacity_changed
)
self._consumer: threading.Thread | None = None
self._timers: threading.Thread | None = None
# Held by the consumer for one pass of capacity check, claim and
# dispatch, and by the timer thread for one pass of promotion, touch
# and reclaim. `hold` takes both. Plain locks, because `release` may
# come from another thread than the one that held.
self._consumer_lock = threading.Lock()
self._timer_lock = threading.Lock()
# Consecutive backlog readings over the threshold, and whether the last
# of them said so out loud.
self._backlog_strikes = 0
self.behind = False
# -------------------------------------------------------------------------
# Lifecycle
# -------------------------------------------------------------------------
def start(self) -> None:
if self._consumer is not None:
return
self._consumer = threading.Thread(
target=self._consume, name="queue-consumer", daemon=True
)
self._consumer.start()
self._timers = threading.Thread(
target=self._tick, name="queue-timers", daemon=True
)
self._timers.start()
def stop(self) -> None:
self._stop.set()
# The timer thread sleeps on this, not on _stop.
self._timer_wake.set()
for thread in (self._consumer, self._timers):
if thread is not None:
thread.join(timeout=5)
self._consumer = None
self._timers = None
self._cascade_pools.shutdown()
self._node_pools.shutdown()
self.queue.close()
def bind(self, pipeline: Pipeline) -> None:
"""Point the service at the pipeline it should execute against."""
self._pipeline = pipeline
def _capacity_changed(self) -> None:
with self._inflight_lock:
self._inflight_lock.notify_all()
def pause_intake(self) -> None:
"""Stop claiming, and wait for what is already claimed to finish.
Called around a rebuild: items claimed against the old pipeline should
finish there rather than half-run against the new one.
"""
self._intake.clear()
deadline = time.monotonic() + DRAIN_TIMEOUT_S
with self._inflight_lock:
while self._running:
remaining = deadline - time.monotonic()
if remaining <= 0:
logger.warning(
"Rebuild did not wait out %d cascades", self._running.total()
)
return
self._inflight_lock.wait(remaining)
def resume_intake(self) -> None:
self._intake.set()
def hold(
self,
abort: threading.Event,
report: Callable[[list[str]], None] | None = None,
) -> bool:
"""Stop claiming, promoting, touching and reclaiming, once every
claimed cascade has finished. For a rename, which rewrites the queue.
Unlike `pause_intake` this also waits out a claim already blocking
when intake clears, and a timer pass. It waits without a limit and
tells ``report`` the nodes whose cascades are still running each time
they change. Setting ``abort`` gives up: claiming resumes and it
returns False. True means held until `release`.
"""
self._intake.clear()
# So a consumer waiting for capacity sees the intake closed.
self._capacity_changed()
self._consumer_lock.acquire()
# The timer lock only after the drain: while a cascade runs, the
# timer thread keeps touching it, so it is not reclaimed as dropped.
if not wait_out(self._inflight_lock, self._busy, abort, report):
self._consumer_lock.release()
self._intake.set()
return False
self._timer_lock.acquire()
return True
def release(self) -> None:
"""End a `hold`."""
self._timer_lock.release()
self._consumer_lock.release()
self._intake.set()
def rename_reclaimed(self, rename: Rename) -> None:
"""Move the names in reclaimed work still waiting to be run, which
the queue's own `rename` cannot reach. Under a `hold`."""
with self._inflight_lock:
self._reclaimed = deque(
rename.item(item) or item for item in self._reclaimed
)
def _busy(self) -> list[str]:
"""The nodes whose cascades are running. Under _inflight_lock."""
return sorted(self._running)
def alive(self) -> bool:
return self._consumer is not None and self._consumer.is_alive()
@property
def inflight(self) -> int:
"""Cascades claimed and still running."""
with self._inflight_lock:
return self._running.total()
# -------------------------------------------------------------------------
# Threads
# -------------------------------------------------------------------------
def _consume(self) -> None:
failures = 0
while not self._stop.is_set():
if not self._intake.is_set():
self._intake.wait(timeout=0.5)
continue
backoff = 0.0
with self._consumer_lock:
free, due_only = self._await_capacity()
if not free:
continue
with self._inflight_lock:
recovered = [
item
for item in self._reclaimed
if not due_only or item.not_before > 0
][:free]
for item in recovered:
self._reclaimed.remove(item)
if recovered:
for item in recovered:
self._dispatch(item)
continue
try:
items = self.queue.claim(
free,
# Briefly, in the due-only case: this is the saturated
# engine, and a slot freeing has to be noticed promptly.
DUE_CLAIM_BLOCK_MS if due_only else CLAIM_BLOCK_MS,
due_only,
)
failures = 0
except Exception as exc:
failures += 1
logger.error("Could not claim work: %s", exc)
self._publish_unavailable(exc)
# Backing off hard: a queue that is down stays down for a
# while. Outside the lock, so a hold does not wait it out.
backoff = min(30.0, 2.0**failures)
items = []
for item in items:
self._dispatch(item)
if backoff:
self._stop.wait(backoff)
def _sleep_until_due(self) -> bool:
"""Wait for the soonest deadline, the housekeeping cap, or a new one.
Sleeping until the deadline avoids adding a fixed polling delay to
timed work. New deadlines wake the timer so earlier work is not missed.
"""
self._timer_wake.clear()
try:
# Read after the clear: a deadline arriving in between sets the
# event again, so the wait below returns immediately rather than
# sleeping through work that landed in the gap.
due = self.queue.next_due()
except Exception as exc:
logger.error("Could not read the next deadline: %s", exc)
due = None
wait = DELAYED_INTERVAL_S if due is None else due - time.time()
self._timer_wake.wait(min(max(wait, 0.0), DELAYED_INTERVAL_S))
# What the caller promotes for: the deadline this woke for has passed,
# or the read failed and it should look anyway. An idle engine reads
# `next_due` once a second and asks for nothing.
return due is None or due <= time.time()
def _tick(self) -> None:
"""Promote delayed items, and take back what a dead engine dropped."""
last_reclaim = 0.0
last_touch = 0.0
last_backlog = 0.0
while not self._stop.is_set():
promote = self._sleep_until_due()
if self._stop.is_set():
break
# One pass, not the sleep above: a hold waits for it to end.
with self._timer_lock:
try:
if promote:
self.queue.move_due(time.time())
except Exception as exc:
logger.error("Could not promote delayed work: %s", exc)
# The item is still due, so the wait above would be zero and
# this would spin on a queue that is down. Back off to what a
# fixed poll used to cost.
self._stop.wait(DELAYED_INTERVAL_S)
now = time.monotonic()
if now - last_backlog >= BACKLOG_INTERVAL_S:
last_backlog = now
try:
self._check_backlog()
except Exception as exc:
logger.error("Could not read the queue backlog: %s", exc)
if now - last_touch >= TOUCH_INTERVAL_S:
last_touch = now
with self._inflight_lock:
running = list(self._active)
try:
self.queue.touch(running)
except Exception as exc:
logger.error("Could not touch claimed work: %s", exc)
if now - last_reclaim < RECLAIM_INTERVAL_S:
continue
with self._inflight_lock:
if self._reclaimed or not self._intake.is_set():
continue
last_reclaim = now
try:
recovered = self.queue.reclaim_stale(RECLAIM_IDLE_MS)
for item in recovered:
logger.info(
"Reclaimed work for '%s' (delivery %d)",
item.node,
item.deliveries,
)
with self._inflight_lock:
self._reclaimed.extend(recovered)
self._active.update(
item.entry_id for item in recovered if item.entry_id
)
except Exception as exc:
logger.error("Could not reclaim stale work: %s", exc)
def _check_backlog(self) -> None:
"""Say so when work has been waiting in the stream for a while.
A flow enqueuing faster than the pool drains produces no event of its
own: the backlog simply grows, every timer and connector poll drifts
behind it, and nothing on the health screen moves. This is that event.
The flow named is the one most of the waiting work belongs to, which is
the half somebody can act on.
"""
backlog = self.queue.backlog()
if backlog < BACKLOG_DEGRADED:
self._backlog_strikes = 0
self.behind = False
return
self._backlog_strikes += 1
if self._backlog_strikes < BACKLOG_STRIKES or self.behind:
return
self.behind = True
flows = self.queue.backlog_flows()
worst = max(flows, key=lambda f: flows[f], default="")
logger.warning("engine behind: %d items waiting (%s)", backlog, worst or "?")
self._publish(
{
"type": "engine_degraded",
"reason": f"{backlog} items waiting in the queue",
"flow": worst,
"ts": time.time(),
}
)
def _await_capacity(self) -> tuple[int, bool]:
"""How many cascades may be claimed now, and whether only due ones.
Claiming past what the pool can run makes nothing faster: the extra
items queue up inside the pool, count as in flight and hold their
journal entries open the whole time, which is how four cascade threads
came to report hundreds busy on a healthy engine. Work left in the
stream is work that is still anyone's to take; work that is claimed is
work that is actually being run.
The gate sat in front of the claim, though, and the due lane's
priority is decided *inside* it — so with every slot held by a long
node, a motor's stop was not merely behind them, it was unread. Past
the limit this therefore keeps claiming, from the due lane alone:
a promoted timer is work that was already waited for, and there are
only ever as many of them as there are deadlines.
"""
with self._inflight_lock:
while not self._stop.is_set():
if not self._intake.is_set():
return 0, False
free, _ = self._cascade_pools.available()
if free > 0:
return free, False
# Only once a slot has genuinely failed to free: the due lane
# is usually empty, and going to look at it ahead of waiting
# would leave the backlog unclaimed for the length of that
# read every time the pool filled up.
if self._inflight_lock.wait(0.5):
continue
_, reserve = self._cascade_pools.available()
if reserve > 0:
return reserve, True
return 0, False
def _dispatch(self, item: WorkItem) -> None:
with self._inflight_lock:
self._running[item.node] += 1
if item.entry_id:
self._active.add(item.entry_id)
try:
pool = (
self._cascade_pools.due
if item.not_before > 0
else self._cascade_pools.normal
)
pool.submit(self._handle, item)
except RuntimeError:
# Pool already shutting down.
self._done(item)
def _done(self, item: WorkItem) -> None:
with self._inflight_lock:
self._running -= Counter((item.node,))
self._active.discard(item.entry_id)
self._inflight_lock.notify_all()
# -------------------------------------------------------------------------
# Handling one item
# -------------------------------------------------------------------------
def step(self, flow: str) -> str | None:
"""Run one item a pause is holding, and hold everything else still.
Blocking, so the caller sees the wave finish. Returns the node the item
came from, or None when nothing is parked for this flow.
"""
pipeline = self._pipeline
if pipeline is None:
return None
item = self.queue.unpark_one(flow)
if item is None:
return None
with pipeline.stepping(flow):
try:
self._run_item(item)
except Exception:
logger.exception("Step of '%s' failed", item.node)
return item.node
def _handle(self, item: WorkItem) -> None:
handled = False
try:
handled = self._run_item(item)
except Exception:
logger.exception("Work item for '%s' failed", item.node)
finally:
# Leaving it unacknowledged is how it comes back: the reaper hands
# it to whoever can actually run it.
if handled:
try:
self.queue.ack(item)
except Exception as exc:
logger.error(
"Could not acknowledge work for '%s': %s", item.node, exc
)
self._done(item)
def _run_item(self, item: WorkItem) -> bool:
"""Run one item. False means it was not handled and must come back."""
pipeline = self._pipeline
if pipeline is None:
logger.warning("No pipeline bound; leaving work for '%s'", item.node)
return False
if item.deliveries > MAX_DELIVERIES:
self.queue.dead_letter(item, f"{item.deliveries} deliveries")
self._publish(
{
"type": "cascade_dropped",
"flow": item.flow,
"node": item.node,
"deliveries": item.deliveries,
"ts": time.time(),
}
)
return True
node = pipeline.get_node_by_id(item.node)
if node is None:
# The flow was edited while this was queued; its values are already
# in state, so there is nothing to salvage.
logger.debug("Work item for unknown node '%s', dropped", item.node)
return True
if pipeline.is_disabled(node.flow):
return True
if pipeline.is_paused(node.flow) and not pipeline.is_stepping(node.flow):
self.queue.park(node.flow, item)
return True
if item.guard_key and str(node.recall(item.guard_key, "")) != item.guard_value:
# The node moved on while this waited — a restarted timer, say.
logger.debug("Guard no longer holds for '%s', dropped", item.node)
return True
# Only here is the item certain to run, which is what a run record is.
now = time.time()
self._publish(
{
"type": "cascade_started",
"run": item.entry_id,
"flow": item.flow,
"node": item.node,
"cause": item.cause,
"parent": item.parent,
"deliveries": item.deliveries,
"ts": now,
}
)
if item.deliveries == 1:
# A redelivery waited for the reaper, not for the engine.
self._publish(
{
"type": "work_latency",
"flow": item.flow,
"node": item.node,
"lag_ms": max(
0.0,
(now - max(item.enqueued_at, item.not_before)) * 1000,
),
"ts": now,
}
)
replay = item.deliveries > 1
emission = item.kind == "emission"
node_pool = self._node_pools.due if item.not_before > 0 else self.node_pool
try:
if item.kind == "flush":
# A rate-limit window ended; nothing to replay, only to let out.
# A run of its own, so what it sets off is recorded somewhere.
pipeline.flush(node, item.entry_id, node_pool=node_pool)
return True
# An emission's values went into state when the node produced them;
# this item carries them so its readers get the chunk that caused
# the wave rather than whichever is newest by the time they run.
# Applying them again would let a mid-node emission overwrite what
# the node returned at the end.
published = (
set(item.outputs)
if emission
else pipeline.apply_outputs(node, item.outputs or None, item.entry_id)
)
pipeline.run_downstream(
node,
entry_id=item.entry_id,
replay=replay,
# A redelivery has to finish a walk that may be half done, and
# an item with no payload is the value already being in state.
# Neither can say what changed, so neither filters on it.
changed=None if replay or not item.outputs else published,
overrides=item.outputs if emission else None,
node_pool=node_pool,
)
finally:
# Paired, or a cascade that raised — state backend gone, say — is a
# run left open until the abandoned sweep ten minutes later.
self._publish(
{
"type": "cascade_finished",
"run": item.entry_id,
"flow": item.flow,
"ts": time.time(),
}
)
return True
# -------------------------------------------------------------------------
# Reporting
# -------------------------------------------------------------------------
def stats(self) -> dict[str, Any]:
try:
stats = self.queue.stats()
except Exception as exc:
return {"error": str(exc), "consumer_alive": self.alive()}
stats["consumer_alive"] = self.alive()
stats["cascades_busy"] = self.inflight
stats["behind"] = self.behind
return stats
def _publish_unavailable(self, exc: Exception) -> None:
self._publish(
{
"type": "queue_unavailable",
"error": f"{type(exc).__name__}: {exc}",
"ts": time.time(),
}
)
def _publish(self, event: dict[str, Any]) -> None:
if self._events is not None:
self._events.publish(event)