stroblmeandClaude Opus 5
180da3d640
The engine was I/O-bound on its own state backend. `RedisState.lock()` is one key — `pipeline:_lock` — for the whole process, taken five times a message at two round trips each, and every cascade and every node read queued behind it. Inside it, reading a node's inputs was three round trips per input (an EXISTS for `in`, then EXISTS and GET for the value), writing was two updates that a single transaction already gives, and the version counters went one INCR at a time. Replaced with the atomic command that was always available: `get_present` is one MGET and tells a missing key from one holding null, so the lock it used to be read under bought nothing; value and timestamp land in one `update`, which is a MULTI/EXEC; `increment_multi` pipelines the counters. `values()` — what every websocket snapshot calls — is two reads whatever the message count instead of two per message. Beside that: every webhook did its blocking XADD on the asyncio event loop (MQTT already used `to_thread`); the per-execution `NodeOutcome` was built and validated even with no run watching; `_minute` built a tz-aware datetime per event on the loop thread to key a dict, and now keys on an int; `move_due` promoted delayed items one round trip each, every second; `FLOW_MAX_CASCADES` makes the in-flight ceiling a setting rather than a constant. `orjson` replaces stdlib json where a message pays for it — state, the journal, the engine side of the worker pipe. `fluksio-worker` stays dependency-free, and the run-cache digest stays on stdlib so no stored key is invalidated. A non-finite number now stores as `null` rather than the bare `NaN` that was never JSON. Measured with `scripts/bench_engine.py` against a real Redis, 200 messages: a five-node chain went from 43.9 to 103.1 msg/s with p50 latency 2110ms → 782ms and p95 3913ms → 1439ms; one source into twenty consumers went from 5.4 to 33.7 msg/s. In memory, twenty consumers went from 187 to 448 msg/s. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01BpfSinyCBfjuieikyfMPbf
511 lines
17 KiB
Python
511 lines
17 KiB
Python
#!/usr/bin/env python
|
|
"""Engine throughput bench: what a message costs, in work and in time.
|
|
|
|
`bench_startup.py` times submitting a run; this times the live path — a value
|
|
arriving at a subscriber and reaching everything downstream of it. It builds a
|
|
pipeline and an execution service in this process, so there is no HTTP, no
|
|
container and no browser between the measurement and the engine.
|
|
|
|
Three scenarios, each answering a different question:
|
|
|
|
``throttle``
|
|
What does a rate-limited port cost? A source publishing every 15s behind
|
|
seven relays, driven at the rate the house's inverter actually sends.
|
|
Reports cascades enqueued, node executions and bus events per injection —
|
|
the numbers, not the wall clock, are the point.
|
|
|
|
``relay``
|
|
The same, with the *source* unlimited: the cascade really is owed, and
|
|
what the relays hold back is what the node reading them should not be
|
|
woken for.
|
|
|
|
``throughput``
|
|
How many messages a second, and how late is the last node? A relay chain,
|
|
driven until the queue drains, reporting end-to-end latency percentiles.
|
|
|
|
``fanout``
|
|
One source into many consumers: the scheduler's own overhead per wave.
|
|
|
|
Run against the memory backends by default; ``--redis`` points state and queue
|
|
at a real Redis, which is what the engine runs on and where the round trips
|
|
this is meant to expose actually happen.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import argparse
|
|
import cProfile
|
|
import json
|
|
import logging
|
|
import pstats
|
|
import statistics
|
|
import sys
|
|
import threading
|
|
import time
|
|
from collections.abc import Callable
|
|
from dataclasses import dataclass, field
|
|
from typing import Any
|
|
|
|
from fluksio.flow.events import EventBus
|
|
from fluksio.flow.executor import ExecutionService
|
|
from fluksio.flow.messages import DType, MessageSpec
|
|
from fluksio.flow.nodes import Node
|
|
from fluksio.flow.pipeline import Pipeline
|
|
from fluksio.flow.queue import MemoryWorkQueue, RedisWorkQueue, WorkQueue
|
|
from fluksio.flow.state import MemoryState, RedisState, StateBackend
|
|
|
|
log = logging.getLogger("bench")
|
|
|
|
FLOW = "bench"
|
|
|
|
|
|
# -----------------------------------------------------------------------------
|
|
# Counting what the engine did
|
|
# -----------------------------------------------------------------------------
|
|
|
|
|
|
@dataclass
|
|
class Counters:
|
|
"""What one scenario cost, counted rather than timed."""
|
|
|
|
executions: int = 0
|
|
events: int = 0
|
|
by_event: dict[str, int] = field(default_factory=dict)
|
|
#: inject -> when the last node downstream of it finished, in ms.
|
|
latencies: list[float] = field(default_factory=list)
|
|
|
|
def count(self, event: dict[str, Any]) -> None:
|
|
kind = str(event.get("type", ""))
|
|
self.events += 1
|
|
self.by_event[kind] = self.by_event.get(kind, 0) + 1
|
|
|
|
|
|
class CountingBus(EventBus):
|
|
"""The real bus, with a tally beside it.
|
|
|
|
Subclassed rather than mocked: the cost of publishing — the queue per
|
|
subscriber, the drop-oldest — is part of what is being measured.
|
|
"""
|
|
|
|
def __init__(self, counters: Counters) -> None:
|
|
super().__init__()
|
|
self._counters = counters
|
|
|
|
def publish(self, event: dict[str, Any]) -> None:
|
|
self._counters.count(event)
|
|
super().publish(event)
|
|
|
|
|
|
# -----------------------------------------------------------------------------
|
|
# Building graphs
|
|
# -----------------------------------------------------------------------------
|
|
|
|
|
|
def spec(name: str, interval: float = 0.0) -> MessageSpec:
|
|
return MessageSpec(name=name, dtype=DType.FLOAT, interval=interval)
|
|
|
|
|
|
def node(
|
|
node_id: str,
|
|
f: Callable[..., Any],
|
|
requires: list[MessageSpec] | None = None,
|
|
provides: list[MessageSpec] | None = None,
|
|
) -> Node:
|
|
n = Node(f=f, requires=requires or [], provides=provides or [], name=node_id)
|
|
n.assign_flow(FLOW, node_id)
|
|
return n
|
|
|
|
|
|
def relay(
|
|
node_id: str, src: str, dst: str, interval: float, counters: Counters
|
|
) -> Node:
|
|
"""A node that republishes what it read — the shape the house is full of.
|
|
|
|
``src`` and ``dst`` are bare port names: the pipeline qualifies them with
|
|
the flow, and the node function only ever sees ports.
|
|
"""
|
|
|
|
def body(**kwargs: Any) -> dict[str, Any]:
|
|
counters.executions += 1
|
|
return {dst: kwargs[src]}
|
|
|
|
return node(
|
|
node_id,
|
|
body,
|
|
requires=[spec(src)],
|
|
provides=[spec(dst, interval=interval)],
|
|
)
|
|
|
|
|
|
# -----------------------------------------------------------------------------
|
|
# Harness
|
|
# -----------------------------------------------------------------------------
|
|
|
|
|
|
class Engine:
|
|
"""A pipeline and the service that drains its queue, as the app wires them."""
|
|
|
|
def __init__(self, nodes: list[Node], redis_host: str, counters: Counters) -> None:
|
|
self.counters = counters
|
|
self.bus = CountingBus(counters)
|
|
self.state: StateBackend
|
|
self.queue: WorkQueue
|
|
if redis_host:
|
|
# A namespace of its own, so a bench never touches a live engine's
|
|
# state or its stream.
|
|
self.state = RedisState(host=redis_host, namespace="bench")
|
|
self.queue = RedisWorkQueue(host=redis_host, namespace="benchq")
|
|
self.state.clear()
|
|
else:
|
|
self.state = MemoryState()
|
|
self.queue = MemoryWorkQueue()
|
|
self.service = ExecutionService(self.queue, max_workers=4, events=self.bus)
|
|
self.pipeline = Pipeline(
|
|
nodes=nodes,
|
|
state=self.state,
|
|
events=self.bus,
|
|
work_queue=self.queue,
|
|
node_pool=self.service.node_pool,
|
|
)
|
|
self.service.bind(self.pipeline)
|
|
|
|
def start(self) -> None:
|
|
self.service.start()
|
|
|
|
def stop(self) -> None:
|
|
self.service.stop()
|
|
|
|
def deliver(self, source: Node, outputs: dict[str, Any]) -> None:
|
|
"""Inject one value and run every cascade it owes, in this thread.
|
|
|
|
The counting scenarios drive the queue by hand rather than starting
|
|
the consumer: injecting flat out means five hundred messages land
|
|
before the first cascade writes the timestamp its window is measured
|
|
from, so every one of them looks due and the thing being counted never
|
|
happens. A house sends three readings a second into an engine that
|
|
finishes a cascade in four milliseconds, which is this.
|
|
"""
|
|
source.inject(outputs)
|
|
while True:
|
|
self.queue.move_due(0.0)
|
|
items = self.queue.claim(16, 1)
|
|
if not items:
|
|
return
|
|
for item in items:
|
|
self.service._run_item(item)
|
|
self.queue.ack(item)
|
|
|
|
def drain(self, timeout: float = 60.0) -> bool:
|
|
"""Wait for the queue to go quiet. False means it never did.
|
|
|
|
Asks the backlog rather than the whole of ``stats()``: the health
|
|
summary's version costs four round trips, and polling it every twenty
|
|
milliseconds competes with the engine for the connection it is
|
|
supposedly measuring.
|
|
|
|
Delayed items are not waited for: a rate-limit flush is due a whole
|
|
window from now, and the scenario is over long before that.
|
|
"""
|
|
deadline = time.monotonic() + timeout
|
|
quiet_since = 0.0
|
|
while time.monotonic() < deadline:
|
|
busy = self.service.inflight or self.queue.backlog()
|
|
if not busy:
|
|
# Two consecutive quiet reads: a cascade between claim and ack
|
|
# shows as neither.
|
|
if quiet_since and time.monotonic() - quiet_since > 0.15:
|
|
return True
|
|
quiet_since = quiet_since or time.monotonic()
|
|
else:
|
|
quiet_since = 0.0
|
|
time.sleep(0.02)
|
|
return False
|
|
|
|
|
|
def percentile(values: list[float], p: float) -> float:
|
|
if not values:
|
|
return 0.0
|
|
ordered = sorted(values)
|
|
idx = min(len(ordered) - 1, int(round(p / 100.0 * (len(ordered) - 1))))
|
|
return ordered[idx]
|
|
|
|
|
|
# -----------------------------------------------------------------------------
|
|
# Scenarios
|
|
# -----------------------------------------------------------------------------
|
|
|
|
|
|
def scenario_throttle(args: argparse.Namespace) -> dict[str, Any]:
|
|
"""A rate-limited source behind relays, driven far faster than its window.
|
|
|
|
The house's shape: an inverter sending ~200 readings a minute into seven
|
|
relay nodes, each told to publish every 15s. What should cost seven
|
|
publishes a minute is what this counts.
|
|
"""
|
|
counters = Counters()
|
|
source = node(
|
|
"source",
|
|
lambda params: None,
|
|
provides=[spec("raw", interval=args.window)],
|
|
)
|
|
nodes = [source]
|
|
for i in range(args.relays):
|
|
nodes.append(relay(f"relay{i}", "raw", f"out{i}", args.window, counters))
|
|
|
|
engine = Engine(nodes, args.redis, counters)
|
|
try:
|
|
started = time.perf_counter()
|
|
for i in range(args.messages):
|
|
engine.deliver(source, {"raw": float(i)})
|
|
elapsed = time.perf_counter() - started
|
|
finally:
|
|
engine.stop()
|
|
|
|
return {
|
|
"scenario": "throttle",
|
|
"messages": args.messages,
|
|
"relays": args.relays,
|
|
"window_s": args.window,
|
|
"elapsed_s": round(elapsed, 3),
|
|
# The three numbers the bug is about.
|
|
"cascades_started": counters.by_event.get("cascade_started", 0),
|
|
"node_executions": counters.executions,
|
|
"bus_events": counters.events,
|
|
"published": counters.by_event.get("message_value", 0),
|
|
"per_message": {
|
|
"cascades": round(
|
|
counters.by_event.get("cascade_started", 0) / args.messages, 3
|
|
),
|
|
"executions": round(counters.executions / args.messages, 3),
|
|
"events": round(counters.events / args.messages, 3),
|
|
},
|
|
}
|
|
|
|
|
|
def scenario_relay(args: argparse.Namespace) -> dict[str, Any]:
|
|
"""An *unlimited* source into limited relays, and one node reading them all.
|
|
|
|
The other half of the house's shape, and the one holding it at the source
|
|
cannot help with: the readings really do arrive, so a cascade is owed —
|
|
but the relays hold their outputs back, and what reads them has nothing
|
|
new to read. That node published 619 messages a minute off inputs that
|
|
changed six times.
|
|
"""
|
|
counters = Counters()
|
|
source = node("source", lambda params: None, provides=[spec("raw")])
|
|
nodes = [source]
|
|
for i in range(args.relays):
|
|
nodes.append(relay(f"relay{i}", "raw", f"out{i}", args.window, counters))
|
|
|
|
ports = [f"out{i}" for i in range(args.relays)]
|
|
|
|
def watch(**kwargs: Any) -> dict[str, Any]:
|
|
counters.executions += 1
|
|
return {"total": sum(kwargs[p] for p in ports)}
|
|
|
|
nodes.append(
|
|
node(
|
|
"watch",
|
|
watch,
|
|
requires=[spec(p) for p in ports],
|
|
provides=[spec("total")],
|
|
)
|
|
)
|
|
|
|
engine = Engine(nodes, args.redis, counters)
|
|
try:
|
|
started = time.perf_counter()
|
|
for i in range(args.messages):
|
|
engine.deliver(source, {"raw": float(i)})
|
|
elapsed = time.perf_counter() - started
|
|
finally:
|
|
engine.stop()
|
|
|
|
return {
|
|
"scenario": "relay",
|
|
"messages": args.messages,
|
|
"relays": args.relays,
|
|
"window_s": args.window,
|
|
"elapsed_s": round(elapsed, 3),
|
|
"cascades_started": counters.by_event.get("cascade_started", 0),
|
|
"node_executions": counters.executions,
|
|
"bus_events": counters.events,
|
|
"published": counters.by_event.get("message_value", 0),
|
|
"per_message": {
|
|
"executions": round(counters.executions / args.messages, 3),
|
|
"events": round(counters.events / args.messages, 3),
|
|
},
|
|
}
|
|
|
|
|
|
def scenario_throughput(args: argparse.Namespace) -> dict[str, Any]:
|
|
"""A relay chain, driven flat out: messages a second, and how late the tail is."""
|
|
counters = Counters()
|
|
starts: dict[float, float] = {}
|
|
lock = threading.Lock()
|
|
|
|
source = node("source", lambda params: None, provides=[spec("v0")])
|
|
nodes = [source]
|
|
for i in range(args.depth):
|
|
nodes.append(relay(f"relay{i}", f"v{i}", f"v{i + 1}", 0.0, counters))
|
|
|
|
# The last link records how long the value took to walk the whole chain.
|
|
last_port = f"v{args.depth}"
|
|
|
|
def sink(**kwargs: Any) -> None:
|
|
counters.executions += 1
|
|
value = kwargs[last_port]
|
|
with lock:
|
|
sent = starts.get(value)
|
|
if sent is not None:
|
|
counters.latencies.append((time.perf_counter() - sent) * 1000)
|
|
|
|
nodes.append(node("sink", sink, requires=[spec(last_port)]))
|
|
|
|
engine = Engine(nodes, args.redis, counters)
|
|
engine.start()
|
|
try:
|
|
started = time.perf_counter()
|
|
for i in range(args.messages):
|
|
value = float(i)
|
|
with lock:
|
|
starts[value] = time.perf_counter()
|
|
source.inject({"v0": value})
|
|
drained = engine.drain(args.drain_timeout)
|
|
elapsed = time.perf_counter() - started
|
|
finally:
|
|
engine.stop()
|
|
|
|
delivered = len(counters.latencies)
|
|
return {
|
|
"scenario": "throughput",
|
|
"messages": args.messages,
|
|
"depth": args.depth,
|
|
"drained": drained,
|
|
"elapsed_s": round(elapsed, 3),
|
|
"msgs_per_s": round(args.messages / elapsed, 1) if elapsed else 0.0,
|
|
"delivered": delivered,
|
|
"latency_ms": {
|
|
"p50": round(percentile(counters.latencies, 50), 2),
|
|
"p95": round(percentile(counters.latencies, 95), 2),
|
|
"max": round(max(counters.latencies), 2) if counters.latencies else 0.0,
|
|
"mean": round(statistics.fmean(counters.latencies), 2)
|
|
if delivered
|
|
else 0.0,
|
|
},
|
|
"node_executions": counters.executions,
|
|
"bus_events": counters.events,
|
|
}
|
|
|
|
|
|
def scenario_fanout(args: argparse.Namespace) -> dict[str, Any]:
|
|
"""One source into many consumers: what the wave scheduler costs per node."""
|
|
counters = Counters()
|
|
source = node("source", lambda params: None, provides=[spec("raw")])
|
|
nodes = [source]
|
|
for i in range(args.width):
|
|
nodes.append(relay(f"leaf{i}", "raw", f"out{i}", 0.0, counters))
|
|
|
|
engine = Engine(nodes, args.redis, counters)
|
|
engine.start()
|
|
try:
|
|
started = time.perf_counter()
|
|
for i in range(args.messages):
|
|
source.inject({"raw": float(i)})
|
|
drained = engine.drain(args.drain_timeout)
|
|
elapsed = time.perf_counter() - started
|
|
finally:
|
|
engine.stop()
|
|
|
|
return {
|
|
"scenario": "fanout",
|
|
"messages": args.messages,
|
|
"width": args.width,
|
|
"drained": drained,
|
|
"elapsed_s": round(elapsed, 3),
|
|
"msgs_per_s": round(args.messages / elapsed, 1) if elapsed else 0.0,
|
|
"node_executions": counters.executions,
|
|
"bus_events": counters.events,
|
|
}
|
|
|
|
|
|
SCENARIOS: dict[str, Callable[[argparse.Namespace], dict[str, Any]]] = {
|
|
"throttle": scenario_throttle,
|
|
"relay": scenario_relay,
|
|
"throughput": scenario_throughput,
|
|
"fanout": scenario_fanout,
|
|
}
|
|
|
|
|
|
# -----------------------------------------------------------------------------
|
|
# Entry point
|
|
# -----------------------------------------------------------------------------
|
|
|
|
|
|
def report(result: dict[str, Any]) -> None:
|
|
name = result.pop("scenario")
|
|
log.info("\n=== %s ===", name)
|
|
for key, value in result.items():
|
|
if isinstance(value, dict):
|
|
inner = " ".join(f"{k}={v}" for k, v in value.items())
|
|
log.info(" %-18s %s", key, inner)
|
|
else:
|
|
log.info(" %-18s %s", key, value)
|
|
|
|
|
|
def main() -> int:
|
|
parser = argparse.ArgumentParser(description=__doc__)
|
|
parser.add_argument(
|
|
"--scenario",
|
|
choices=[*SCENARIOS, "all"],
|
|
default="all",
|
|
help="Which scenario to run (default: all).",
|
|
)
|
|
parser.add_argument("--messages", type=int, default=500)
|
|
parser.add_argument("--relays", type=int, default=7, help="throttle: relay count")
|
|
parser.add_argument("--window", type=float, default=15.0, help="throttle: interval")
|
|
parser.add_argument("--depth", type=int, default=5, help="throughput: chain length")
|
|
parser.add_argument("--width", type=int, default=20, help="fanout: consumer count")
|
|
parser.add_argument(
|
|
"--redis",
|
|
nargs="?",
|
|
const="localhost",
|
|
default="",
|
|
metavar="HOST",
|
|
help="Run against a real Redis (namespaces bench/benchq) rather than memory.",
|
|
)
|
|
parser.add_argument("--drain-timeout", type=float, default=60.0)
|
|
parser.add_argument("--profile", action="store_true", help="cProfile, top 25.")
|
|
parser.add_argument("--json", action="store_true", help="Machine-readable output.")
|
|
args = parser.parse_args()
|
|
logging.basicConfig(level=logging.INFO, format="%(message)s", stream=sys.stdout)
|
|
|
|
names = list(SCENARIOS) if args.scenario == "all" else [args.scenario]
|
|
|
|
profiler = cProfile.Profile() if args.profile else None
|
|
if profiler:
|
|
profiler.enable()
|
|
|
|
results = [SCENARIOS[name](args) for name in names]
|
|
|
|
if profiler:
|
|
profiler.disable()
|
|
|
|
if args.json:
|
|
log.info(json.dumps(results, indent=2))
|
|
else:
|
|
for result in results:
|
|
report(dict(result))
|
|
|
|
if profiler:
|
|
log.info("\n=== profile (cumulative, top 25) ===")
|
|
pstats.Stats(profiler, stream=sys.stdout).sort_stats("cumulative").print_stats(
|
|
25
|
|
)
|
|
|
|
return 0
|
|
|
|
|
|
if __name__ == "__main__":
|
|
raise SystemExit(main())
|