diff --git a/STRATEGY.md b/STRATEGY.md index 328dc10363..b564f551f0 100644 --- a/STRATEGY.md +++ b/STRATEGY.md @@ -259,6 +259,37 @@ single-session transport, bounded by the untested premise that windowing is not practice. What would reopen it is a transport that cuts the per-crossing cost by roughly two orders of magnitude - the embedded/FFI direction - not any windowing or placement design. +**Updated 2026-08-25 (second), and the reopening condition above has been met - but what it +reopened is the floor, not the verdict.** (The crossings: +`docs/inflight/perf-crossing-cost-ladder.md`; the native engine: +`docs/inflight/perf-streams-under-native-image.md`; the floor decomposition and the in-session +retake: `docs/inflight/perf-streams-engine-floor.md`.) The paragraph above named its own condition +for reopening - a transport cutting the per-crossing cost by roughly two orders of magnitude - and +that condition is now met: GraalWasm crosses in **747ns** and a Numba `@cfunc` in **19.9ns** +against the **135us** fitted here, and the Streams engine has been proven to run as a native-image +binary. Two results followed, pointing opposite ways. **For the wrapper:** most of the measured +engine floor turned out to be an instrument choice rather than Kafka Streams - the state-store +cache was set to zero - and with the cache on and nothing crossing, the wrapper reaches **69,265 +rec/s** at hopping-12 and **169,748 rec/s** at tumbling. **Against it:** retaken with the +reimplementation arm interleaved in the *same* session, the dictionary still wins **4.70x** at +tumbling and **6.64x** at hopping-12. So removing the crossing does not by itself close the gap, +and the 69x/122x above should be read as the crossing's price rather than the residual. (Both +retaken figures are firm: the reimplementation arm's apparent instability was traced to a stalled +consumer fetch path, not to the arm, and the retake ran below the record count where that stall +occurs. The **122x** above is itself an artefact of that stall and understates the gap.) + +**The substantive change is neither number: it is that the floor was mis-specified.** The +reimplementation arm is a stateless, non-durable dictionary - no store, no changelog, no restore, +no rebalance recovery, no exactly-once - which makes it the floor for a product Kafka Streams is +not in the business of being. Measuring against it answers *"can a toy beat an engine at toy +work"*, and it can, at any transport speed; sharpening that number further decides nothing. **The +question that decides this strategy is the crossover: how many of the features a user actually came +for can be added back to that dictionary before hand-rolling becomes the worse choice.** That is +the measurement now under way, one feature at a time, starting with durability. Until it returns, +the not-offered verdict above stands on its own evidence - but the *reason* recorded for it, that a +reimplementation is simply faster, is too strong. It is faster only at the feature level where +nobody needed Kafka Streams in the first place. + So the hard part of Streams-in-another-language is not the streaming; it is that a topology has no portable description. ~~That is an IDL to design~~ - **and the proof of concept showed it is not.** See below. diff --git a/docs/inflight/branch-crossing-cost-ladder.md b/docs/inflight/branch-crossing-cost-ladder.md new file mode 100644 index 0000000000..5605f05de1 --- /dev/null +++ b/docs/inflight/branch-crossing-cost-ladder.md @@ -0,0 +1,50 @@ +# The FFI fast-path spike: the crossing-cost ladder, and the feature-crossover ladder + + + + + +Cut 2026-08-25 from astubbs#334's head (post-windowing-verdict), on the owner's direction, to run +the spike the bet-off named as its reopening condition. +[`perf-embedding-the-engine-over-ffi.md`](perf-embedding-the-engine-over-ffi.md) **owns the +candidate** - the compile-the-function design, its prior-art survey, the owner's +WASM-subset-is-fine direction, and the one-C-ABI-seam refinement; what is here is only what the +BRANCH is for. + +**The question:** what does one host-function crossing cost under each in-process mechanism, and +does any clear the pre-registered bar of **~1.35us marginal** (two orders under the measured 135us +gRPC crossing)? Arms: (a) the gRPC figure as context (measured, astubbs#334), (b) an in-process +queue handoff (the embedded pull seam's shape), (c) a raw C-ABI call (ctypes/FFM into a no-op and +a realistic fold), (d) a Numba `@cfunc` pointer called from the engine side, (e) a GraalPy +polyglot call, (f) a **GraalWasm** UDF - (f) primary per the owner's direction, and a GraalWasm +result alone green-lights a product slice. Method inherits the windowing spike's discipline: +predictions in the tree before runs, an instrument check that can move (a busy-wait injection must +show up), a realistic-fold arm beside every no-op (whether the fast path covers real workloads, +not benchmarks), and the end-to-end ceiling restated against U6's engine floor (free crossings +reach arm D's rate, not arm H's). + +**Named companion gap, owner-corrected 2026-08-25 - Kafka Streams has never run under GraalVM +here.** The embedded `--shared` library covers PC core only; the Streams fast path's end state +needs one of two unproven routes: (1) native-image including Kafka Streams (RocksDB JNI, +reflection over serde config, unknown metadata surface), or (2) **libjvm embedding** - a full JVM +hosted in the client process (JIT retained, no native-image build, heavier footprint). The ladder +measures call mechanics with a minimal harness, so neither route gates the measurement - but a +green ladder without settling this gap is not a green light for Streams-in-process, and the +write-up must say which route it assumes. **Probed 2026-08-25, gap crossed for the in-memory +surface**: route (1) is proven and cheaper - the engine builds into a 78MB native binary that +passes the demo, one traced capture was the whole wall, and libjvm demotes to fallback; +[`perf-streams-under-native-image.md`](perf-streams-under-native-image.md) owns the result and its +durability boundary. + +**The spike carries a second ladder, in the other dimension: the feature-crossover ladder.** The +transport ladder above asks how cheaply a call can cross the boundary. That question is answered, +and the answer did not settle the strategy - so the spike also adds the features a user actually +came for back to the *reimplementation*, one at a time, to find where hand-rolling becomes the +worse choice. Durability is the first rung, measured; exactly-once is the candidate for the +second. [`perf-streams-engine-floor.md`](perf-streams-engine-floor.md) **owns both sets of +numbers** - what is here is only that the spike has two purposes, so a reader arriving at the +transport ladder does not take it for the whole. + + +Delete this note when the branch lands or is superseded; the spike's results note (created on this +branch) will carry the numbers. diff --git a/docs/inflight/core-compiled-function-seam-design.md b/docs/inflight/core-compiled-function-seam-design.md new file mode 100644 index 0000000000..42b55e90c7 --- /dev/null +++ b/docs/inflight/core-compiled-function-seam-design.md @@ -0,0 +1,210 @@ +# The compiled-function seam: one C-ABI contract, and the accumulator stays on the callee's side + + + +Design for the fast path the crossing-cost ladder green-lit; nothing below is built. The ladder +([`perf-crossing-cost-ladder.md`](perf-crossing-cost-ladder.md)) owns the measurements and +[`perf-embedding-the-engine-over-ffi.md`](perf-embedding-the-engine-over-ffi.md) owns the candidate +and the owner's two directions. What is here is the seam those two imply and neither specifies. + +Three measurements bind it, and the second is the one nobody predicted: + +- **A second thread disqualifies a mechanism.** Every arm that cleared the 1.35us bar made the call + on the caller's own thread; the one that did not - `SynchronousQueue round trip`, 10,028 ns fold - + failed by ~7x. The seam is a *call*, never a handoff, and the embedded pull-queue shape cannot be + the fast path however cheap the rest of it gets. +- **Data placement dominates mechanism.** The same GraalPy call costs `1,024` ns with guest-staged + bytes and `121,775` ns crossing a host `byte[]` per call; the same GraalWasm call costs `747` ns + staged and `9,160` ns with a per-call `writeBufferByte` copy. A 100x swing with the mechanism held + constant - so this is an invariant of the design, not a tuning note. +- **The ceiling relocates rather than vanishes.** With crossings free the wrapper reaches arm D's + `20,062 rec/s` engine floor ([`perf-streams-windowing-multiplier.md`](perf-streams-windowing-multiplier.md)), + leaving 4.5x (hopping-12) to 36x (tumbling) to the reimplementation floor - engine cost, which + this design does not touch. + +## The contract + +One entry point per function token, over a shared arena. Every field is an **offset into the +arena**, never a host pointer, so the identical layout is legal in a wasm module's linear memory and +in a native heap block - which is what lets one contract serve both producers instead of two calling +conventions wearing one name. + +```c +#define PC_ABI_V1 1u + +/* Written by the engine into the arena, once per call. ~72 bytes, fixed size. */ +typedef struct { + uint32_t abi_version; /* PC_ABI_V1 */ + uint32_t kind; /* mirrors InvocationKind: MAP/REDUCE/JOIN/AGGREGATE */ + uint32_t present; /* bit per span: PRESENT vs ABSENT (see below) */ + uint32_t key_off, key_len; + uint32_t value_off, value_len; + uint32_t right_off, right_len; /* the table side, for a joiner */ + uint32_t acc_off, acc_len, acc_cap; /* IN/OUT - the callee rewrites acc_len */ + uint32_t out_off, out_cap, out_len; /* OUT - the callee writes out_len */ + uint32_t err_off, err_cap, err_len; /* OUT - UTF-8 detail, becomes InvocationResult.error */ +} pc_call_v1; + +/* The registered symbol / wasm export. Native form takes the arena base; the wasm form drops it, + because the module's exported linear memory IS the arena and offset 0 is its base. */ +int32_t pc_invoke_v1(void *arena, uint32_t call_off); /* wasm: (param i32) (result i32) */ +``` + +- **Return codes**: `0` ok; `1` user error (`err_*` populated, the record fails - the wire's rule + that "a wrong value entering an aggregation is worse than a failed record" is unchanged); `2` + `out_cap` too small, the engine's one legal retry with a larger `out` region; anything negative is + a contract violation and the *registration* is killed, not the record. +- **`present` is a bitmask because absence is meaningful and `len == 0` is not absence.** The wire + already turns on this - `Invocation.aggregate` is "absent rather than empty on the first value for + a key", and `GetResult.found` exists for the same reason. A null offset would collide with a + legitimate arena offset of 0. +- **Flat scalars only, no structs by value, no callee allocation** - producer constraints + discovered rather than chosen: wasm has no aggregate parameter types, and Numba's `nopython` fold + compiled first try precisely because its arguments expressed as `types.CPointer(types.uint8)` + plus lengths. + +### Carried as an additive capability on the existing token registration + +`RegisterFunction` in +[`streams.proto`](../../parallel-consumer-proxy-streams/src/main/proto/parallelconsumer/streams/v1alpha1/streams.proto) +carries only `token` and `description` today. The fast path is one additive `CompiledFunction` field +beside them - artifact kind (`WASM_MODULE` bytes, a `NATIVE_LIBRARY` path the engine `dlopen`s, or a +raw `NATIVE_POINTER`), symbol (default `pc_invoke_v1`), execution mode, requested arena size. Absent, +the token behaves exactly as it does now. + +**The wire path remains the universal fallback, per function, and it is never entered silently.** A +token registering no artifact takes the wire; a token registering one the engine cannot load, or +whose `abi_version` it does not know, has its **registration refused by name** rather than +downgraded behind the host's back - the Go demo's rule, on the grounds that a silent fallback lets +"a run that was meant to exercise the embedded engine prove nothing". `NATIVE_POINTER` is +additionally refused over gRPC by construction: an address from another process names nothing. + +## The data-placement rule, as an invariant + +**The accumulator lives on the function's side of the fence. The engine passes offsets and copies it +zero times per call.** The ladder's headline restated as a rule; a producer that cannot satisfy it +does not qualify. The arena is the accumulator's *home*, not a staging buffer: + +- **WASM module (sandboxed)**: a region of the module's own exported linear memory, grown by + `memory.grow` at registration. A `(key, window)` accumulator holds a slot for the life of that + window. `747` ns is what this costs; `9,160` ns is what copying instead costs. +- **Numba `@cfunc` / native library / raw pointer (trusted)**: an engine-allocated native block + handed to the artifact at registration. Same slots, same offsets, real addresses. +- **What the engine gives up**: it no longer holds the canonical accumulator bytes between calls - + the genuine tension with Kafka Streams, whose window store owns them for the changelog and for + restore. The reconciliation is that the store's value backing *becomes* the arena slot: the engine + reads a slot out only when a changelog write or store flush needs it, once per commit interval + rather than once per record, and rebuilds slots from the changelog on restore. **Restore and + rebalance are where this design is thinnest** (open question 3). + +## Producers of the contract + +| Producer | Mode | Measured, as the ladder ran it | What it costs the host | +|---|---|---|---| +| **GraalWasm module** (primary) | sandboxed, in-engine | `747` ns staged | a to-WASM toolchain | +| **Numba `@cfunc`** | trusted | `19.9` ns, called from a C driver | `nopython` subset; nothing to install beyond numba | +| **Raw native pointer / `dlopen`** (Rust, Mojo, C) | trusted | `1.3` ns no-op, `392` ns fold via a C function pointer | nothing - the function already *is* the contract | +| **wasm2c / AOT lowering** | trusted, from a sandboxed artifact | **not measured** - no C-to-wasm toolchain on the box | one build step; portable authoring at native speed | + +**Sandboxing is a per-registration policy, not an architecture fork.** The same wasm artifact runs +in-engine when isolation matters and lowered-to-native when the last microsecond does; the host +picks per token, and can `dlopen` and unit-test the exact native artifact the engine will call +before registering it. Rust, not C, is the zero-friction wasm producer here - the ladder's artifact +is `fold_wasm.rs`, because no C-to-wasm toolchain was reachable. + +## What this deliberately does not solve + +- **The engine's own floor.** Free crossings reach `20,062 rec/s`, not the reimplementation's + 89k-723k. The residual 4.5x-36x is engine cost, closed against a different floor - + parity-plus-durability, per `STRATEGY.md`'s reopening condition. +- **Kafka Streams under GraalVM.** The ladder's JVM-hosted arms model route (2), libjvm embedding; + route (1), native-image including Streams, is unmeasured and a sibling probe is running - + [`branch-crossing-cost-ladder.md`](branch-crossing-cost-ladder.md) owns that gap. **This design is + route-agnostic and can afford to be**: the C-ABI arms are route-independent. The *sandboxed* mode + is not - GraalWasm's `747` ns is a libjvm-embedding number, so a route-(1) answer moves the + primary producer's cost and nothing else here. +- **Crash isolation in trusted mode.** A segfaulting compiled function takes the topology process + with it; the sidecar dies loudly instead. [`parked-a-c-client-and-the-ffi-question.md`](parked-a-c-client-and-the-ffi-question.md) + names it as an inherited hazard, and the sandboxed mode is the only answer this design has. +- **Versioning and ops for shipped artifacts.** Who builds the `.wasm`, where it lives, how a + running engine learns a token's artifact changed, what an `abi_version` bump does, and how any of + it meets the release-matrix objection - all unaddressed. + +## Open questions + +1. **Does the lowered-wasm path reach native speed?** No `wasm2c` or Wasmtime-AOT artifact has been + measured through this contract, and the whole "same artifact, two execution modes" claim rests on + it. Owner: the ladder's missing arm, which needs a C-to-wasm toolchain the box did not have. +2. **Does the fast path re-impose the constraint the binding design boasts of avoiding?** + [`docs/language-bindings.md`](../language-bindings.md)'s function-delivery axis records ours as + "Token and local lookup", with "**no serializability constraint whatsoever**". A compiled + artifact is not serializability but is its sibling - user code must be *compilable to the + contract*. That axis needs a third row; the doc owns it. +3. **Arena lifetime across rebalance, restore and window expiry.** Who zeroes a slot, who grows the + arena when occupancy does, and what a restore costs when every slot must be rebuilt from the + changelog before the first record is processed. +4. **Polyglot/JDK version lockstep as a shipping hazard.** The ladder's wasm arm silently fell to + the Truffle interpreter, 145x slower, on a version mismatch that warns only on stderr. Shipping + the sandboxed mode means shipping a startup assertion that runtime compilation is on. +5. **Which slice ships first.** The one-C-ABI-seam refinement re-admits Python at full speed through + Numba, while the coverage direction scopes the first slice to to-WASM-mature bindings. They do + not disagree about the architecture, only about who gets it first. **Owner's call, 2026-08-25: + spike BOTH in parallel to spike depth - one function shape end to end per path, measured - then + reassess together before anything is fleshed out.** The two spikes also test the fork's hidden + asymmetry: a WASM artifact is bytes that ship over the wire to today's sidecar unchanged, while + a Numba pointer is meaningful only in-process and therefore forces the embedded (`--shared`) + engine shape. Branches `spike/242-fastpath-wasm` and `spike/242-fastpath-numba`, each with its + own branch note. + +## Reassessment, 2026-08-25: both spikes ran, and the fork partially inverted + +Owner's gate, exercised. Both paths proved end to end with sabotage checks (each spike's note +lives on its branch: `spike/242-fastpath-wasm` and `spike/242-fastpath-numba`, +`docs/inflight/perf-spike-fastpath-wasm.md` / `perf-spike-fastpath-numba.md`). + + +- **Path A held its shape**: a 966-byte wasm artifact over today's wire into today's sidecar, + 1.9x end to end, 94.9 percent of the wire-to-control gap closed, artifact identity checked at + registration, Temurin refusal instead of silent interpretation. Deployment verdict: topology + unchanged, sidecar artifact ~50MB fatter with a GraalVM pin. +- **Path B inverted the premise**: embedding deleted gRPC's ~165us/record reliably, and the + compiled pointer added ~27us-at-the-median on top - not separable from noise. Its raw-address + registration is a hole in a protocol, not a capability, and does not ship in that shape. Its + accidental discovery outranks its thesis: **the embedded streams engine itself** - the whole + engine as a --shared native library inside the Python process, built first try on the traced + metadata - is a product capability independent of compiled functions. +- **Convergent finding, both spikes independently: the engine floor is the next question.** + ~250us/record (embedded, B) and ~132us control (A's box) with NOTHING crossing. The crossing is + solved; what stands between the wrapper and the reimplementation floor is Kafka Streams' own + per-record cost. +- **Convergent test hole, both spikes independently: the streams demo's assertions are + value-blind** - a wrong-valued transform passes the count checks on every path. Spike A's + --verify-mapped sink is the fix and should be adopted regardless of the fork. +- **Disposition**: Path A is the ship-shape candidate; Path B rescopes to the embedded engine with + the pointer mechanism parked until artifacts carry identity; nothing is fleshed out until the + engine floor is understood (spike dispatched, results in + [`perf-streams-engine-floor.md`](perf-streams-engine-floor.md) once it lands, created by that + spike). + + +## Owner direction, 2026-08-25 (second): open question 5 resolved, spike/PoC scope + +**WASM for the artifact-producing bindings; Numba interception as Python's special case; one seam +under both.** The rationale, recorded so it is not re-derived: for compiled languages the artifact +is a byproduct of their normal build - author once, ship bytes, sandboxed, identity-checked - while +Python is the one binding that cannot cheaply produce an artifact but uniquely carries a runtime +JIT that compiles the user's ACTUAL function in place. Python's user base is large enough - and +central enough to agentic programming - that a special case earns its keep. + +**The correctness net for the dual lanes is the cross-binding conformance harness** +([`test-cross-binding-streams-conformance.md`](test-cross-binding-streams-conformance.md) owns it): +known topologies replayed against each engine and each lane (wire, Numba, wasm), asserted to match +the `TopologyTestDriver` oracle recorded from plain Apache Kafka Streams - which is exactly the +check that makes the transform-written-twice divergence hazard visible instead of silent. The +harness was already earmarked a product feature; this decision makes it load-bearing for the fast +path too. + +Coupling stated plainly: Numba pointers are in-process only, so Python's fast lane arrives with +the embedded-engine decision (or, later, a mature Python-to-WASM toolchain compiling the same +intercepted function to bytes). Scope of all of this: **the spike PoC** - fleshing out remains +gated on the engine-floor result. diff --git a/docs/inflight/perf-crossing-cost-ladder.md b/docs/inflight/perf-crossing-cost-ladder.md new file mode 100644 index 0000000000..dd9e48ae1a --- /dev/null +++ b/docs/inflight/perf-crossing-cost-ladder.md @@ -0,0 +1,208 @@ +# The crossing-cost ladder: what one host-function crossing costs, mechanism by mechanism + + + +The pre-registration and results record for the crossing-cost ladder spike +([`branch-crossing-cost-ladder.md`](branch-crossing-cost-ladder.md) owns the branch's purpose; +[`perf-embedding-the-engine-over-ffi.md`](perf-embedding-the-engine-over-ffi.md) owns the +candidate this serves). **Everything above the Results line was written and committed before any +arm ran** - the windowing spike's discipline +([`perf-streams-windowing-multiplier.md`](perf-streams-windowing-multiplier.md)) inherited whole: +predictions in the tree before runs, an instrument check that can move, a realistic fold beside +every no-op, and the ceiling restated against U6's engine floor. + +## The question and the bar + +What does ONE host-function crossing cost, marginally, under each in-process mechanism - and does +any clear the pre-registered bar of **~1.35us marginal** (two orders under the measured 135us gRPC +per-crossing cost from U6's fitted line, `t(m) = 33us + m x 135us`)? + +**The fold** (the realistic arm beside every no-op): a windowed-aggregation-shaped operation - +take (key bytes ~16B, value bytes ~1KB, accumulator bytes ~1KB), fold the value into the +accumulator element-wise, return a result byte. This is the shape the windowing verdict was lost +on: compute-light, called once per (record x window), the accumulator serially dependent on +itself. A bounded element-wise fold rather than an unbounded append, so the per-call work is +constant across a batch. + +## The ceiling, restated before any number lands (binding) + +**Free crossings reach U6's arm D (~20,000 rec/s on that box), NOT arm H's rate.** Arm D is the +same engine with zero crossings - the engine's own floor. Arm H (the in-process single-threaded +reimplementation) measured 89k rec/s (hopping-12) to 723k rec/s (tumbling). So even a mechanism +that makes the crossing *free* leaves the wrapper at ~20k rec/s against H's 89k-723k: the ladder +can close the crossing term from ~100x to single digits, and no further. A green ladder relocates +the verdict question to parity-plus-durability against a published rate bound; it does not win +the F2 comparison by itself. + +## The route assumption (the named companion gap) + +Kafka Streams has never run under GraalVM here; the embedded `--shared` library covers PC core +only. This ladder measures **call mechanics with a minimal harness** - the JVM-hosted arms (b, e, +f) run on an ordinary JIT JVM, so the end state they most directly model is **route (2), libjvm +embedding**: a full JVM hosted in the client process, JIT retained, no native-image build, +heavier footprint. Route (1), native-image including Kafka Streams (RocksDB JNI, reflective serde +config, unknown metadata surface), is NOT what these numbers were taken on - Truffle-under- +native-image warmup and peak behaviour can differ, and that gap is not settled by this spike. +Arms (c) and (d) measure the raw C-ABI seam itself and are route-independent. + +## Environment facts recorded before running + +32-core Linux box (`6.14.11-4-pve`), ambient load ~4-6 from other agent sessions (1-minute load +recorded beside every arm's run). Toolchains found: gcc 14-era system cc (no clang, no wat2wasm, +no wasm-ld); Python 3.13.5 with venv (pypi reachable - numba installable); Temurin 17.0.20+8 and +GraalVM CE 25.0.2 via mise; maven central reachable (GraalWasm/GraalPy polyglot deps +downloadable); rustc 1.97.1 with only the native target installed (`rustup target add +wasm32-unknown-unknown` is the reachable to-WASM toolchain; C-to-wasm is NOT reachable on this +box - no clang/wasm-ld/emcc). The fold-to-wasm artifact will therefore be **Rust-compiled, not +C-compiled**, and a hand-assembled binary no-op module covers the no-op arm if the target +install fails. + +## Method (binding) + +- **Marginal cost per call**: warmup discarded (counts reported per arm; Truffle/JIT arms get + large warmups), then many batches of N calls; ns/call = batch elapsed / N; report **median and + p99 over >= 30 batches**, never a single number. +- **Instrument check per arm**: a variant of the fold with a calibrated ~1us busy-wait inside; + every arm's fold figure must move by roughly +1us. An arm whose number does not move is not + measuring the call and its row is void. +- **Machine load** (`uptime` 1-minute figure) recorded beside each arm's run. +- **Sabotage/controls**: the busy-wait injection IS the sabotage arm (a number that cannot move + is dead); arm (c) additionally runs the C-driver-side loop as its own control (the same fold + called with no Python in the loop), separating Python-side marshalling from the callee. +- Arm (a), gRPC, is **not re-measured**: 135us per crossing is the fitted per-crossing cost from + U6 (astubbs#334's branch, `perf-streams-windowing-multiplier.md`), cited as context. + +## Pre-registered predictions (written before any run; honest guesses with reasoning) + +| Arm | Mechanism | Predicted no-op ns/call (median) | Predicted fold ns/call | Predicted verdict vs 1.35us bar | +|---|---|---|---|---| +| (a) | gRPC crossing (context, measured) | 135,000 marginal | - | fails, by two orders (that is the point) | +| (b) | Java SynchronousQueue round trip, 2 threads | ~4,000 (p99 ~40,000) | ~4,300 | **fails** - two scheduler wakeups per round trip, ~1-3us each on a loaded box; this is the embedded pull seam's floor | +| (c) | Python ctypes -> C | ~800 | ~950 | **passes, narrowly** - ctypes per-call marshalling is ~0.5-1us with argtypes set; three pointer args push toward 1us | +| (c') | C driver -> function pointer (engine-side proxy) | ~2 | ~100 | **passes trivially** - an indirect call is nanoseconds; the 1KB fold is ~1 cycle/byte at -O2 | +| (d) | Numba @cfunc pointer called from C driver | ~3 | ~150 | **passes trivially** - LLVM-compiled native code behind a raw pointer; slightly worse codegen than gcc on the loop. Subset risk: byte-pointer args must be expressible as `types.CPointer(types.uint8)`; predicted to compile | +| (e) | GraalPy polyglot call (JIT JVM host) | ~300 | ~3,000 | **no-op passes, fold fails** - Truffle inlines the call after warmup, but per-element interop access to host byte arrays is the killer unless bytes are staged guest-side | +| (f) | GraalWasm call (JIT JVM host), bytes staged in wasm memory | ~300 | ~700 | **passes** - post-warmup `Value.execute` of an export is sub-microsecond; fold reads/writes wasm linear memory directly so no per-element interop | +| (f2) | GraalWasm, 1KB copied into wasm memory per call via the polyglot buffer API | - | ~5,000 | **fails** - per-byte `writeBufferByte` is ~1k API calls; recorded to bound what "realistic data handoff" costs if staging is impossible | + +Reasoning summary: the ladder should split cleanly into *pointer-call* mechanisms (c', d - single +nanoseconds, the "crossing disappears" class), *managed-boundary* mechanisms (c, e, f - hundreds +of nanoseconds, pass the bar with care about data placement), and *thread-handoff* mechanisms (b +- microseconds, fails the bar because the cost is the scheduler, not the call). If (b) fails as +predicted, the embedded pull seam alone does NOT clear the bar and the compile-the-function +candidate is the only route that does - which is exactly the claim the candidate note makes and +this spike exists to test. + +**Warmup plan**: (b) 50k round trips discarded; (c/c'/d) 100k calls; (e/f) 200k calls (Truffle +compilation thresholds are in the tens of thousands). + +--- + +## Results + +Appended as the arms run, each beside its prediction, confirmed or refuted. Nothing above this +line changes after the first run; corrections land as dated entries here. + +### The ladder, measured 2026-08-25 + +Harness: `ffi/crossing-ladder/` (`fold.c` + `libfold.so` for c/c'/d, `QueueHandoffBench.java` +for b, `bench_ctypes.py` for c/c', `bench_numba.py` for d, `fold_wasm.rs` -> `fold.wasm` + +`GraalWasmBench.java` for f, `GraalPyBench.java` for e, `graal/pom.xml` for the polyglot deps). +Exact versions: gcc 14.2.0 (`-O2`), Python 3.13.5, numba 0.67.0 / llvmlite 0.49.0, rustc 1.97.1 +(`wasm32-unknown-unknown`, `-C opt-level=3`), Temurin 17.0.20+8 (arm b), GraalVM CE 25.0.2 (Java +25) with **polyglot 25.0.2** for arms e/f. The box's ambient `JAVA_TOOL_OPTIONS` +(`ActiveProcessorCount=8`, `MaxRAM 48g` at 20%) applied to every JVM arm. 1-minute load at each +arm's run is in its row. All figures are medians over the stated batches; p99s were within ~1.2x +of the median on every passing arm (worst: arm b's p99 1.27x median). + +| Arm | Mechanism | no-op ns/call (median / p99) | fold ns/call (median / p99) | warmup | load | verdict vs 1.35us | +|---|---|---|---|---|---|---| +| (a) | gRPC crossing (cited, U6 fitted) | 135,000 marginal | - | - | - | **fails** (context) | +| (b) | SynchronousQueue round trip, Temurin 17 | 9,351 / 11,871 | 10,028 / 12,334 | 50k round trips | 5.8 | **fails, ~7x over** | +| (c) | Python ctypes -> C | 696 / 830 | 1,115 / 1,499 | 100k | 4.6 | **passes** (fold under the bar; p99 straddles it) | +| (c') | C driver -> function pointer | 1.3 / 1.3 | 392 / 445 | 100k | 4.6 | **passes, ~1000x under** | +| (d) | Numba @cfunc pointer from C driver | 2.0 / 2.3 | 19.9 / 20.1 | 100k | 4.0 | **passes, ~68x under** | +| (e) | GraalPy polyglot (JIT JVM host) | 201 / 257 | guest-staged bytearray 1,024 / 1,074; host byte[] **121,775** / 123,665 | 100k (no-op), 20k (fold) | 2.1 | **splits**: no-op and guest-staged pass; per-element host interop fails ~90x | +| (f) | GraalWasm polyglot (JIT JVM host) | 105 / 113 | staged in wasm memory 747 / 792 | 200k | 2.0 | **passes** | +| (f2) | GraalWasm, 1KB copied per call via `writeBufferByte` | - | 9,160 / 9,619 | 50k | 2.0 | **fails** - the per-byte buffer API copy alone costs 8,414 ns | + +30-50 batches x 5,000-20,000 calls per arm (printed by each harness). + +**Instrument-check deltas (a ~1us clock- or count-calibrated busy-wait injected into the fold; +an arm that does not move is not measuring the call):** + +| Arm | Injected | Measured delta | Reads as | +|---|---|---|---| +| (b) | 1,000 ns (nanoTime spin) | +1,668 ns | moved; excess is scheduler jitter on a loaded box | +| (c) | 1,000 ns (clock spin in C) | +1,086 ns | moved | +| (c') | 1,000 ns (same) | +1,074 ns | moved | +| (d) | count-calibrated 1,278 ns | +1,287 ns | moved, matches calibration within 1% | +| (e) | count-calibrated 10,463 ns | +10,189 ns | moved, matches within 3% - deliberately injected ~10us, because 1us is under this arm's noise floor (fold base 122us, batch spread ~2us) | +| (f) | count-calibrated 1,160 ns | +1,182 ns | moved | + +Two instrument incidents worth keeping: numba's first spin (a side-effect-free counting loop +guarded by an impossible branch) was **dead-code-eliminated by LLVM - the arm's number did not +move at all**, exactly the failure the check exists to catch; replaced with a serial +data-dependent chain written to observable memory, which all count-calibrated arms now use. And +the first GraalWasm run silently fell back to **Truffle interpreter mode** (polyglot 25.2.4 on +the 25.0.2 JVMCI fails its version check and drops runtime compilation): staged fold read 108,431 +ns - 145x the compiled figure. The warning is printed but easy to grep away; a harness that +did not read stderr would have recorded the wasm arm as failing the bar when it passes by 2x. +Pinning polyglot to the JDK's own version fixed it. + +### Predictions against measurements + +| Arm | Predicted (no-op / fold) | Measured | Reading | +|---|---|---|---| +| (b) | 4,000 / 4,300, fails | 9,351 / 10,028 | **verdict confirmed, magnitude refuted** - 2.3x worse than guessed; two scheduler wakeups per round trip cost more under ambient load | +| (c) | 800 / 950, passes narrowly | 696 / 1,115 | **confirmed** - fold 17% over guess, still under the bar | +| (c') | 2 / 100, passes | 1.3 / 392 | **verdict confirmed; fold 4x the guess** - gcc does not vectorise the aliasing `char*` loop | +| (d) | 3 / 150, passes | 2.0 / 19.9 | **confirmed, better than guessed** - LLVM vectorises the fold (7x under the guess); the numba subset cliff did NOT bite: byte-pointer args expressed cleanly as `types.CPointer(types.uint8)`, nopython compiled first try | +| (e) | 300 / 3,000, no-op passes fold fails | 201 / 121,775 (host bytes) | **direction confirmed, magnitude refuted by 40x** - per-element interop on host arrays is catastrophic, not merely slow. Unpredicted third variant: guest-staged bytearray passes at 1,024 | +| (f) | 300 / 700, passes | 105 / 747 | **confirmed** - the closest prediction on the board | +| (f2) | ~5,000, fails | 9,160 | **direction confirmed, ~2x worse** | + +The pre-registered three-class split (pointer-call / managed-boundary / thread-handoff) survived +contact: c', d in single-to-tens of ns; c, e, f in hundreds; b in thousands. What the +predictions missed, both times in the same direction: **data placement dominates the mechanism** +- the same GraalPy call is 1,024 ns with guest-staged bytes and 121,775 ns with host bytes; the +same GraalWasm call is 747 ns staged and 9,160 ns with a per-call buffer-API copy. The call is +cheap; moving 1KB across a polyglot boundary per call is not, unless the bytes already live on +the callee's side. + +### The ceiling, restated with the measured numbers (binding restatement from above) + +Free-ish crossings reach **U6's arm D: ~20,000 rec/s** on that box (50us/rec engine floor), not +arm H's 89k-723k. Substituting the ladder's winners into U6's fitted line `t(m) = 33us + m x +135us`: a GraalWasm crossing at ~0.75us gives hopping-12 ~16,500 rec/s (vs the measured 603) and +tumbling ~19,600 rec/s - a ~27x improvement that lands almost exactly ON the engine floor, +i.e. the crossing term becomes noise. The remaining gap to the reimplementation floor is then +the engine itself: ~4.5x (hopping-12) to ~36x (tumbling) - and that gap is what +parity-plus-durability has to argue against, not the crossing. + +### Blockers and subset cliffs, named + +- **Numba subset cliff: not hit.** The windowed-fold shape (byte pointers + lengths -> byte) + compiled under `nopython` first try. The cliff presumably waits for richer folds (allocation, + objects); this shape - the one the windowing verdict was lost on - is inside the subset. +- **C-to-wasm toolchain: absent on this box** (no clang/wasm-ld/emcc/wat2wasm). The fold arm of + (f) is **Rust-compiled** (`rustup target add wasm32-unknown-unknown`, one 20s download) rather + than C-compiled; no hand-written .wat fallback was needed. Consequence for the candidate: the + "one C-ABI seam, WASM as producer" refinement should not assume C is the reference producer - + Rust was the zero-friction one here. +- **Polyglot/JDK version lockstep** (the interpreter-fallback incident above): the maven + polyglot version must match the GraalVM JDK's compiler version or Truffle silently drops to + interpreter (~145x on the wasm fold). It warns on stderr and keeps running. +- **GraalPy host-array interop**: not a blocker, a measured hazard - any design that hands the + engine's `byte[]` to a GraalPy UDF per element pays ~119us/KB. Bytes must be staged + guest-side (or handed as a buffer the guest reads natively) before GraalPy's fold is usable. +- **GraalPy cost not measured under native-image** - the route assumption above stands: these + are libjvm-embedding numbers. + +### Summary line + +**Arms (c), (c'), (d) and (f) clear the 1.35us bar - (f) GraalWasm, the owner's primary, clears +it at 747ns staged - while (b), the embedded pull-queue seam alone, fails it by ~7x; with a +sub-microsecond crossing the end-to-end ceiling relocates to U6's ~20k rec/s engine floor +(crossing cost becomes noise), leaving a ~4.5x (hopping) to ~36x (tumbling) gap to the +reimplementation floor that the crossing can no longer explain.** diff --git a/docs/inflight/perf-streams-engine-floor.md b/docs/inflight/perf-streams-engine-floor.md new file mode 100644 index 0000000000..6a7962e3ed --- /dev/null +++ b/docs/inflight/perf-streams-engine-floor.md @@ -0,0 +1,1224 @@ +# The engine floor: where the microseconds go when NOTHING crosses the boundary + + + +The pre-registration and results record for the engine-floor spike. **Everything above the Results +line was written and committed before any arm ran** - the discipline inherited whole from +[`perf-streams-windowing-multiplier.md`](perf-streams-windowing-multiplier.md) (U6) and +[`perf-crossing-cost-ladder.md`](perf-crossing-cost-ladder.md): predictions in the tree before runs, +one term toggled per arm, an instrument check that can move, the broker's log-append clock, and the +record basis proven per run rather than assumed. + +## The question + +Two spikes converged on the same next question +([`core-compiled-function-seam-design.md`](core-compiled-function-seam-design.md), "Reassessment, +2026-08-25"): with the crossing removed, Kafka Streams still costs **~50us/record** (U6 arm D, this +class of box), **~132us/record** (spike A's control) and **~250us/record** (spike B, embedded), and +the reimplementation floor is **89k-723k rec/s** (arm H). The crossing is solved; this floor is the +whole remaining 4.5x-36x term. **Is it Kafka-Streams-intrinsic, or is it configuration and harness?** + +Three candidate explanations are on the table before any arm runs, and the first is the reason this +spike exists at all: + +1. **U6 ran the cache OFF** (`statestore.cache.max.bytes=0`, stated in U6's conditions and chosen + there so emit counts would be exact). Cache off makes **every** put forward downstream, so arm D + produced 12 changelog writes and 12 sink records per input record. That is a measurement choice, + not a property of Kafka Streams. +2. **U6 ran `commit.interval.ms=200`** - 25x under the Kafka Streams default of 5,000ms - which + forces a producer flush and an offset commit five times a second per thread. +3. **Arm D is a hopping-1h/5m topology, multiplier 12.** Its 50us/record is *twelve* window updates, + so the per-(record x window) figure is ~4.2us and the per-record floor at multiplier 1 is a + different number nobody has measured crossing-free. + +## The unit that matters, stated before the numbers + +**us per RECORD is the floors' unit** (U6's R6), but the budget below is built in **us per +(record x window)** wherever a term scales with the multiplier, because arm D's headline conflates +the two. A term that is once-per-record (poll, fetch, deserialise, source-offset bookkeeping) and a +term that is once-per-window-update (store put, changelog write, downstream forward, sink produce) +are different products, and the 4.5x-36x gap is only interpretable once they are separated. + +## Pre-registered budget: where I think the 50us/record goes + +Honest guesses, written before any arm ran, for U6 arm D's shape (hopping 1h/5m, multiplier 12, +cache off, `commit.interval.ms=200`, 8 threads, 8 partitions, 1 KB values, in-memory window store, +sink through `to_stream`). + +| Term | Scales with | Predicted us/record (of ~50) | Reasoning | +|---|---|---|---| +| Sink produce | multiplier | **~16** (1.3 per update) | 12 x 1 KB records/record produced, serialised, batched, acked | +| Changelog produce | multiplier | **~16** (1.3 per update) | same volume again - the changelog is a second full copy of every forward | +| Window store put + forward | multiplier | **~10** (0.8 per update) | in-memory store, byte[] serde, `KTableSuppress`-free forward down the processor chain | +| Consumer poll / fetch / deserialise | record | **~4** | one 1 KB record decoded, `StreamTask` bookkeeping, punctuation checks | +| Commit (offsets + producer flush) | wall clock | **~3** | 5/s/thread x 8 threads, each flushing a partly-full producer batch | +| Cache | - | **0 as run** | it is OFF; the prediction is that turning it ON removes a large slice of the two produce terms | +| Demo/harness artefacts | - | **~1** | the verifier consuming 1.5M sink records on the same box | + +**The load-bearing structural prediction: roughly two thirds of arm D's 50us is produce volume that +the cache-off choice manufactured, and roughly 42 of the 50us scales with the multiplier rather than +with the record.** + +## Pre-registered predictions + +| # | Prediction | Predicted effect | Why | +|---|---|---|---| +| 1 | Baseline replica of U6 arm D reproduces its rate on this box within a factor of ~1.5 | 13k-30k rec/s | same box class, same lab, ambient load differs | +| 2 | **Cache generous (64 MB) vs 0 is the single biggest toggle** | **>= 2x rate** | it collapses 12 forwards/record into ~one per (key,window) per flush, deleting most of BOTH produce terms | +| 3 | Changelog disabled vs enabled | **~25-30% faster** (12-16us/rec) | removes one of the two full-volume produce paths | +| 4 | `commit.interval.ms` 5,000 vs 200 | **~5-12% faster** | fewer flushes, fuller producer batches; real but second-order | +| 5 | No-sink vs sink | **~25-35% faster** (12-18us/rec) | removes the other full-volume produce path | +| 6 | `num.stream.threads` 1 vs 8 | per-thread rate within ~1.3x of 1/8th of the 8-thread rate | the engine floor is per-thread work, not a shared serialised resource - the crossing was the serialised thing, and it is gone | +| 7 | **Crossing-free TUMBLING (multiplier 1) is 5-15us/record, i.e. 65k-200k rec/s** | ~8-10x the hopping-12 rate, not 12x | most of arm D's cost scales with the multiplier; U6 arm A's 137us/rec minus its ~135us crossing leaves single-digit us for the engine at multiplier 1 | +| 8 | Instrument check: +100us/record injected through the wire path moves the per-record figure by 80-130us | delta ~= injected | anything else means the harness is not measuring what it claims | + +**Prediction 7 is the one that would change the strategic reading**, and it is registered here +precisely because it is the uncomfortable one: if it holds, U6's "50us engine floor" is mostly the +*window multiplier*, not Kafka Streams' per-record economics, and the 4.5x-36x gap is +specification-dependent rather than intrinsic. + +## Arms (each toggles exactly ONE term against the baseline) + +All arms are **crossing-free**: `combine=LAST_BYTES` engine-side, **no host function registered at +all**, so the zero crossings are a measurement (an engine-side invocation would name an unregistered +token and fail the run) rather than an assumption - U6's rule, inherited. + +| Arm | Toggle against baseline | Baseline value | +|---|---|---| +| **D0** baseline | none - U6 arm D's shape | hop 1h/5m, cache 0, commit 200ms, sink on, changelog on, 8 threads | +| **D-cache** | `statestore.cache.max.bytes` 0 -> 64 MB | | +| **D-nolog** | changelog on -> off (`withLoggingDisabled`, env-gated) | | +| **D-commit** | `commit.interval.ms` 200 -> 5,000 | | +| **D-nosink** | sink on -> off (no `sink()` call; the store is the terminus) | | +| **D-t1** | `num.stream.threads` 8 -> 1 | | +| **T0** tumbling | window hop 1h/5m -> tumbling 1h (multiplier 12 -> 1) | | +| **I0 / I100** instrument check | host function on the wire path, delay 0 vs 0.1ms | tumbling, so the delta is per-record not per-window | + +**Clocks.** Sink-bearing arms use the sink topic's **broker log-append clock** and quiescence, as +U6 did. `D-nosink` has no sink, so it and a matched sink-bearing companion are BOTH measured on a +second clock - the engine group's **committed source offsets**, sampled to completion - so the +no-sink comparison is never made across two different clocks. Every sink-bearing arm reports both +clocks, which is what makes the second one believable. + +**Method, inherited and binding.** 5,000+ records per arm (the runs below use far more), 3 reps, +arms interleaved within a rep so machine drift lands on all of them, 1-minute load recorded beside +every run, the engine's committed source offsets required to cover the whole seeded backlog before +a rate is believed, and a quiescence break confirmed against advancing sink end offsets before it is +trusted. Rates are reported as median and range over reps, never a single number. + +**The env-gated changelog toggle is measurement-only.** `PC_STREAMS_MEASURE_DISABLE_CHANGELOG` in +`TopologyAssembler` (`windowedAggregate`) is off by default and is not on the protocol; a real +capability would be an additive field on `Aggregate`, which this spike deliberately does not add. + +--- + +## Results + +Appended as the arms run, each beside the prediction it confirms or refutes. Nothing above this line +changes after the first run; corrections land here as dated entries. + +### The decomposition, measured 2026-08-25 + +Harness: `streams_windowing_lab.py`, experiment `engine-floor` (arms `D0`, `D-cache`, `D-nolog`, +`D-commit`, `D-nosink`, `D-t1`, `T0`, `T0-cache`; instrument pair `I0`/`I100`/`I1000`). Engine on +Temurin 17.0.20+8 under the box's ambient `JAVA_TOOL_OPTIONS` (`MaxRAM=48g`, `MaxRAMPercentage=20`, +`ActiveProcessorCount=8`), compose broker `confluentinc/cp-kafka:7.9.0` on loopback +(`127.0.0.1:19097`), Python 3.13.5, 32-core Linux box, 1 KB payloads, 8 partitions, in-memory window +store, constant event time past the epoch clamp. Every arm crossing-free unless its row says +otherwise, with the zero crossings measured client-side rather than assumed. + +**Deviations from the pre-registration, named rather than glossed:** + +- **1,000 keys, not U6's 8,000.** At 8,000 keys the hopping working set is 8,000 x 12 x ~1 KB = ~96 MB + and a 64 MB cache would have measured eviction thrash rather than caching - the cache arm would + have answered a different question. Every arm shares the key count, so the comparisons hold. +- **64,000 records per arm, flat, no sweep.** The arms are crossing-free, so there is no invocation + count to normalise on; the term under test is the record. +- **Quiet-machine gate raised to 1-minute load 40** - the box carried ambient 1-20 from other agent + sessions throughout. Per-run load is recorded beside every run (0.96-30.29). Arms are interleaved + within each rep, so drift lands on all of them; absolute rates are biased low. +- **3 reps for the pre-registered arms; 2 for `T0-cache` and `I1000`**, both added after the first + sweep in response to what it showed (stated below, with why). +- **`D-commit`'s committed-offset clock is void by construction** at a 5,000 ms commit interval - its + first sample already sees the whole backlog and it reads 630k rec/s. Its sink clock is the figure, + as the pre-registration required. + +#### Per-arm table + +Medians over reps, min-max beside; rates in RECORDS per second on the sink's broker log-append clock +except `D-nosink`, which has no sink and is read on the committed-source-offset clock **against +`D0`'s figure on that same clock** (16,739 rec/s, 59.8 us/rec - within 0.2 percent of `D0`'s sink +clock, which is what makes the second clock believable). + +| Arm | One term moved | rec/s (min-max) | us/rec | us per (rec x window) | emits | vs D0 | +|---|---|---|---|---|---|---| +| **D0** | - (U6 arm D's shape) | 16,758 (15,960-17,544) | **59.7** | 5.0 | 768,000 | 1.00x | +| **D-cache** | cache 0 -> 64 MB | 67,797 (54,514-67,941) | **14.8** | 1.2 | 45,432 | **4.05x** | +| **D-nolog** | changelog on -> off | 20,215 (17,582-20,460) | 49.5 | 4.1 | 768,000 | 1.21x | +| **D-commit** | commit 200 -> 5,000 ms | 18,064 (15,733-19,698) | 55.4 | 4.6 | 768,000 | 1.08x | +| **D-nosink** | sink on -> off | 27,779 (18,290-29,137) | 36.0 | 3.0 | 0 | **1.66x** | +| **D-t1** | threads 8 -> 1 | 11,709 (9,357-13,101) | 85.4 | 7.1 | 768,000 | 0.70x | +| **T0** | hopping-12 -> tumbling (multiplier 12 -> 1) | 81,946 (81,841-90,652) | **12.2** | 12.2 | 64,000 | **4.89x** | +| **T0-cache** | tumbling AND cache 64 MB | 194,927 (190,476-199,377) | **5.1** | 5.1 | 2,000 | **11.63x** | +| I0 | instrument control: + one host crossing/record | 5,392-6,589 | 151.8-185.5 | - | 64,000 | 0.39x | +| I100 | I0 + 0.1 ms/record injected host-side | 5,399 (4,742-7,144) | 185.2 | - | 64,000 | - | +| I1000 | I0 + 1 ms/record injected host-side | 4,137 (3,580-4,694) | 241.7 | - | 64,000 | - | + +#### The budget: which term owns how many microseconds + +**The multiplier split, fitted from the one pair that moves only the window specification.** With +`us/rec = F + m x P`, `T0` (m = 1, 12.2 us) and `D0` (m = 12, 59.7 us) give + +> **P = 4.3 us per (record x window-update), F = 7.9 us per record.** + +So of U6 arm D's headline, **51.8 us of 59.7 (87 percent) is the multiplier**, and only 7.9 us is +once-per-record engine cost. The "50 us engine floor" was mostly twelve of something small. + +**Where the per-window-update 4.3 us goes**, read off the single-term toggles against `D0`: + +| Term | Predicted (of ~50) | **Measured** (of 59.7 us/rec) | Share | +|---|---|---|---| +| Sink produce | ~16 us | **23.8 us** (`D-nosink`, matched clock) | 40% | +| Changelog produce | ~16 us | **10.2 us** (`D-nolog`) | 17% | +| Commit (offsets + producer flush) | ~3 us | **4.3 us** (`D-commit`) | 7% | +| Consumer poll / fetch / deserialise + store put + forward | ~14 us | **~21 us** (the residual, and it is where the fixed 7.9 us/record sits) | 36% | +| **Cache, as a single toggle** | 0 as run; "large slice" of the produce terms | **45.0 us** (`D-cache`) - it subsumes sink, changelog and store-forward work at once by removing **94 percent of the emits** (768,000 -> 45,432) | **75%** | +| Demo/harness artefacts | ~1 us | not separately measured; the verifier's own consume runs on the same box and is inside every arm equally | - | + +The terms are not additive: sink 23.8 + changelog 10.2 + commit 4.3 = 38.3 us, while the cache toggle +alone buys 45.0 us, because a cached put never reaches either produce path *or* the downstream +processor chain. + +**The volume reading, which is the finding underneath all of the above.** `D0` writes 768,000 sink +records plus 768,000 changelog records of ~1 KB each - about **1.5 GB of broker writes per 64,000 +input records**, in 3.8 s, or **~400 MB/s** into a single-container loopback broker. `T0-cache` +writes 2 MB for the same 64,000 records. The two arms differ by a factor of 750 in bytes produced and +a factor of 12 in rate. + +#### The JFR capture (baseline arm, one run) + +async-profiler is not on this box; JFR ships with the JDK, so the capture is JFR execution samples +(`settings=profile`), one `D0` run, 1,234 samples of which **1,219 are on `StreamThread` threads**. +Categories overlap by construction (a produce sample is reached *through* the processor chain), so +these are containment shares, not a partition: **71.6 percent of stream-thread samples carry a +producer frame** (`RecordCollectorImpl` / `KafkaProducer` / `RecordAccumulator`), 35.1 percent a +processor-chain frame, 21.2 percent a window-store frame, 3.7 percent a consumer fetch frame. The top +leaf frames are `Bytes$LexicographicByteArrayComparator.compare`, `HashMap.getNode`, +`ByteUtils.writeVarint`, `KafkaProducer$AppendCallbacks.onCompletion` and the metrics `Sensor` path - +serialising and accounting for records on the way out. The profile and the toggles agree: **the +produce path dominates.** + +#### Predictions, confirmed and refuted + +| # | Prediction | Outcome | +|---|---|---| +| 1 | Baseline reproduces U6 arm D within ~1.5x | **confirmed** - 16,758 rec/s here vs 20,062 fitted there, 1.20x, on a box carrying more ambient load | +| 2 | Cache is the single biggest toggle, >= 2x | **confirmed, and by more than predicted** - 4.05x, the largest single term by a factor of three over the next one | +| 3 | Changelog disabled ~25-30% faster | **refuted, low** - +21% (10.2 us of 59.7). Direction right, magnitude below the band: the changelog write is cheaper than the sink write on the same volume | +| 4 | `commit.interval.ms` 5,000 vs 200 ~5-12% faster | **confirmed** - +7.8% | +| 5 | No-sink ~25-35% faster | **refuted, high** - +66% on the matched clock. The sink produce path is the largest *individually removable* term | +| 6 | Per-thread rate within ~1.3x of 1/8th of the 8-thread rate | **REFUTED, badly, and it reframes the floor** - one thread delivers 11,709 rec/s where eight deliver 16,758. Eight threads buy **1.43x**, not 8x; per thread, one thread is **5.6x** more efficient than each of eight. The crossing-free engine does not scale with threads here | +| 7 | Crossing-free tumbling is 5-15 us/record, 65k-200k rec/s | **confirmed, mid-band** - 12.2 us/record, 81,946 rec/s | +| 8 | +100 us/record injected moves the per-record figure by 80-130 us | **REFUTED** - +33 us at 0.1 ms and +56 us at 1 ms (both medians). Mechanism established below; a valid substitute check is recorded in its place | + +#### The instrument check, refuted as designed - and what replaced it + +**The host-side injection does not move the figure by what it injects, and the reason is +structural rather than instrumental.** The Python client dispatches invocations onto a thread pool, +so a per-record sleep on the host side is absorbed by that concurrency whenever the keys are spread +across partitions: at 1 ms injected the figure moved 56 us, roughly the injected delay divided by the +pool width. U2's version of this check moved 1,091 us against 1,000 us injected precisely because +**its arm A ran a single key** - one partition, one stream thread, a strictly serial chain with no +concurrency to hide in. Recorded as a property of the harness: *the demo's wire path cannot inject a +calibrated per-record cost unless the arm is single-key.* + +**The check that does hold, and it is the stronger one because its magnitude is known +independently:** `T0` and `I0` are the same topology differing by exactly one term - a registered +host function, one crossing per record. The per-record figure moves **12.2 us -> 151.8-185.5 us, a +delta of 140-173 us**, against U6's independently fitted **135 us per crossing** from a different +session, a different arm family and a different sweep. The instrument moves, on the exact quantity +under test, by a constant nobody tuned it to hit. + +#### Contextualised against the two floors + +| Figure | rec/s | us/rec | Source | +|---|---|---|---| +| U6 arm D (crossing-free, cache off, hopping-12) | 20,062 | 50 | `perf-streams-windowing-multiplier.md` | +| **D0 here** (same shape, busier box) | 16,758 | 59.7 | this note | +| **Best crossing-free hopping-12** (`D-cache`) | **67,797** | 14.8 | this note | +| **Best crossing-free tumbling** (`T0-cache`) | **194,927** | 5.1 | this note | +| Arm H, reimplementation floor, hopping-12 | 89,821 | 11.1 | U6 | +| Arm H, reimplementation floor, tumbling | 723,265 | 1.4 | U6 | + +**What the wrapper's best case becomes when the biggest toggled term is eliminated** - that is, when +the cache is simply left at a sane value instead of the zero the measurement chose: + +- **hopping-12: the gap to the reimplementation floor falls from 4.5x to 1.32x** (67,797 vs 89,821); +- **tumbling: from 36x to 3.7x** (194,927 vs 723,265). + +Both against a floor that is explicitly stateless and non-durable - no store, no changelog, no +rebalance recovery, no late-record handling - so at hopping-12 a crossing-free wrapper is inside +noise of a reimplementation that gives all of that up. + +#### Strategic reading: configuration and harness, not Kafka Streams + +**The floor is not Kafka-Streams-intrinsic.** Three arms say so independently and they agree: +87 percent of U6 arm D's 59.7 us/record is the window multiplier rather than per-record engine cost +(`T0`); 75 percent of it is deleted by turning the state-store cache on (`D-cache`), a setting U6 set +to zero for a measurement reason - exact emit counts - and not for a product reason; and 71.6 percent +of profiled stream-thread samples sit in the produce path, writing the ~1.5 GB per 64,000 records +that the cache-off choice manufactures. The refuted thread-scaling prediction closes the argument: +eight threads buy 1.43x, which is what a **shared write path** looks like, not what per-record CPU +looks like. **So the 4.5x-36x that the compiled-function design named as untouchable engine cost is +mostly a measurement artefact plus a window specification** - with the cache on, hopping-12 lands at +1.32x of the non-durable reimplementation floor and tumbling at 3.7x. + +**Against `STRATEGY.md`'s reopening condition**, which reads *"a transport that cuts the per-crossing +cost by roughly two orders of magnitude - the embedded/FFI direction"*: both fast-path spikes met it +(GraalWasm 747 ns staged; the embedded engine deleting gRPC's ~165 us outright), and this spike +removes the reason to believe the engine floor blocks the consequence. The windowed-aggregation +verdict was taken as *"the fitted cost model puts that floor out of reach at any window multiplier"*; +with the crossing gone and the cache on, the wrapper is within 1.32x at hopping-12. That is a +falsification of the strategy text's live claim, not a caveat to it, and the file's own rule - work +that falsifies a claim must update it - now applies. **What is NOT settled and must not be smuggled +in:** the cache-on arms have different emit semantics (94-97 percent of emits are deduplicated by the +flush), so a specification that genuinely needs every intermediate update is not covered by this +result; the F2 comparison against arm H has not been re-run in-session at cache-on; and the whole +decomposition ran on one 32-core box against a single-container broker whose write bandwidth is +visibly the binding constraint on the cache-off arms. + +**Next, in order:** re-run U6's decisive placement arms with the cache on and arm H interleaved, so +the F2 verdict is retaken in-session rather than inferred across notes; then decide whether +`STRATEGY.md`'s windowed-aggregation paragraph is rewritten or annotated. + +### The F2 comparison, retaken in-session 2026-08-25 + +The section above closed by naming this run as the next thing to do, and it was right to: its F2 +reading paired **this note's** cache-on arms against **U6's** arm-H figures, measured in a different +session. The project's pre-registered discipline forbids exactly that - the authoritative baseline +is the control arm measured in the same session as its treatment arm, never a cited constant (the +plan's KTD18) - so the 1.32x and 3.7x above were inferred across notes rather than measured. This +section retakes them with arm H and the cache-on arms in one session, interleaved within each +repetition. **It does not confirm them.** + +Harness: `streams_windowing_lab.py`, new experiment `f2-rerun` (`run_f2_rerun`), which reuses the +engine-floor arms through `_run_floor_arm` rather than restating their toggles. Arms within a +repetition, in order: arm H tumbling, arm H hopping-12, `T0-cache`, `D-cache`, `D0`, `T0`, then the +instrument pair `I0`/`I1000` (`_F2_ENGINE_ORDER`). Arm H goes first while no sidecar is up, the rule +inherited from `_shared_phase`. + +**Conditions.** Engine on Temurin 17.0.20+8 (resolved through `mise`) under the box's ambient +`JAVA_TOOL_OPTIONS` (`MaxRAM=48g`, `MaxRAMPercentage=20`, `ActiveProcessorCount=8`), Kafka Streams +3.9.2, compose broker `confluentinc/cp-kafka:7.9.0` on loopback `127.0.0.1:19098` (compose project +`pc-f2rerun`, started and torn down by this run alone), Python 3.13.5 with `confluent-kafka` 2.15.0, +32-core Linux box. 1 KB payloads, 8 partitions, 8 stream threads, `commit.interval.ms` 200, +in-memory window store, constant event time past the epoch clamp, **1,000 keys**, **64,000 records +per arm**, quiescence at 15 commit intervals with each break confirmed against sink end offsets after +a further 2x, and the engine group required to have committed the whole seeded backlog. **3 reps per +pass, two passes, so n=6 per engine arm.** Every engine arm registers no host function and reported +`crossings/rec=0.00` **measured** client-side on all six runs; `I0`/`I1000` reported exactly 1.00. +1-minute load was read and recorded beside every one of the 60 runs: **2.07-13.65, median 3.22**, +against a limit of 40, so no run ever waited. + +**Deviations from the plan, named rather than glossed:** + +- **Two 3-rep passes, pooled to n=6, rather than one.** The first pass ran before the arm-H + key-count control below existed; rather than discard three reps of the six arms it shares, both + passes are pooled and the pooling is named here. The passes agree - `D0` medians 19,759 and 20,480, + 1.04x apart - and the wider min-max columns are pass 2 running under a heavier ambient load + (2.20-13.65) than pass 1 (2.07-4.71). +- **An arm the plan did not ask for: arm H at 8,000 keys** (`--f2-host-control-keys`, default U6's + 8,000), in-session, one term moved. The 1,000-key choice was made to protect the *cache* arms from + eviction thrash, but it lands on arm H too, and U6's arm-H figures were taken at 8,000 - without + this control the disagreement below would have been *explained* rather than attributed. It refuted + the explanation it was added to test. +- **A third measurement outside the interleave**: arm H standalone at U6's exact conditions (8,000 + keys, **128,000** records, engine idle, 3 reps), run after both passes through the existing + `host-reimpl` experiment. It carries no ratio - it exists to test one cross-session figure. +- **The record count is reconciled to `--floor-records` on both sides.** `run_host_reimpl` derives + its count from `max(--crossings-sweep)` and `run_engine_floor` from `--floor-records`; a comparison + whose two sides ran at different loads is void, so `f2-rerun` drives arm H from `--floor-records` + too. Every arm here ran at 64,000 records. +- **The instrument check was run, not argued for.** `I0`/`I1000`, both halves, inside each rep. + `I100` was deliberately not re-run - refuted above as too small for the client's thread pool to + expose. +- **Quiet-machine gate at 1-minute load 40**, as above, not the harness default of 8. +- **Broker on port 19098, not the 19097 the decomposition used.** A leftover container from a + concluded spike holds 19096; a fresh port and a fresh compose project keep the two independent, and + only this run's broker was torn down. +- **A smoke pass at 8,000 records was abandoned rather than accommodated.** At that size the whole + backlog commits between two 50 ms samples of the committed-offset clock, which then reports a zero + window and fails the run's own validity gate. That is a floor on the harness's record count, not a + fault; **no gate was relaxed to get past it** - the same check is live at 64,000 and passes. +- **The engine classpath was the one already built in this worktree** + (`parallel-consumer-proxy-streams/target/classes`, with `pcStreams.measure.disableChangelog` + present in the compiled `TopologyAssembler`), not rebuilt: a rebuild mid-session would have + contended with the measurement it was for. + +#### Per-arm table + +Medians over 6 reps, min-max beside; rates in RECORDS per second on the sink's broker log-append +clock. The committed-source-offset clock is sampled on every arm and agrees: `D0` reads 19,994 rec/s +on the sink clock and 19,732 on the committed clock, 1.3 percent apart, which is what makes the +second clock believable where it stands alone. + +| Arm | One term moved | rec/s (min-max) | us/rec | us per (rec x window) | emits | vs D0 | +|---|---|---|---|---|---|---| +| **D0** | - (U6 arm D's shape, cache off) | 19,994 (12,230-21,433) | **50.0** | 4.2 | 768,000 | 1.00x | +| **D-cache** | cache 0 -> 64 MB | 69,265 (65,641-88,398) | **14.4** | 1.2 | 46,998 | **3.46x** | +| **T0** | hopping-12 -> tumbling | 90,724 (80,706-98,613) | **11.0** | 11.0 | 64,000 | **4.54x** | +| **T0-cache** | tumbling AND cache 64 MB | 169,748 (113,879-246,154) | **5.9** | 5.9 | 2,264 | **8.49x** | +| I0 | instrument control: + one host crossing/record | 8,114 (6,565-8,622) | 123.2 | 123.2 | 64,000 | 0.41x | +| I1000 | I0 + 1 ms/record injected host-side | 5,816 (4,985-5,867) | 171.9 | 171.9 | 64,000 | 0.29x | + +**Arm H, this session, at the matched condition** (1,000 keys, 64,000 records, single-threaded, +non-durable - no store, no changelog, no rebalance recovery, no late-record handling, so it is an +upper bound on a real reimplementation), n=6: + +| Arm H specification | rec/s (min-max) | us/rec | +|---|---|---| +| tumbling | 797,338 (630,271-909,065) | 1.3 | +| hopping-12 | 460,026 (390,388-487,071) | 2.2 | + +#### The F2 verdict, retaken in-session + +This is the number the whole re-run exists to produce. Wrapper best case against arm H **at the same +specification, in the same session, interleaved**: + +| Specification | Wrapper best case | Arm H (F2) | **H / wrapper** | The cross-session figure above | +|---|---|---|---|---| +| tumbling | `T0-cache` 169,748 rec/s | 797,338 rec/s | **4.70x** | 3.7x | +| hopping-12 | `D-cache` 69,265 rec/s | 460,026 rec/s | **6.64x** | **1.32x** | + +**At tumbling the in-session figure is close to the inferred one** (4.70x against 3.7x, the +difference inside the arms' own spread). **At hopping-12 it is not: 6.64x against 1.32x, a factor of +five.** Under the pre-registered F2-first band semantics - wrapper-low against H-high - both +specifications read **fails**: `T0-cache`'s 113,879 against H's 909,065, `D-cache`'s 65,641 against +H's 487,071. The wrapper does not reach the reimplementation floor at either specification, cache on. + +The wrapper side is not the disagreement. `D-cache` reads 69,265 here against 67,797 above, within +2 percent. **The entire discrepancy is arm H**, which read 89,821 rec/s at hopping-12 in U6's session +and 460,026 here. + +#### The anchors, and what they say about the box + +| Arm | This session | 2026-08-25 | Ratio | +|---|---|---|---| +| `D0` | 19,994 rec/s | 16,758 rec/s | 1.19x | +| `T0` | 90,724 rec/s | 81,946 rec/s | 1.11x | + +**Both anchors read high, in the same direction, within 8 points of each other.** That is a +box-condition offset of roughly 10-20 percent rather than an arm effect: this session's ambient load +was 2.07-13.65 (median 3.22) against the decomposition's recorded 0.96-30.29. So the two sessions' +*engine* figures are comparable after a uniform ~15 percent, and the interleave makes even that +harmless for every ratio reported here. **The anchors reproduce. Arm H does not** - which is exactly +what having anchors is for: it localises the disagreement to one arm instead of leaving it as +"different day". + +#### Where arm H's 5x went: the key count is refuted, and the figure is bimodal + +The obvious suspect was the key count - the engine arms run at 1,000 keys and U6's arm H at 8,000 - +so it was moved as a control arm, in-session, with nothing else changed (n=3): + +| Arm H specification | 1,000 keys | 8,000 keys | Key count is worth | +|---|---|---|---| +| tumbling | 797,338 rec/s | 763,716 (690,192-800,705) | 1.04x | +| hopping-12 | 460,026 rec/s | 372,571 (280,538-420,417) | 1.23x | + +**Refuted.** A 1.23x cannot account for a 5.1x. So arm H was re-run at U6's *exact* conditions - +8,000 keys, 128,000 records, engine idle, standalone, 3 reps - and the result is the finding: + +- **tumbling: 751,163 rec/s (677,567-760,137) against U6's 723,265. Reproduces.** +- **hopping-12: 423,267 / 92,254 / 417,230 rec/s. Bimodal.** One rep of three landed at 92,254 - + within 3 percent of U6's 89,821 (88,484-91,619, n=4) - and the other two at ~420,000. + +Across all twelve arm-H hopping-12 runs this session, at every key and record condition, the samples +are 92,254 / 280,538 / 372,571 / 390,388 / 413,867 / 417,230 / 420,417 / 423,267 / 445,698 / +474,355 / 478,637 / 487,071. **One of twelve sits at U6's value and a second is halfway down; +the remaining ten span 372,571-487,071. All four of U6's reps sat in the slow mode.** + +**Reported as a contradiction, not tuned into agreement.** The consequence is stated rather than +resolved: *F2 at hopping-12 is not a stable quantity on this harness*, so the 1.32x above rests on an +arm-H figure that this session reproduces one time in twelve. The leading hypothesis is CPython's +cyclic collector - hopping-12 allocates a `(key, start)` tuple twelve times per record, 768,000 to +1,536,000 per run against tumbling's twelfth of that, and whether a generation-2 collection lands +inside the timed window is close to a coin toss - which also explains why only the hopping arm is +bimodal while tumbling is stable across every condition tried. **It is a hypothesis with no control +arm behind it and must not be cited as a cause.** It was deliberately not tested here, and the reason +is worth recording: the slow mode appeared once in twelve, so a three-rep paired arm toggling +`gc.disable()` would with high probability show both sides fast and prove nothing. **The follow-up +needs a design that can make the slow mode appear on demand** - many more reps, or a forced +generation-2 collection inside the timed window - before a paired control is worth running at all. + +#### The instrument check + +Both halves ran inside each rep, and the stronger one is the crossing: + +- **Crossing:** `T0` -> `I0` adds exactly one registered host function to the same tumbling topology + and moves the per-record figure **11.0 -> 123.2 us/rec, a delta of 112 us**, against U6's + independently fitted **135 us per crossing** from a different session and a different arm family. + The instrument moves, on the quantity under test, by a constant nobody tuned it to hit. +- **Injected:** `I0` -> `I1000` adds 1,000 us/record host-side and moves the figure **123.2 -> 171.9 + us/rec, a delta of 49 us**. That is the harness property already recorded above - the client + dispatches invocations onto a thread pool, which absorbs a per-record sleep unless the arm is + single-key - reproduced here rather than a new result. It is why the crossing delta, not this one, + is the check that counts. + +#### Two caveats carried forward + +- **The cache-on arms deduplicate almost all of their emits, and that is a different specification.** + `D-cache` emits 46,998 where `D0` emits 768,000 (**93.9 percent deduplicated**); `T0-cache` emits + 2,264 against 64,000 (**96.5 percent**). A specification that genuinely needs every intermediate + update is **not** covered by any figure in this section. +- **Every prior bet-off verdict remains valid for its pre-registered conditions.** Nothing here says + a previous measurement was wrong; it says a condition of one of them - the state-store cache set to + zero - was instrumental rather than a product choice, and that the F2 side of the comparison had + never been taken in the same session as the arms it was being compared against. + +#### What this changes above, and what is next + +The preceding section's closing claim - *"hopping-12: the gap to the reimplementation floor falls +from 4.5x to 1.32x"* - **does not survive an in-session retake**: the in-session figure is 6.64x, and +the difference is entirely arm H, whose hopping-12 rate this session reproduces U6's value in one run +of twelve. The tumbling claim (3.7x) survives as 4.70x. The cache finding itself is untouched - +`D-cache` and `T0-cache` reproduce within 2 percent and 13 percent respectively - so the decomposition +above stands; what does not stand is the consequence it drew for F2 at hopping-12. + +**Next, in order:** (1) settle arm H's bimodality with a single-term control arm on the collector, +because until it is settled F2-hopping has no median worth quoting; (2) only then decide whether +`STRATEGY.md`'s windowed-aggregation paragraph is rewritten or annotated - on today's evidence the +falsification claimed above is **not** established at hopping-12, and annotating it with this +section is the conservative reading. + +### Why arm H's hopping-12 rate is bimodal, settled 2026-08-25 + +The section above closed by naming this as the first of two things to do, because until it is +settled *F2 at hopping-12 has no median worth quoting*. It also named the leading suspect - CPython's +cyclic collector - and, in the same breath, said it was **a hypothesis with no control arm behind +it**. So this section does not start there. It pre-registers five candidates, runs an observational +pass that can show each one's signature *before* any toggle exists, and only then toggles. + +**Everything from here to the `#### Measured results` marker was written into the tree before the +first arm ran.** The harness change (`host-bimodal`, `run_host_bimodal`, `_H_ARMS`) was written first, because +the instrumentation is part of the pre-registration: what gets recorded beside each rate is itself a +claim about what could be responsible. + +#### The condition is chosen to make the slow mode COMMON, not rare + +The previous round declined to run a paired toggle and gave the reason: the slow mode appeared once +in twelve, so three reps would show both sides fast and prove nothing. That is a statement about a +*pooled* frequency across every key and record condition tried. Split by record count, the twelve +samples are not one population: + +- **64,000 records** (the `f2-rerun` interleave, both key counts): 9 samples, **none** below + 280,538 rec/s; +- **128,000 records** (U6's four reps, plus this fork's standalone three at U6's exact conditions): + 7 samples, **five** at ~90,000 rec/s. + +So the slow mode is not 1-in-12 everywhere; at U6's exact arm-H conditions it is roughly 5-in-7, and +64,000 records is where it hides. **Every arm below therefore runs at 128,000 records and 8,000 +keys** - U6's conditions, the condition under which every slow sample so far was taken. Choosing the +condition that makes the mode common is what buys the power the previous round did not have; the +record count is itself pre-registered as a term (H3 predicts it is *the* term). + +#### Pre-registered hypotheses and what each predicts + +| # | Hypothesis | Predicted signature in the observational pass | Arm that would refute it | +|---|---|---|---| +| **H1** | **CPython's cyclic collector.** Hopping-12 allocates a `(key, start)` tuple twelve times per record - 1,536,000 per run against tumbling's twelfth - so whether a generation-2 pass lands inside the timed window is close to a coin toss | Slow runs carry >= 1 gen-2 pass inside the window and fast runs do not; **measured collector pause accounts for most of the ~1.1 s excess**; `cpu/wall` stays near 1 (the process is busy, not waiting) | `H-gcoff` (`gc.disable()`, one term) shows no slow runs, paired against `H-base` in the same rep; and `H-gcforce` prices a forced gen-2 pass | +| **H2** | **Cold read / per-topic first-read state.** The arm-H topic is REUSED across reps (`_seed_host_topic` sets `retention.ms=-1` for exactly that reason), so the first read of a topic is cold and later ones may be served from page cache | Slow runs cluster at low `rep`; the excess sits in `consume`, not `fold` | `H-fresh` (a topic seeded for this rep and never read) is slow every rep, or is not slow at all | +| **H3** | **Fetch-path stall.** The loop batch-consumes with `timeout=1.0`; librdkafka's local queue defaults to `queued.max.messages.kbytes=65536`, about 64,000 1 KB records - so at 128,000 records the loop MUST outrun the fetcher and can take an empty poll, which the timed window charges at up to a full second | Slow runs show >= 1 empty poll after the window opened, or one very large `max gap`; **the excess is quantised in ~1.0 s units**; `cpu/wall` collapses (the process is waiting); the fold-only rate is unaffected | `H-queue` (local queue raised past the whole backlog) shows no slow runs; `H-starve` (queue shrunk) produces the signature on demand | +| **H4** | **Box contention.** The box carries other agent sessions; a ~0.3 s single-threaded burst descheduled or landed on a busy core reads as a slow run | Slow runs correlate with the per-run **pure-CPU calibration** and with 1-minute load; the excess is spread continuously through `fold`, not quantised; `cpu/wall` stays near 1 while the calibration is proportionally slower | The calibration is flat across fast and slow runs | +| **H5** | **The metric charges wait to the rate.** `records / (ended - started)` counts every second between the first batch and the last, including seconds in which no record was processed. Whatever causes a wait, arm H's "rate" is then a property of the harness's polling rather than of the reimplementation | The **fold-only rate** (`records / fold_s`) is unimodal and stable across every run, while the wall-clock rate is bimodal | The fold-only rate is bimodal too - in which case the slow mode is real work, not accounting | + +H1 and H4 predict the process is **busy**; H2, H3 and H5 predict it is **waiting**. `cpu/wall` and +the fold/consume split separate those two families on the observational pass alone, before a single +term is toggled - which is the point of running it first. + +**H1 can also be refuted on magnitude without any toggle**, and that is the cheapest result +available: the live dict holds 8,000 x 12 = 96,000 entries plus their tuples, so a full generation-2 +pass traverses a few hundred thousand objects. If `H-gcforce` prices that at milliseconds, no number +of them accounts for 1.1 s, and H1 is dead whatever the correlation says. + +#### Arms + +Each moves exactly one term against `H-base`, the untouched loop (`_H_ARMS` in +`streams_windowing_lab.py`). Three phases, in order, and the order is the method. + +| Phase | Arms | What it is for | +|---|---|---| +| `observe` | `H-base` (hopping-12), `T-base` (tumbling) | The untouched loop, many reps, **nothing toggled**. `T-base` is the in-session stability control - tumbling has reproduced in every session, so an explanation that would also make tumbling bimodal is wrong | +| `toggle` | `H-base`, `H-gcoff`, `H-queue`, `H-fresh` | Paired single-term arms, interleaved within each rep, so a rep in which `H-base` is slow and its partner is fast is a *discordant pair* rather than a between-group difference | +| `positive` | `H-base`, `H-gcforce`, `H-starve` | Arms that make each candidate mechanism happen **on demand**, so it is priced instead of argued about. This is what the previous round said the follow-up needed | + +**Power, stated before the runs.** For a toggle arm showing zero slow runs to mean anything, the +slow mode must be common in its partner. At the pooled `p = 1/12` the previous round quoted, 12 reps +of a clean toggle arm carry `(1-p)^n = 0.35` - a third of the time you see that by luck, which is why +it declined to run one. At this section's condition the historical rate is `5/7 = 0.71`, where 12 +reps carry `4e-7`. The paired design is stronger still: with `k` discordant reps all in one +direction, the exact two-sided sign test is `2^(1-k)`, so **six discordant pairs settle a toggle**. +`H-gcforce` and `H-starve` need no power argument at all - they do not wait for the mode, they cause +it. + +**Conditions, fixed for every arm.** 128,000 records, 8,000 keys, 8 partitions, 1 KB payloads, +constant event time past the epoch clamp, single-threaded `confluent_kafka`, **no engine, no sidecar +and no classpath** (arm H needs none). Compose broker `confluentinc/cp-kafka:7.9.0`, its own port +and compose project. 1-minute load read and recorded beside every run; every run also carries a +fixed pure-CPU calibration taken immediately before its window, the window split into fold time and +consume time, empty-poll count and duration, largest single consume gap, process CPU time across the +window, and the collector's passes and **measured pause time** inside the window. + +**Nothing above this line changes after the first run; corrections land below as dated entries.** + +#### Measured results + +**Conditions.** Harness `streams_windowing_lab.py`, new experiment `host-bimodal` +(`run_host_bimodal`, arms in `_H_ARMS`, phases in `_H_PHASES`). Python 3.13.5 with +`confluent-kafka` 2.15.0 (librdkafka 2.15.0), compose broker `confluentinc/cp-kafka:7.9.0` on +loopback `127.0.0.1:19099` (compose project `pc-hbimodal`, started and torn down by this run +alone), 32-core Linux box, 48 GB RAM. 128,000 records, 8,000 keys, 8 partitions, 1 KB payloads, +constant event time past the epoch clamp, unless a row says otherwise. **No engine, no sidecar and +no classpath** - arm H needs none, which is why this ran in minutes rather than hours. 1-minute +load recorded beside every one of the 178 runs: **1.27-8.15**, against a limit of 40, so no run +ever waited. + +#### What settled it, in one line + +**The stall is librdkafka's `fetch.queue.backoff.ms`.** When the consumer's local queue passes +`queued.max.messages.kbytes` (64 MB by default, about 85,000 of these records) librdkafka stops +fetching and postpones the next fetch by **1,000 ms**. Arm H's aggregation loop then drains the +queue, arrives at an empty one, and blocks inside `consume()` for the remainder of that timer - +**one 0.57-0.66 s wait, at a fixed position in the stream, charged in full to a window that +otherwise takes 0.26 s.** Nothing in arm H is slow; arm H is *waiting*, and +`records / (ended - started)` counts the wait. + +#### Phase `observe` - the untouched loop, nothing toggled + +`H-base` hopping-12, n=20, and `T-base` tumbling, n=20, interleaved within each rep. + +| Arm | median rec/s | min-max | fold-only rec/s (median) | polls > 100 ms | gen-2 passes | collector pause | cpu/wall | +|---|---|---|---|---|---|---|---| +| `H-base` hopping-12 | **94,333** | 93,182-95,088 | **495,980** | **3 in every run** | 0-1 | <= 0.008 s | 0.27-0.31 | +| `T-base` tumbling | 1,082,531 | 738,540-1,195,233 | 1,802,586 | **0 in every run** | 0 | <= 0.001 s | 1.56-1.65 | + +`H-base`'s twenty wall-clock samples: 93,182 / 93,812 / 93,885 / 93,990 / 94,060 / 94,088 / 94,094 +/ 94,213 / 94,306 / 94,310 / 94,355 / 94,405 / 94,411 / 94,420 / 94,492 / 94,557 / 94,621 / 94,647 +/ 94,698 / 95,088. + +**Three things are visible before any term is toggled.** The spread is **1.02x** - at 128,000 +records the "slow mode" is not a mode at all, it is the only outcome. Every run's largest wait is +**0.61-0.66 s and lands at the same record index** (92,545 in 19 of 20). And `cpu/wall` is +**0.27-0.31**: the process is idle for three quarters of its own measured window, which rules out +every hypothesis that predicts work. + +#### Phase `order` - the confound the smoke pass exposed, refuted + +A 2-rep smoke ran before the arms were final and showed `H-base` slow in both reps - but `H-base` +ran *first* in each rep, where `f2-rerun` runs tumbling first. Read position is a term the +pre-registration did not name, so it got an arm before anything else was toggled (n=12 each, +interleaved as `H-first`, `T-base`, `H-second` on one shared topic). + +| Arm | median rec/s | min-max | +|---|---|---| +| `H-first` (first read of the rep) | 93,438 | 87,517-94,804 | +| `H-second` (after `T-base` read the same topic) | 93,927 | 91,456-94,842 | + +**Read order is worth 1.005x. Refuted** - and with it the "an early rep is disproportionately +likely to be slow" reading of the historical samples. + +#### Phase `toggle` - the pre-registered paired arms + +n=12 each, interleaved within every rep, at 1-minute load 5.31-7.43. + +| Arm | One term moved | median rec/s | min-max | vs `H-base` | polls > 100 ms | +|---|---|---|---|---|---| +| `H-base` | - | 91,871 | 79,817-94,440 | 1.00x | 3 in every run | +| `H-gcoff` | `gc.disable()` for the window | 93,120 | 86,333-94,242 | **1.01x** | 3 in every run | +| `H-fresh` | topic seeded this rep, never read | 91,371 | 51,480-93,372 | **0.99x** | 3 in every run | +| `H-queue` | local queue raised past the whole backlog | **355,205** | 190,638-437,165 | **3.87x** | **0 in every run** | + +**`H-gcoff` verified itself**: collector pause was exactly `0.000 s` on all twelve runs, so the +toggle demonstrably reached the run - and the rate did not move. **`H-fresh`** carries the one +outlier of the whole session (51,480 rec/s, a 1.734 s wait) and it is the same signature, not a +different one. + +#### Phase `backoff` - the arm that names the mechanism + +n=12 each, interleaved, one term: librdkafka's `fetch.queue.backoff.ms`. + +| Arm | `fetch.queue.backoff.ms` | median rec/s | min-max | fold-only (median) | polls > 100 ms | cpu/wall | +|---|---|---|---|---|---|---| +| `H-base` | 1,000 (librdkafka's default) | 94,650 | 93,370-95,186 | 510,030 | 3 | 0.26-0.30 | +| `H-backoff100` | 100 | **436,569** | 424,129-447,529 | 513,786 | **0** | 1.21-1.29 | +| `H-backoff10` | 10 | **430,678** | 407,176-449,563 | 514,542 | **0** | 1.21-1.29 | + +**Non-overlapping** - `H-base`'s maximum is 95,186 and `H-backoff100`'s minimum is 424,129 - and +**12 of 12 discordant pairs in the same direction**, exact two-sided sign test `2^-11 = 4.9e-4`. +The three arms' **fold-only** rates are identical (510,030 / 513,786 / 514,542): the toggle changes +nothing about the aggregation, only about the waiting. + +**One prediction inside this arm was refuted.** The ladder was registered expecting the stall's +*length* to track the setting - 100 ms in, 100 ms of stall out. It does not: at 100 ms the stall +disappears entirely rather than shrinking. The reason is mechanical and is itself a confirmation - +the timer only bites if the consumer empties the queue before it expires, and draining 64 MB at +~510,000 rec/s takes ~125 ms, which is longer than 100 ms and far shorter than 1,000 ms. **The +response is a threshold, not a proportion.** + +#### Phase `positive` - the two arms that make each mechanism happen on demand + +n=3 each (the reduced n is named below). These need no power argument: they do not wait for a mode, +they cause one. + +| Arm | median rec/s | window | polls > 100 ms | What it prices | +|---|---|---|---|---| +| `H-base` | 94,080 | 1.36 s | 3 | - | +| `H-gcforce` (one forced `gc.collect(2)` mid-window) | **94,453** | 1.36 s | 3 | **a full generation-2 collection over this working set costs 7-12 ms** | +| `H-starve` (local queue shrunk to ~1 MB) | **947** | 135 s | **135, each of them 1.001-1.002 s** | **`fetch.queue.backoff.ms` read straight off the clock, 135 times per run** | + +`H-starve` is the decisive one: with the queue shrunk so that it refills and re-fills constantly, +the consume loop takes **135 waits of exactly 1.002 s** - at intervals of ~956 records, the shrunken +queue's capacity - while its **fold-only rate is unchanged at 318,310 rec/s** and `cpu/wall` reads +`0.00`. The mechanism is not inferred from a correlation; it is reproduced on demand with the timer's +own value on it. + +#### Phase `ladder` - the record count is the term, and tumbling is not immune + +3 reps at each count, untouched loop, default fetch config. + +| Records | hopping-12 rec/s | stalls in the hopping window | tumbling rec/s | stalls in the tumbling window | +|---|---|---|---|---| +| 32,000 | 155,113-318,145 | **none** | 705,517-958,089 | none | +| 48,000 | 227,199-320,364 | **none** | 392,445-1,003,259 | none | +| 64,000 | 375,775-398,053 | **none** | 890,508-1,077,448 | none | +| 80,000 | 163,154-324,199 | **none** | 487,834-1,050,101 | none | +| 96,000 | 71,061-73,329 | **3/3 runs**, ~0.5 s at record ~84,000-92,000 | 602,690-1,054,509 | none | +| 128,000 | 91,597-94,395 | **3/3 runs**, ~0.6 s at record ~84,000-92,000 | 1,017,067-1,070,303 | none | +| 192,000 | 80,281 | **two episodes**, at records ~85,000 **and** ~177,000 | **143,810** | **yes** - 0.742 s at record 177,209 | + +**The switch is between 80,000 and 96,000 records**, which is where the backlog first exceeds the +64 MB local queue by enough for the consumer to drain it before the 1,000 ms timer expires. This is +the whole of the historical "bimodality": **64,000-record runs sat below the threshold and 128,000- +record runs above it.** And at 192,000 records **tumbling stalls too** - it is not a property of the +hopping specification, it is a race between the fetcher's supply rate and the loop's drain rate, and +tumbling drains fast enough to keep the queue below the cap for longer, not forever. + +#### Hypotheses, confirmed and refuted + +| # | Hypothesis | Outcome | The arm that settled it | +|---|---|---|---| +| **H1** | CPython's cyclic collector | **REFUTED, three ways** | (i) magnitude, no toggle needed: measured collector pause inside a slow window is **2-15 ms** against a **1.1 s** excess, and gen-2 passes are 0 or 1; (ii) `H-gcforce` prices a *forced* full gen-2 pass at **7-12 ms** - you would need ~90 of them; (iii) `H-gcoff`, the paired toggle, moves the rate by **1.01x** with the collector demonstrably off (pause exactly 0.000 s, 12/12) | +| **H2** | Cold read / per-topic first-read state | **REFUTED, twice** | `H-second` reads a topic another arm read seconds earlier in the same rep and is **1.005x** of `H-first`; `H-fresh` seeds its own topic every rep and is **0.99x** of `H-base` | +| **H3** | Fetch-path stall | **CONFIRMED, and named exactly** | Three independent arms, each moving one term: `H-backoff100`/`H-backoff10` (the timer) **4.6x**; `H-queue` (the capacity) **3.87x**; `H-starve` (the positive control) reproduces the wait 135 times at its literal 1.002 s. The ladder adds the fourth: the stall switches on between 80,000 and 96,000 records, where the backlog crosses the queue's 64 MB | +| **H4** | Box contention | **REFUTED** | The per-run pure-CPU calibration is **13.1-26.4 ms across all 178 runs** and flat between fast and slow ones; the slowest and fastest `H-base` runs of the observational pass differ by 1.02x while their calibrations differ by 1.19x in the *wrong* direction. `cpu/wall` at 0.27-0.31 says the process is idle, not contended | +| **H5** | The metric charges wait to the rate | **CONFIRMED, and it is the reason the quantity looked bimodal** | The **fold-only** rate is 445,501-518,212 rec/s in the observational pass (spread 1.16x) while the wall-clock rate of the *same runs* is 93,182-95,088. Across the toggled arms the fold-only rate is 510,030 / 513,786 / 514,542 - unchanged by every term that moves the wall-clock rate 4.6x | + +The two families the pre-registration named separated on the observational pass exactly as it said +they would: **`cpu/wall` was 0.27-0.31, so the process was waiting**, which killed H1 and H4 before +a single arm was toggled. + +#### The distribution, which is the finding + +**98 runs of the untouched loop at 128,000 records** (arms `H-base`, `H-first`, `H-second`, +`H-gcoff`, `H-fresh`, `H-gcforce` - none of which touches the fetch path), across five phases and +1-minute loads from 1.27 to 8.15: **every single one between 51,480 and 95,186 rec/s**, 96 of them +between 79,817 and 95,186. **36 runs with one fetch-path term moved** (`H-backoff100`, +`H-backoff10`, `H-queue`): **every single one between 190,638 and 449,563 rec/s.** The two +populations do not overlap and nothing in between was ever observed. + +So the quantity was never bimodal in the sense of a coin toss. It was **two deterministic regimes +selected by the record count**, and the earlier sessions sampled both without recording the term +that chose between them. + +#### Power, as reasoned rather than as hoped + +The pre-registration argued from a pooled `p = 1/12` (useless at n=12) and a conditioned +`p = 5/7` at U6's exact conditions (`(1-p)^12 = 4e-7`). **The measured `p` at 128,000 records is +1.00 - 98 of 98.** That makes the paired toggles far stronger than planned: `H-base` against +`H-backoff100` is 12 discordant pairs out of 12, `2^-11 = 4.9e-4`; `H-base` against `H-queue` the +same. The refutations are equally powered in the other direction - `H-gcoff` produces **zero** +discordant pairs in 12, against a partner that stalls every time. + +**And none of it was load-bearing**, because `H-starve` and `H-gcforce` do not sample a rate: one +reproduces the mechanism on demand and the other prices it. That is what the previous section meant +by "a design that can make the slow mode appear on demand", and it is why this settled in one +session where a paired 3-rep toggle would not have. + +#### The guard, and its negative control + +**A measurement that could silently become 4.7x wrong now fails instead.** `measure_host` raises +when its timed window contains a `consume()` call over 100 ms, naming the mechanism, the position +and the lever; the bimodality arms whose whole purpose is to exhibit the stall carry +`expect_stall=True` and stand down. Verified in both directions, and the negative control is the +exact configuration that produced the disputed number: + +- `host-reimpl` at U6's conditions (128,000 records, 8,000 keys) - the run that reported **89,821 + rec/s** in U6 and **92,254** in the section above - now **fails** with + `arm H invalid: 3 consume() call(s) over 100ms inside the timed window ... 81% of this window was + fetch wait, not aggregation`; +- the same run with `--host-fetch-queue-backoff-ms 100`, one term moved, **passes**, and reads + **393,855 and 433,285 rec/s** at hopping-12 (and 1,118,959 / 1,156,428 at tumbling); +- the guard then caught a case nobody predicted: **`T-base` at 192,000 records**, where tumbling + stalls too, printed `STALLED` rather than a rate. + +#### What F2 at hopping-12 should now be quoted as + +**The in-session 6.64x stands, and the cross-session 1.32x is now dead for a stated reason rather +than merely contradicted.** + +- The `f2-rerun` retake ran arm H at **64,000 records**, which the ladder places **below the stall + threshold**. Its arm-H hopping-12 figure (460,026 rec/s, 390,388-487,071) sits squarely in this + session's un-stalled population (190,638-449,563 at 128,000 records; 375,775-398,053 at 64,000). + **That comparison was never contaminated, so `D-cache` 69,265 against arm H 460,026 = 6.64x is + the figure to quote.** +- U6's **89,821 rec/s was the artefact**: taken at 128,000 records with librdkafka's default + backoff, it is 78-81 percent fetch wait. Corrected at U6's own conditions, through U6's own + `host-reimpl` experiment, with one term moved, arm H reads **393,855-433,285 rec/s** - **4.4-4.8x + higher**. The 1.32x was a ratio whose denominator was a stalled consumer. +- **Arm H's hopping-12 rate is a stable quantity after all**, once the term that was never recorded + is fixed: **~430,000-440,000 rec/s** on the wall clock at 128,000 records with the fetch queue not + starved, and **~510,000 rec/s** on the fold-only clock, which is the figure that does not depend on + the harness's polling at all. It was never a coin toss and there was never a second mode. +- **What this section does NOT license.** No engine ran in this session, so **no new F2 ratio is + taken here** - KTD18 forbids pairing these arm-H figures against the wrapper arms measured in the + `f2-rerun` session, which is the exact error this whole line of work exists to correct. The + hopping-12 verdict remains `f2-rerun`'s 6.64x; what changes is that the 1.32x has a cause, and + that arm H now has a defensible number to re-take a ratio against when engine arms next run. + +Against the section above, its "Next, in order" item (1) is discharged: **arm H's bimodality is +settled, F2-hopping does have a median worth quoting, and it is 6.64x.** Item (2) - whether +`STRATEGY.md`'s windowed-aggregation paragraph is rewritten or annotated - is untouched by this +work and, on today's evidence, still reads as annotate: the wrapper does not reach the +reimplementation floor at hopping-12. + +#### Deviations, named rather than glossed + +- **A 2-rep smoke pass ran before the arm set was final**, and its numbers are reported rather than + discarded (92,501 / 91,968 rec/s, both with the 0.57-0.63 s stall, gen-2 pauses of 2-3 ms). It is + what exposed the read-order confound and motivated `H-first`/`H-second` and the + gap-position instrument. It is counted in the 98. +- **Two arms and one instrument were added after the pre-registration**, both named at the point + they appear above: the `order` phase (read position - a term the pre-registration did not name), + and the `backoff` ladder plus the record-count `ladder` (added once the observational pass had + localised the stall). The pre-registered arms were all run regardless, including the two the + observational pass had already made unlikely. +- **The `positive` phase ran at n=3, not 12.** `H-starve` takes **135 seconds per run** by + construction; three runs of it produce 405 waits of 1.002 s, which is not a quantity more reps + would sharpen. A first attempt at n=8 was cut off by a wall-clock limit after 3 reps and its two + completed `H-starve` runs agree with these (153 s, 154 waits of 1.001-1.002 s). +- **The `ladder` phase ran at n=3 per record count**, under a rising ambient load (4.42-8.15). The + hopping rates below the threshold vary continuously with that load (155,113-398,053) and are not + claimed as anything but "no stall"; the threshold itself is the result and it is 3/3 at every + count. +- **`H-queue`'s spread is wide** (190,638-437,165). A queue raised past the whole backlog makes + librdkafka buffer 140 MB eagerly, and its fetch threads then compete with the fold for CPU on a + box at load 5-7. It moves the outcome decisively in the right direction; its *median* is not a + clean figure for anything and is not used as one. +- **The instrumentation is inside the loop under test.** Two `time.monotonic()` calls per batch + (about 130 per run) plus a `gc.callbacks` entry that runs only when the collector does. The check + that it is harmless is that `H-base` reproduces the pre-existing figure: 94,333 here against + 92,254 in the section above and 89,821 in U6. +- **`--load-limit 40`, not the harness default of 8**, as in both sections above; the box carried + other agent sessions throughout and the per-run load is recorded beside every figure. +- **The broker is on port 19099 in compose project `pc-hbimodal`**, torn down by this run alone. The + leftover `pcnumba-broker-1` on 19096 was left untouched, as was `pc-f2rerun`'s. +- **No engine arm was run and none was needed.** Every hypothesis on the table was about the + reimplementation's own consume loop, and arm H requires no engine, no sidecar and no classpath - + which is why 178 measured runs fitted in one session. + +#### What is not settled + +**Why the previous session's three standalone 128,000-record arm-H runs came out 2/3 fast** +(423,267 / 92,254 / 417,230) when this session's 98 untouched runs at the same record count are +98/98 slow. The mechanism explains how that can happen - the stall only arms if the *fetcher* +outruns the *consumer* far enough to fill 64 MB, so anything that depresses the fetcher (a busier +broker, a busier box) removes it - and the tumbling arm demonstrates that race in-session from the +other side, stalling at 192,000 records where it does not at 128,000. But this session never +reproduced a fast untouched 128,000-record run, at loads from 1.27 to 8.15, so the fetcher-side +condition is named rather than measured. **What would settle it:** the same ladder run against a +broker under concurrent read load, with the fetcher's delivery rate recorded per run rather than +inferred from the consumer's. + +### The crossover ladder, rung 1: what durability costs the reimplementation, 2026-08-25 + +Every F2 verdict in the three sections above divides by **arm H** - a bare single-threaded Python +`confluent_kafka` consumer folding records into a dict, whose own docstring says it is *stateless +and non-durable*: no state store, no changelog, no restore, no rebalance recovery, no late-record +handling, no exactly-once. The owner's judgement, now recorded in `STRATEGY.md` and in +[`docs/solutions/architecture-patterns/a-per-record-crossing-loses-to-reimplementation-before-features-enter.md`](../solutions/architecture-patterns/a-per-record-crossing-loses-to-reimplementation-before-features-enter.md) +("Correction, 2026-08-25 (second)"), is that **this comparison decides nothing**: Kafka Streams is +not in the business of trivial stateless aggregation, so a floor built from a dict is the floor for +a different product, and a toy beats an engine at toy work at any transport speed. + +The question that does decide it is the **crossover**: *how many of the features a user actually +came for can be added back to that dictionary before hand-rolling becomes the worse choice?* This +section takes the first step on that ladder. The owner has chosen the first feature: **durability**. + +**Everything from here to the `#### Measured results` marker was written into the tree before the +first arm ran**, harness included - the same rule the bimodality section states, and for the same +reason: what gets recorded beside each rate is itself a claim about what could be responsible. + +#### What "durability" means here, and what it deliberately does not + +**One term moved.** H-durable is arm H plus the two halves of what Kafka Streams' state store gives +you, and nothing else: + +- **a changelog** - each state update produced to a compacted Kafka topic, so the dict's contents + are recoverable; +- **restore on restart** - read that changelog back and rebuild the dict before processing resumes. + +**Not on this rung, and not smuggled in:** exactly-once (`enable.idempotence` is explicitly `false` +on the changelog producer), rebalance handling, late-record logic, a real state store. Those are +later rungs. The wrapper arms it is compared against carry all of them anyway, so every omission +here runs in the reimplementer's favour - which is the direction this whole programme has kept its +thumb on the scale. + +#### Pre-registered design decisions, and what each one means for the number + +These determine what the number means, so they are registered rather than reported. + +| Decision | Choice | What it means for the number | +|---|---|---| +| **Write granularity** | **Both, as two rungs**: `H-dur-per` writes one changelog record per state update; `H-dur-coal` coalesces the dirty `(key, window)` set and writes it once per commit interval | These are two different reimplementers, not one with an optimisation. The naive one writes per update - at hopping-12 that is 12 changelog records per input record, exactly `D0`'s volume. The careful one hand-rolls what Kafka Streams' state-store cache does, the toggle the decomposition above priced at **4.05x** (`D-cache`). Measuring only one would model only one reimplementer | +| **Delivery guarantee** | `acks=all`, `enable.idempotence=false`, librdkafka's default linger, **`flush()` awaited at every boundary, inside the timed window** | A changelog you do not wait for is not durable, and this choice is expected to dominate. The final boundary is inside the window on purpose: an arm whose last 200 ms of state reached the broker only after the clock stopped was not durable at the moment it claimed a rate | +| **Boundary interval** | **200 ms**, i.e. `--commit-interval-ms`, the same cadence the engine arms commit at | Both sides flush at the same rate, so the comparison is not a comparison of flush cadences. On a pre-seeded backlog a fast arm may reach only one or two boundaries; that is maximum batching and it favours the reimplementer | +| **Source-offset commit** | **Included**, synchronous, *after* the flush | A restored dict with no resume point is not durability - you would rebuild the state and then reprocess from the beginning. Flush-then-commit is the ordering that makes the pair mean anything. It is ~10 synchronous calls per run and `commit_s` is reported separately so it can be seen not to dominate | +| **Changelog key** | the **state** key (`key|windowStart`), topic `cleanup.policy=compact` | This is what makes it a changelog rather than a log of deltas. Compaction is asynchronous and will not have run in a session this short, so **restore reads the uncompacted log** - an upper bound on restore time, stated rather than glossed | +| **What restore is measured as** | wall clock from asking the broker where the log ends to the dict being complete, **rebuilt entry count asserted** against `keys x multiplier` | Steady-state throughput and restart latency are different quantities and both matter, so restore is its own figure and is never folded into a rate | +| **Restore fetch config** | measured **twice**, on librdkafka's defaults and with `fetch.queue.backoff.ms=10` | A restore reads far more bytes than the arm that wrote them, so the stall that turned arm H's own rate into a 4.7x artefact (section above) can land here. Two configurations price it instead of arguing about it | + +#### Arms + +Interleaved within each repetition (KTD18 - in-session control arms, the whole reason the previous +two rounds exist). Host arms first, while no sidecar is up (`_shared_phase`'s inherited rule). + +| Arm | One term against `H-base` | Why it is here | +|---|---|---| +| **`H-base`** | - | The control. Plain arm H, unchanged. Without it in-session nothing else means anything | +| **`H-dur-per`** | changelog, one awaited record per state update | The naive reimplementer - what someone writes first | +| **`H-dur-coal`** | changelog, dirty set coalesced per 200 ms boundary | The careful reimplementer - Kafka Streams' state-store cache, hand-rolled | +| **`H-dur-nowait`** | the same changelog volume, `acks=0`, **flush moved outside the window** | Not durable, and here on purpose: a durable arm that is accidentally not durable looks wonderfully fast, and this prices exactly how fast | +| **`T0-cache`** | (engine) tumbling, cache 64 MB, crossing-free | The wrapper's best case at tumbling. Cache on, **changelog on** - so it is durable too, which is what makes this rung's comparison like-for-like for the first time | +| **`D-cache`** | (engine) hopping-12, cache 64 MB, crossing-free | The wrapper's best case at hopping-12 | +| **`D0`, `T0`** | (engine) the cache-off anchors | They tie this box to the two sessions above through `_F2_ANCHOR_RATES`; a disagreeing anchor is a finding about the box, reported and never tuned away | + +#### Pre-registered predictions + +Written before any arm ran, against the in-session figures the `f2-rerun` section reported +(`T0-cache` 169,748, `D-cache` 69,265, arm H tumbling 797,338, arm H hopping-12 460,026 rec/s). + +| # | Prediction | Predicted effect | +|---|---|---| +| 1 | `H-base` reproduces `f2-rerun`'s in-session arm H within ~1.5x, both specifications | tumbling 550k-1.1M, hopping-12 320k-620k rec/s | +| 2 | **`H-dur-per` at hopping-12 falls by more than 8x against `H-base`** - it produces 768,000 acked 1 KB records where `H-base` produces nothing, the same volume `D0` writes | 25,000-60,000 rec/s | +| 3 | **`H-dur-coal` is 3-8x faster than `H-dur-per`** at hopping-12: coalescing collapses 768,000 writes into at most 12,000 per boundary, the same trick the cache toggle bought 4.05x with | 120,000-300,000 rec/s | +| 4 | **The crossover INVERTS at hopping-12 for the naive reimplementer and NOT for the careful one.** `D-cache` overtakes `H-dur-per`; `H-dur-coal` stays 2-4x ahead of `D-cache` | wrapper wins one rung, loses the other | +| 5 | **Tumbling narrows but does not invert at either granularity** - one changelog record per record is a twelfth of the hopping volume | `H-dur-per` 100k-250k, `H-dur-coal` 300k-600k, both above `T0-cache` | +| 6 | **Restore of the per-update changelog at hopping-12 takes longer than the whole steady-state run it recovers** - 768,000 records of ~1 KB against a 64,000-record window | restore 1-10 s; coalesced restore shorter roughly in the ratio of records written | +| 7 | **`H-dur-nowait` lands within 1.5x of `H-base`** - i.e. essentially the entire durability cost is the awaited write, and an unawaited changelog would have looked almost free | the accounting error, priced | +| 8 | **Instrument check**: every awaited arm's changelog end offsets, summed off the broker, equal the records it produced exactly | 64,000 / 768,000 / one-per-boundary-per-dirty-entry | + +**Prediction 4 is the uncomfortable one and it is why this rung is worth running.** If it holds, the +first feature on the ladder is already enough to beat the naive reimplementer and nowhere near +enough to beat the careful one, and the crossover question becomes a question about *which +reimplementer* rather than about *how many features*. + +#### Conditions + +Matched to the established series so the numbers join it: **1,000 keys, 8 partitions, 1 KB +payloads, `commit.interval.ms` 200, 8 stream threads, in-memory window store, constant event time +past the epoch clamp, crossing-free engine arms (no host function registered at all)**. + +**64,000 records per arm**, both sides, the count `f2-rerun` used - and the count the ladder in the +section above places **below** the 80,000-96,000 fetch-stall threshold, so arm H runs on +librdkafka's default `fetch.queue.backoff.ms` and the guard in `measure_host` is left at full +strength rather than lowered to get a run through. **n=5 reps**, arms interleaved within each rep, +1-minute load recorded beside every run. + +**Nothing above this line changes after the first run; corrections land below as dated entries.** + +#### Measured results + +**Conditions.** Harness `streams_windowing_lab.py`, new experiment `crossing-ladder` +(`run_crossing_ladder`, arms in `_LADDER_ARMS`, engine arms in `_LADDER_ENGINE_ORDER`), which +reuses `measure_host`/`HostRun` and the engine-floor arms through `_run_floor_arm` rather than +restating either. Engine on Temurin 17.0.20+8 (resolved through `mise`) under the box's ambient +`JAVA_TOOL_OPTIONS` (`MaxRAM=48g`, `MaxRAMPercentage=20`, `ActiveProcessorCount=8`), Kafka Streams +3.9.2, compose broker `confluentinc/cp-kafka:7.9.0` on loopback `127.0.0.1:19100` (compose project +`pc-ladder`, started and torn down by this run alone), Python 3.13.5 with `confluent-kafka` 2.15.0 +(librdkafka 2.15.0), 32-core Linux box. 1,000 keys, 64,000 records, 8 partitions, 8 stream threads, +1 KB payloads, `commit.interval.ms` 200, in-memory window store, constant event time past the epoch +clamp. Every engine arm registered no host function and reported `crossings/rec=0.00` **measured** +client-side on all twenty runs. **Two passes of 5 reps, pooled to n=10 per arm**; 1-minute load read +and recorded beside every one of the 120 measured arm runs: **1.27-14.20, median 3.99**, against a +limit of 40, so no run ever waited. **The engine classpath was the one already built in this +worktree** (`parallel-consumer-proxy-streams/target/classes`), not rebuilt: a rebuild mid-session +would have contended with the measurement it was for. + +**No fetch-path stall was seen anywhere.** Every arm-H run at every rung reported **0 polls over +100 ms**, on librdkafka's default `fetch.queue.backoff.ms`, exactly as the record-count ladder in +the section above predicts for 64,000 records. **The guard was left at full strength and nothing +was lowered to get a run through.** + +**Deviations from the pre-registration, named rather than glossed:** + +- **Two 5-rep passes pooled to n=10, rather than one pass of 5.** The first pass's `T0-cache` + spread was 7x (40,000-289,593), so a second pass was run and both are pooled. The passes agree on + every arm that is not `T0-cache`; the second ran under a heavier ambient load (2.68-14.20 against + 1.27-4.62), which is where the wider min-max columns come from. +- **A harness bug aborted the first attempt at pass 2 and was fixed rather than worked around.** + The synchronous source-offset commit at the *final* boundary raises `_NO_OFFSET` whenever the + last batch had already triggered a boundary - "nothing new to commit", not a failed commit. It + now catches exactly that code and re-raises anything else. It cannot change a measured quantity: + a boundary that hits it does no commit, so it adds nothing to `commit_s`, and pass 1 (which never + hit it) and pass 2 agree. +- **`H-dur-per`'s reported `durable share` understates its own cost, by construction.** In + per-update mode the `produce()` calls happen inline in the fold loop, so they land in `fold_s` + and only the awaited flush and commit are counted in `produce_s`/`flush_s`/`commit_s`. The + decomposition below therefore prices the produce path from the arm difference + (`H-dur-nowait` - `H-base`), not from that column. +- **An arm the pre-registration named but did not size: `H-dur-coal`'s changelog volume varies with + the boundary count** (12,000-24,000 records per hopping-12 run, 1,000 per tumbling run). A run + that reaches two boundaries writes the dirty set twice. That is the arm behaving correctly and it + is why its changelog column is a range. +- **The kill-and-rebuild check ran as its own experiment** (`ladder-kill`, n=3) after both passes, + not interleaved. It carries no ratio - it exists to prove the durability is real under an + uncontrolled death, and interleaving a process kill inside the throughput passes would have put a + fresh JVM's worth of contention beside the arms it was supposed to leave alone. +- **The engine's own restore was not measured.** The wrapper arms are durable (changelog on) and + their restore path exists, but measuring it means restarting a Kafka Streams application and + waiting for `RUNNING`, which is a different instrument. **So the restore figures below are the + reimplementation's alone and are NOT a comparison** - stated here because a reader will reach + for one. +- **Restore reads the UNCOMPACTED changelog.** Compaction is asynchronous and does not run inside a + session this short. The consequence is quantified below rather than waved at. +- **`--load-limit 40`, not the harness default of 8**, as in all three sections above. +- **Broker on port 19100 in compose project `pc-ladder`**, torn down by this run alone. The + leftover `pcnumba-broker-1` on 19096 was left untouched. + +#### The engine arms, and the anchors + +Medians over 10 runs, min-max beside; rates in RECORDS per second on the sink's broker log-append +clock, with the committed-source-offset clock beside them. + +| Arm | rec/s (min-max) | us/rec | committed clock | emits (median) | +|---|---|---|---|---| +| **`T0-cache`** tumbling, cache 64 MB | **213,388** (40,000-289,593) | 4.7 | 230,921 | 1,188 | +| **`D-cache`** hopping-12, cache 64 MB | **73,442** (52,718-85,447) | 13.6 | 81,308 | 40,992 | +| `D0` hopping-12, cache off (anchor) | 20,637 (11,858-22,425) | 48.5 | 20,399 | 768,000 | +| `T0` tumbling, cache off (anchor) | 89,264 (78,049-97,710) | 11.2 | 95,881 | 64,000 | + +**The anchors reproduce, high and in the same direction**: `D0` 20,637 against the decomposition's +16,758 (**1.23x**) and `T0` 89,264 against 81,946 (**1.09x**), which is the same 10-20 percent +box-condition offset the `f2-rerun` section reported (1.19x and 1.11x). The wrapper arms reproduce +too: `D-cache` 73,442 here against `f2-rerun`'s 69,265 (**1.06x**). **`T0-cache` is the exception +and it is not new** - 213,388 here (40,000-289,593) against `f2-rerun`'s 169,748 (113,879-246,154). +That arm emits ~1,188 records for 64,000 inputs, so its log-append window is the spread of one or +two commit flushes and is quantised by the commit interval; its committed-offset clock agrees run +for run, so the variance is the engine's, not the clock's. **Every tumbling verdict below is +therefore stated with bands, not medians alone.** + +#### The ladder: arm H with one feature added back + +Medians over 10 runs, min-max beside, on this process's wall clock (arm H produces no sink, so +there is no log-append record of its progress). `fold-only` is the rate charging the aggregation +loop alone - the clock the bimodality section established as independent of the harness's polling. + +| Arm | Durability | rec/s (min-max) | us/rec | fold-only rec/s | changelog records/run | +|---|---|---|---|---|---| +| **tumbling** | | | | | | +| `H-base` | none (the control) | **831,476** (498,810-1,312,502) | 1.20 | 2,127,714 | 0 | +| `H-dur-per` | one awaited write per update | **327,385** (99,835-339,282) | 3.05 | 448,576 | 64,000 | +| `H-dur-coal` | dirty set per 200 ms boundary | **810,778** (444,543-1,059,461) | 1.23 | 1,568,833 | 1,000 | +| `H-dur-nowait` | same volume, `acks=0`, not awaited | 389,423 (334,816-421,742) | 2.57 | 580,380 | 64,000 | +| **hopping-12** | | | | | | +| `H-base` | none (the control) | **428,554** (322,677-494,424) | 2.33 | 537,002 | 0 | +| `H-dur-per` | one awaited write per update | **42,028** (27,716-44,117) | 23.79 | 43,136 | 768,000 | +| `H-dur-coal` | dirty set per 200 ms boundary | **282,575** (184,926-302,246) | 3.54 | 310,428 | 12,000-24,000 | +| `H-dur-nowait` | same volume, `acks=0`, not awaited | 45,922 (31,145-48,817) | 21.78 | 47,746 | 768,000 | + +`H-base` reproduces the `f2-rerun` session's in-session arm H at both specifications - 831,476 +against 797,338 (1.04x) at tumbling, 428,554 against 460,026 (0.93x) at hopping-12 - which is what +makes the rest of this table readable. + +#### What the durability term actually is, and it is not what the pre-registration assumed + +Read off the three arms that differ by one term each, at both specifications: + +| Term | tumbling (1 write/record) | hopping-12 (12 writes/record) | Per changelog write | +|---|---|---|---| +| `H-base` | 1.20 us/rec | 2.33 us/rec | - | +| **+ the changelog writes, unawaited** (`H-dur-nowait` - `H-base`) | **+1.37 us/rec** | **+19.44 us/rec** | **1.37 us / 1.62 us** | +| **+ awaiting them** (`H-dur-per` - `H-dur-nowait`) | +0.49 us/rec | +2.02 us/rec | - | +| **durability, naive, total** | +1.85 us/rec (**2.54x** slower) | +21.46 us/rec (**10.20x** slower) | - | +| **durability, coalesced, total** | +0.03 us/rec (**1.03x** slower) | +1.21 us/rec (**1.52x** slower) | - | + +**Prediction 7 is refuted, and the refutation is the finding of this rung.** The pre-registration +expected the awaited flush to dominate - "this choice will dominate the number" is the brief's own +wording, and it was written into the design table as such. It does not: at hopping-12 the awaited +`acks=all` flush plus the synchronous offset commit is **2.02 of 21.46 us/rec, 9 percent** of the +durability cost. **91 percent of it is the `produce()` calls themselves** - client-side per-record +work in the reimplementer's own process, before a byte reaches the broker. + +The two specifications price that call independently, at **1.37 us** (one write per record) and +**1.62 us** (twelve), from arms whose rates differ by an order of magnitude. **Nobody tuned the +harness to make those agree**, and they are the reason the naive rung collapses exactly in +proportion to the window multiplier: durability written per update costs the reimplementer *one +librdkafka produce call per (record x window)*, which is precisely the volume term the +decomposition above showed the engine's state-store cache deleting (`D-cache`, 4.05x). + +**So the first feature drags a second one in with it.** A reimplementer who adds durability the +obvious way must then also hand-roll the engine's cache to get back to where they started - and +`H-dur-coal` measures exactly that: coalescing recovers **19 of the 21.5 us**, leaving 1.21 us/rec +(1.52x) at hopping-12 and 0.03 us/rec (1.03x) at tumbling. + +#### Restore, as its own figure + +Medians over 10 restores each, rebuilt entry count asserted against `keys x multiplier` on every +one - a restore that does not reproduce the dict fails the run. + +| Arm | Spec | Changelog records read | Restore, default fetch config | Restore, `fetch.queue.backoff.ms=10` | Entries rebuilt | +|---|---|---|---|---|---| +| `H-dur-per` | tumbling | 64,000 | **0.103 s** (0.051-0.184) | 0.132 s (0.096-0.181) | 1,000 | +| `H-dur-coal` | tumbling | 1,000 | **0.031 s** (0.004-0.061) | 0.057 s (0.004-0.060) | 1,000 | +| `H-dur-per` | hopping-12 | 768,000 | **1.222 s** (0.448-1.391) | 0.708 s (0.449-1.349) | 12,000 | +| `H-dur-coal` | hopping-12 | 12,000-24,000 | **0.071 s** (0.022-0.279) | 0.076 s (0.012-0.300) | 12,000 | + +- **The naive changelog costs 17x the restore time of the coalesced one** at hopping-12 (1.222 s + against 0.071 s), for identical recovered state - 12,000 entries either way. The naive log holds + 768,000 records for 12,000 logical entries, **64x write amplification**, and an uncompacted + restore reads all of it. +- **Restore of the naive hopping-12 changelog takes 80 percent of the steady-state run that + produced it** (1.222 s against a 1.52 s window). **Prediction 6 is refuted, narrowly** - it + predicted longer, and it is not; it is the same order. +- **Compaction is the difference between a 1.2 s and a 0.07 s restart, and it did not run here.** + The figures above are the uncompacted upper bound. A compacted log holds one record per entry - + the coalesced arm's row is what that looks like. +- **The fetch stall did not bite the restore path**, and the second configuration is what says so: + `fetch.queue.backoff.ms=10` moves the largest figure from 1.222 s to 0.708 s and leaves the rest + inside their own spread, with 0 or 1 polls over 100 ms in every run. **Named as measured rather + than clean**: at 768 MB the default config is slower in the tail, which is the same fetcher race + the section above named, showing up as a restore cost instead of as a fake throughput. + +#### Kill and rebuild: does the state actually survive? + +`restore_host` on a complete changelog measures a rebuild; it does not prove the thing durability is +*for*. So the writer was run as a separate process and **SIGKILLed mid-run** - nothing flushed, +nothing closed, no `finally` ran - and the parent then rebuilt from whatever had reached the broker +(`ladder-kill`, `run_ladder_kill`, arm `H-dur-per` hopping-12, n=3): + +| Rep | Changelog records that survived the kill | Entries rebuilt | Restore | +|---|---|---|---| +| 1 | 276,000 of the 768,000 a complete run writes | **12,000 of 12,000** | 0.184 s | +| 2 | 272,883 | **12,000 of 12,000** | 0.414 s | +| 3 | 272,878 | **12,000 of 12,000** | 0.351 s | + +The full key space comes back because 1,000 keys are all touched within the first few thousand +records; what is *not* claimed is that the recovered values equal a completed run's. They are the +values as of the last awaited boundary, and the committed source offset is where processing +resumes - which is at-least-once, and is exactly the guarantee this rung buys. + +**And the check failed first, which is the more useful half.** At a 600 ms kill the writer had not +yet reached its first commit boundary: **0 changelog records survived and 0 entries were rebuilt**, +and `run_ladder_kill` refused the run rather than reporting a restore of nothing. **Durability has +a granularity of one commit interval** - state younger than the last boundary is gone - and that is +a property of the design registered above, not a fault in it. + +#### The instrument check, and what it returned + +Two halves, both direct rather than argued: + +- **The changelog end offsets, summed off the broker and compared with what each arm says it + produced.** Across all 40 durable runs, **every awaited arm matched exactly**: 64,000/64,000 and + 768,000/768,000 for `H-dur-per`, 1,000/1,000 and 12,000-24,000 matched for `H-dur-coal`. A + durable arm that was accidentally not durable would look wonderfully fast, and this is the check + that would have caught it. +- **`H-dur-nowait` is the negative control, and it failed the check on its own terms.** With + `acks=0` and the flush moved outside the window, one hopping-12 run of ten produced 768,000 + changelog records and left **758,486** on the broker - **9,514 records of state silently + lost**, with **zero** error delivery reports. An earlier smoke run at 8,000 records lost 1,070 of + 8,000 the same way. The mechanism is not established here and is not claimed; the observation is, + and it is what "a changelog you do not wait for is not durable" looks like when measured instead + of asserted. + +The wrapper-side instrument checks (`T0` -> `I0`, the crossing; `I0` -> `I1000`, the injected cost) +were **deliberately not re-run**: both were taken in the two sessions above, the crossing one moved +by 112-173 us against an independently fitted 135 us, and this rung moves no term on the wrapper +side. The check that had to be new is the durability one, and it is the one above. + +#### Predictions, confirmed and refuted + +| # | Prediction | Outcome | +|---|---|---| +| 1 | `H-base` reproduces `f2-rerun`'s arm H within ~1.5x | **confirmed** - tumbling 831,476 vs 797,338 (1.04x), hopping-12 428,554 vs 460,026 (0.93x) | +| 2 | `H-dur-per` at hopping-12 falls >8x, landing 25,000-60,000 rec/s | **confirmed** - 42,028 rec/s, a 10.20x fall | +| 3 | `H-dur-coal` is 3-8x faster than `H-dur-per` at hopping-12, 120,000-300,000 rec/s | **confirmed** - 282,575 rec/s, 6.72x faster, top of the band | +| 4 | The crossover **inverts at hopping-12 for the naive reimplementer and not for the careful one** | **confirmed, and with non-overlapping bands both ways** - `D-cache` 73,442 (52,718-85,447) against `H-dur-per` 42,028 (27,716-44,117), and against `H-dur-coal` 282,575 (184,926-302,246) | +| 5 | Tumbling narrows but does not invert; `H-dur-per` 100k-250k, `H-dur-coal` 300k-600k | **direction confirmed, magnitudes refuted HIGH** - 327,385 and 810,778, both above their bands. Neither inverts, but `H-dur-per` now **straddles** `T0-cache` rather than clearing it | +| 6 | Restore of the naive hopping-12 changelog takes longer than the run that produced it | **refuted, narrowly** - 1.222 s against a 1.52 s window, 80 percent of it | +| 7 | `H-dur-nowait` lands within 1.5x of `H-base` - the awaited write is essentially the whole cost | **REFUTED, badly, and it reframes the rung** - 9.33x from `H-base` at hopping-12. The awaited flush is **9 percent** of the durability cost; 91 percent is the `produce()` calls | +| 8 | Every awaited arm's changelog end offsets equal what it produced | **confirmed** - 40 of 40 runs exact | + +#### Where durability puts the crossover + +**This is the number the whole rung exists to produce.** Wrapper best case against each rung, at the +same specification, in the same session, interleaved. Bands are min-max; "clears" means +non-overlapping in the stated direction. + +| Specification | Wrapper | Rung | Reimplementation | **H / wrapper** | Band | +|---|---|---|---|---|---| +| hopping-12 | `D-cache` 73,442 | rung 0: `H-base`, non-durable | 428,554 | **5.84x** | reimplementation clears | +| hopping-12 | `D-cache` 73,442 | **rung 1a: durable, naive** | 42,028 | **0.57x** | **WRAPPER clears** | +| hopping-12 | `D-cache` 73,442 | **rung 1b: durable, coalesced** | 282,575 | **3.85x** | reimplementation clears | +| tumbling | `T0-cache` 213,388 | rung 0: `H-base`, non-durable | 831,476 | **3.90x** | reimplementation clears | +| tumbling | `T0-cache` 213,388 | **rung 1a: durable, naive** | 327,385 | **1.53x** | straddles | +| tumbling | `T0-cache` 213,388 | **rung 1b: durable, coalesced** | 810,778 | **3.80x** | reimplementation clears | + +**Stated plainly, because the brief asks for it plainly: durability alone does not close the gap.** + +- **Against a careful reimplementer it barely moves it.** At hopping-12 the gap goes 5.84x -> 3.85x, + which is **41 percent of the distance to parity**; at tumbling 3.90x -> 3.80x, **3 percent**. In + both cases the wrapper still loses, with non-overlapping bands. One feature, and the answer at + tumbling is *no measurable movement at all*. +- **Against a naive reimplementer it closes the gap and inverts it, at hopping-12.** 5.84x in the + reimplementation's favour becomes **1.75x in the wrapper's**, non-overlapping. At tumbling the + same rung takes 3.90x down to a straddle. So the first feature is already enough to beat the + reimplementer *who writes the obvious thing* - and the reason is not durability's inherent cost + but write volume, which the engine deduplicates and the naive reimplementer does not. +- **The crossover question is therefore not only "how many features" but "which reimplementer".** + The two rungs at the same feature differ by 6.7x and land on opposite sides of the wrapper. Every + later rung has to be quoted against both, or it is quoting whichever one flatters the answer. + +**What the next rung would have to be worth.** To close 3.85x at hopping-12 against the careful +reimplementer, the remaining features would have to cost it another **3.85x** - and durability, the +feature with the largest obvious per-record footprint on this list, bought **1.52x** when written +carefully. So on today's evidence the ladder does not converge on throughput grounds within the +features that remain (exactly-once, rebalance recovery, late-record handling, a real spilling state +store), unless one of them turns out to be structurally worse to hand-roll than durability was - +and the candidate for that is **exactly-once**, which forces a transactional producer and a +per-boundary commit the coalescing trick cannot amortise away. **That is the next rung to measure, +and it is now the one with the most to decide.** + +**What this does NOT license.** No claim here is about correctness, operability or effort - only +throughput and restart latency. `H-dur-coal` is 200 lines that get at-least-once durability right +for one topology under no rebalances; the wrapper gets it for any topology under all of them. The +strategic write-up's title claim is untouched: what this rung adds is that **the first feature on +the ladder moves the number by 41 percent of the way at one specification and 3 percent at the +other**, and that a comparison against "a reimplementation" is meaningless until it says *which*. + +#### What is not settled + +- **`T0-cache`'s variance.** 40,000-289,593 across ten runs, agreeing on the committed-offset clock, + so it is the engine's and not the clock's. At ~1,188 emits per 64,000 records its window is one or + two commit flushes. Every tumbling figure above is quoted with its band for that reason, and the + tumbling median should not be cited alone. **What would settle it:** an emit-count-independent + clock for the cache-on tumbling arm, or a record count large enough to span many commit intervals + - which at this specification runs into the fetch-stall threshold on the host side. +- **The engine's restore was not measured**, so the restore figures are one-sided. A like-for-like + restart comparison needs a Kafka Streams application restarted to `RUNNING` against the same + state, and that is a different instrument. +- **`H-dur-nowait`'s lost records.** 9,514 of 768,000 in one run of ten, 1,070 of 8,000 in a smoke + run, zero error delivery reports in both. The mechanism is not established - it is reported as an + observation that `acks=0` silently dropped state, which is all this rung needs it for. +- **One box, one broker, one container.** As in all three sections above, the broker's write + bandwidth is visibly the binding constraint on the cache-off arms, and the durable arms write into + the same single container. diff --git a/docs/inflight/perf-streams-under-native-image.md b/docs/inflight/perf-streams-under-native-image.md new file mode 100644 index 0000000000..d3760b29ee --- /dev/null +++ b/docs/inflight/perf-streams-under-native-image.md @@ -0,0 +1,203 @@ +# Kafka Streams under GraalVM native-image - the ladder's named companion gap + + + + +**Branch: `perf/242-crossing-cost-ladder`.** +[`branch-crossing-cost-ladder.md`](branch-crossing-cost-ladder.md) **owns why this probe exists**: +the ladder measures call mechanics under libjvm-or-native assumptions, and it names this as the gap +that a green ladder does not close - *Kafka Streams has never run under GraalVM here*. Two routes +need one of them proven: (1) native-image including Kafka Streams, (2) libjvm embedding. This note +settles route (1) for the PoC surface only. + +**Scope choice, stated up front because it changes what the result licenses.** +`parallel-consumer-proxy-streams` uses **in-memory stores only** - +`TopologyAssembler` builds every materialisation with `Stores.inMemoryKeyValueStore`. So the classic +RocksDB-JNI blocker is out of scope by construction, not by being solved. **RocksDB remains an +unprobed cliff for any durable-state future** - see +[`core-rocksdb-works-on-the-jvm-sidecar.md`](core-rocksdb-works-on-the-jvm-sidecar.md). + +## Pre-registered predictions, written before the first build + +Recorded 2026-08-25, before any native-image invocation. House falsification style: the point is +that the misses are visible afterwards, not that the guesses were good. + +| # | Prediction | Confidence | +|---|---|---| +| P1 | The image **builds**. In-memory stores mean no `org.rocksdb` native library is needed at run time, and reachability of `RocksDBStore` costs size, not a build failure | high | +| P2 | The build **needs a new metadata capture**. The sidecar's shipped `META-INF/native-image/reachability-metadata.json` traced a PC-core session and knows nothing about Streams | high | +| P3 | The wall, if there is one, is at **run time inside `new KafkaStreams(...)` or `streams.start()`**, not at build time - Streams resolves serdes, the timestamp extractor, both exception handlers, the partition assignor and the client supplier **from configuration strings**, exactly the shape that broke the sidecar's `Configure` | high | +| P4 | **Logging is the build-time obstacle again**, not Netty or Kafka - the sidecar's five-attempt log says every blocker was logback/SAX, and gRPC-netty-shaded raised nothing | medium | +| P5 | **GraalVM 25 may reject the inherited `--initialize-at-build-time=ch.qos.logback,...` list.** That recipe was captured on Oracle GraalVM 23; strict image heap is the default from 24 onward, which is the same mechanism that produced attempt 4's `LocatorImpl` in the image heap | medium | +| P6 | **No dynamic-proxy blocker.** Kafka Streams' hot path is plain classes; the JMX/metrics surface registers concrete MBeans rather than `Proxy` instances | medium | +| P7 | Binary **110-150MB** (sidecar was 79MB; kafka-streams plus its state-store and assignor machinery is the delta), build **2-5 minutes** on this box | low | +| P8 | Startup to the `port:` line **under 200ms native vs 1-3s JVM** - the same order the sidecar showed, and the one number this probe can quote honestly at 200 records | medium | +| P9 | The demo's **assertions pass unchanged if it starts at all** - once the topology is assembled the record path is bytes in, bytes out over gRPC, and nothing on it is reflective | medium | +| P10 | **`num.stream.threads` and the state-directory lock are not a problem.** Streams' `StateDirectory` uses ordinary file locks, which Substrate supports | medium | + +**The prediction I most expect to be wrong** is P3's *precision*: I expect a runtime failure, but I +expect to be wrong about *which* class it names first, and the tracing agent - not reading - is what +finds it. That is the sidecar note's transferable lesson, and it is why the trace has to run over a +**real** demo session rather than a start-and-stop. + +**What would falsify the whole route** (as opposed to costing another metadata entry): a Streams +internal that needs a class name computed at run time from something the trace cannot enumerate, or +a build-time initialisation cycle that neither `--initialize-at-run-time` nor a metadata entry can +break. Anything fixable by adding entries is *cost*, not a wall. + +## Result: Kafka Streams RUNS under native-image, and the Python demo passed against it + +Measured 2026-08-25 on Linux/x86-64, GraalVM CE 25.0.2, box under ordinary load (`load average` +7-12 of 32 cores). **The existing Python Streams demo, unchanged in what it asserts, passed against +a native executable with no JVM in it:** + +``` +Keys expected 400 +Keys matching exactly 400 +Python invocations 400 +Consumer group STABLE/1 for all 3 samples after joining +OK - 400 keys counted correctly by a topology described entirely from Python +``` + +`ldd` on the binary lists `libz`, `libc` and the loader - **no `libjvm`, no `libjava`**. Combined +with `--no-fallback`, that is the check that this is a real image rather than a fallback that still +needs a JVM. + +| | JVM engine (Temurin 17) | native engine | | +|---|---|---|---| +| startup to the `port:` line | 317 / 336 / 330ms | **14 / 16 / 14ms** | ~22x, 3 runs each | +| demo end to end, 400 records | 2.0s | 1.4s | startup-dominated | +| artifact | classpath of 44 jars | **78MB** executable | | +| build | - | 53s | | + +**No throughput claim is available from this.** 400 records is startup-dominated, the box was +shared, and the per-invocation figures (1662us JVM against 1394us native) differ by less than the +run-to-run spread on a loaded box. The startup number is the only one worth quoting, and it is the +one that matters for an embedded engine anyway. + +## The wall, and it was exactly where the sidecar's was + +The **first** build - no traced metadata, only what ships on the classpath - **built fine in 41s +(41.7MB)**, started, bound gRPC, and **assembled the topology correctly** (the demo printed the +`Topologies:` description the engine produced). It then died the moment the topology was started: + +``` +Exception in thread "grpc-default-executor-0" java.lang.ExceptionInInitializerError + at org.apache.kafka.streams.KafkaStreams.(KafkaStreams.java:833) +Caused by: org.apache.kafka.common.config.ConfigException: Invalid value + org.apache.kafka.streams.errors.LogAndFailExceptionHandler for configuration + default.deserialization.exception.handler: Class ... could not be found. + at org.apache.kafka.common.config.ConfigDef.parseType(ConfigDef.java:778) + at org.apache.kafka.streams.StreamsConfig.(StreamsConfig.java:921) +``` + +**The failing frame is `StreamsConfig.`, and that is the transferable part.** It is not a +serde resolved from a user's configuration - it is Kafka Streams' own `ConfigDef` **defaults**, +which are class *names* validated by loading them while the config class initialises. So the very +first thing Streams does resolves a dozen classes by string, and closed-world analysis sees none of +them. Same mechanism as the sidecar's `Configure` failure, one layer earlier. + +Fixed by one traced capture and one rebuild - **no flag changes, no `--initialize-at-run-time`, no +substitutions.** + +## The recipe that worked + +``` +native-image --no-fallback -cp :<44 runtime jars> \ + --initialize-at-build-time=ch.qos.logback,org.slf4j,org.xml.sax,com.sun.org.apache.xerces,javax.xml \ + -H:ConfigurationFileDirectories= \ + bz.stub.parallelconsumer.streams.StreamsMain +``` + +Two scripts carry it, and neither invents a build system - both wrap what the sidecar and the +`--shared` build already do: + +- **`ffi/crossing-ladder/build-streams-native.sh`** - the build. The `--initialize-at-build-time` + list is inherited verbatim from the sidecar's recipe. +- **`ffi/crossing-ladder/trace-streams-engine.sh`** - a `java` stand-in that runs the engine under + the tracing agent, reached through the demo's own `PC_DEMO_JAVA`. `config-merge-dir`, so several + traced sessions accumulate into one config. + +The capture it produced is kept at +`ffi/crossing-ladder/streams-native/trace/reachability-metadata.json` (23KB, 179 types); the +directory's `.gitignore` keeps the 78MB binary out while keeping that. **It is the expensive half: +it needs a broker, a real demo run and the agent, and the build is a minute once you have it.** + +**The demo needed one seam to launch a binary**, and it is the seam the comparison demo already +had: `streams_demo.py` now resolves `PC_DEMO_STREAMS_ENGINE` (an absolute binary) before falling +back to `PC_DEMO_STREAMS_CLASSPATH` plus `java`, mirroring `reference_demo.py`'s +`PC_DEMO_SIDECAR` / `PC_DEMO_SIDECAR_CLASSPATH` pair exactly. + +## Predictions scored + +| # | Prediction | Outcome | +|---|---|---| +| P1 | image builds | **confirmed** - first attempt, 41s, no flag hunting | +| P2 | needs a new metadata capture | **confirmed** - and it is the ONLY thing that was needed | +| P3 | wall at run time in `new KafkaStreams`/`start()`, from config strings | **confirmed in mechanism, wrong in target** - it is `StreamsConfig.` resolving its own `ConfigDef` defaults, before any user serde is looked at. The shape was right; the class was not, which is why the agent found it and reading would not have | +| P4 | logging is the build-time obstacle | **refuted** - nothing blocked the build at all. Inheriting the sidecar's init list meant the logging problem was already paid for | +| P5 | GraalVM 25's strict image heap rejects the inherited list | **refuted** - CE 25.0.2 accepted it unchanged. The macOS/Oracle-23 recipe transferred to Linux/CE-25 verbatim | +| P6 | no dynamic-proxy blocker | **confirmed** (nothing surfaced) | +| P7 | 110-150MB, 2-5 min | **refuted, and by a lot** - 78MB and 53s with metadata; 41.7MB and 41s without. Kafka Streams cost ~36MB and 12s over the un-traced build. The sidecar's 79MB was for PC core alone, so **the whole Streams engine fits in the size budget the sidecar already established** | +| P8 | startup under 200ms native, 1-3s JVM | **confirmed on the native side (14ms), refuted on the JVM side (330ms)** - this engine is a gRPC listener that starts no Kafka client until a session opens, so the JVM's cost here is much lower than a sidecar's | +| P9 | demo assertions pass unchanged | **confirmed** | +| P10 | state directory and threads fine | **confirmed** for in-memory stores, one stream thread | + +Wrong on 4 of 10, including both of the ones about where the difficulty would be. **The build was +the easy half and the metadata was the whole of the difficulty**, which is the sidecar note's +lesson arriving intact one module later. + +## What this does NOT prove + +- **In-memory stores only, and that is a PoC scope choice, not a solved problem.** `RocksDB` under + native-image is untouched here: `rocksdbjni` is on the classpath but nothing on this path reaches + it, so its JNI library was never loaded. **Any durable-state future re-opens this as an unprobed + cliff** - see [`core-rocksdb-works-on-the-jvm-sidecar.md`](core-rocksdb-works-on-the-jvm-sidecar.md). +- **One happy path traced, exactly as the sidecar's capture was.** Two attempts to walk the failure + arm (`--function-delay-ms 60` over 100 records, then 150ms over 600) produced **no reflection + failure and no eviction** - the second simply ran out of demo timeout. So the rebalance and + eviction paths are **unprobed under native image**, not proven. The trace also never walked a + windowed store, a join, or an interactive query. +- **One topology shape**: source -> mapValues -> groupByKey -> count -> to. `TopologyAssembler` + supports more than the demo describes. +- **Linux/x86-64 only**, one Kafka version (3.9.2), `num.stream.threads=1`. +- **Nothing about `--shared`.** This is an executable. The `--shared` build has its own entry-point + surface, and the reflection-inheritance question was settled for the PC core library + ([`perf-embedding-the-engine-over-ffi.md`](perf-embedding-the-engine-over-ffi.md)) but not for + this classpath. + +## What it means for the two embedding routes + +[`branch-crossing-cost-ladder.md`](branch-crossing-cost-ladder.md) names the write-up's obligation: +say which route it assumes. **Route (1), native-image including Kafka Streams, is no longer +unproven - it is the cheaper of the two on this evidence.** The engine builds in under a minute +into a 78MB self-contained binary that starts in 14ms and counts correctly, and getting there cost +one tracing run and zero build-flag archaeology; the metadata approach the fork already uses for PC +core carried over without modification. That matters more than the size or the speed, because it +means the Streams fast path can be built on the **same** artifact pipeline as the `--shared` +library the FFI work already produces, rather than forking the toolchain. **Route (2), libjvm +embedding, is now the fallback rather than the likely answer** - its advantages (JIT retained, no +closed-world analysis, no metadata to maintain) are real but they are paid for with a JVM inside +the host process, and the only one of those advantages this probe found a use for is the metadata +maintenance, which is a real ongoing cost rather than a one-off. **The honest boundary is +durability**: everything above holds for in-memory stores. If a durable-state Streams engine is +ever in scope, RocksDB's JNI surface has to be probed before route (1) can be assumed again, and +that is exactly the point at which libjvm embedding stops being the fallback and becomes the +question again. + +## Prior art this builds on + +Checks run before this probe, and what each returned: + +- `ls docs/plans/` + grep for `native-image` - `2026-08-22-001-feat-shared-c-transport-plan.md` + and `2026-08-22-002-feat-kafka-streams-foreign-wrappers-plan.md`; neither had built Streams + natively. +- `grep -rl` over `docs/solutions/` for `native-image` - **nothing**. +- `grep -rl` over `docs/inflight/` - the two notes this builds on, plus + `core-rocksdb-works-on-the-jvm-sidecar.md`, `parked-a-c-client-and-the-ffi-question.md` and + `next-kafka-streams-foreign-wrappers.md`. +- [`perf-native-image-sidecar-works.md`](perf-native-image-sidecar-works.md) - the build recipe, + the five-attempt log, and the "only the agent could fix it" finding, all of which transferred. +- [`perf-embedding-the-engine-over-ffi.md`](perf-embedding-the-engine-over-ffi.md) - the `--shared` + build and the classpath-discovered metadata that covered it unchanged. + diff --git a/docs/inflight/perf-streams-windowing-multiplier.md b/docs/inflight/perf-streams-windowing-multiplier.md index 496bb013c1..bbb8df5e35 100644 --- a/docs/inflight/perf-streams-windowing-multiplier.md +++ b/docs/inflight/perf-streams-windowing-multiplier.md @@ -558,3 +558,44 @@ premise, at the loads named above. 3. **The U8 follow-up about the test's "default 200ms" comment is closed**: this branch already corrected `WindowedAggregatorCallCountTest`'s comment to the verified figures (1000ms engine default; TTD overrides to zero), so no follow-up remains. + +### Dated correction, 2026-08-25 (second) - arm H's hopping-12 figure was a stalled consumer + +**`89,821 rec/s` (arm H, hopping-12, 128,000 records, n=4) does not measure the reimplementation. +It measures librdkafka's fetch path stalling.** Settled by the `host-bimodal` arm set - five +pre-registered hypotheses, observational pass before any toggle - recorded in +[`perf-streams-engine-floor.md`](perf-streams-engine-floor.md) under "Why arm H's hopping-12 rate +is bimodal". The mechanism: once the consumer's local queue passes `queued.max.messages.kbytes` +(64 MB, about 85,000 of these records), librdkafka stops fetching and postpones the next fetch by +`fetch.queue.backoff.ms`, 1,000 ms by default. The fold loop drains the queue, finds it empty, and +blocks inside `consume()` for the remainder - **78-81 percent of that timed window was fetch wait, +not aggregation**, and `records / (ended - started)` charges the wait to the rate. + +**The threshold sits between 80,000 and 96,000 records**, which is why the figure looked bimodal +rather than simply wrong: the 64,000-record runs elsewhere in this program are below it and clean, +and U6's 128,000-record runs are above it. Corrected at U6's own conditions through U6's own +experiment with one term moved, **arm H reads 393,855-433,285 rec/s** - 4.4-4.8x the recorded +figure. CPython's cyclic collector, a cold-read effect and box contention were each pre-registered +and each refuted with their own arm; the collector, the leading suspect, moves the rate 1.01x with +it demonstrably off. + +**What this changes, and it is not the verdict.** The hopping bet is still OFF, and by a wider +margin than recorded: arm B's max 725 rec/s against a corrected hopping-H of ~393,855 fails F2 by +roughly **540x**, not ~122x. **So entry 2 above is superseded on its number** - the ~122x/~125x +discussion is moot, both because its denominator was stalled and because the corrected margin is +five times larger either way. The tumbling figure (`723,265 rec/s`, 128,000 records) is **not** +affected: the stall is a fetcher-versus-consumer race that tumbling at this record count wins, and +the guard below only fires on that arm at 192,000 records. + +**Enforced rather than documented, per the repo's rule:** `measure_host` now raises when its timed +window contains a `consume()` call over 100 ms, naming the mechanism, the position and the lever +(`--host-fetch-queue-backoff-ms`). Re-running `host-reimpl` at U6's exact conditions now **fails** +with that diagnosis instead of silently averaging over the stall. **Any future run of `f2-rerun` +or `placement` above the threshold will now hard-fail** - that is the intent, not a regression. + +**Not settled:** why a previous session's three standalone 128,000-record runs came out 2-of-3 +fast, where 98 of 98 untouched runs stalled here. The mechanism explains how it could (anything +depressing the fetcher removes the stall) and the tumbling arm demonstrates the race in-session, +but no fast untouched 128,000-record run was reproduced. What would settle it is named in the +engine-floor note: the record-count ladder against a broker under concurrent read load, with the +fetcher's delivery rate recorded per run. diff --git a/docs/solutions/architecture-patterns/a-per-record-crossing-loses-to-reimplementation-before-features-enter.md b/docs/solutions/architecture-patterns/a-per-record-crossing-loses-to-reimplementation-before-features-enter.md index bd9794829c..90f9e9c778 100644 --- a/docs/solutions/architecture-patterns/a-per-record-crossing-loses-to-reimplementation-before-features-enter.md +++ b/docs/solutions/architecture-patterns/a-per-record-crossing-loses-to-reimplementation-before-features-enter.md @@ -69,3 +69,34 @@ than an entire native hopping topology. - **`TopologyTestDriver` over-counts cached emissions** (commits - and so flushes - per record); broker-vs-TTD emit counts only agree under close-driven emit rules (suppression, `EmitStrategy.onWindowClose()`). + +## Correction, 2026-08-25 (second): the 122x was a stalled consumer, and the floor itself was mis-specified + +Two later rounds changed what the numbers above are worth. Neither overturns the pattern; both +sharpen what it may be cited for. Full workings in +`docs/inflight/perf-streams-engine-floor.md` and the second dated correction in +`docs/inflight/perf-streams-windowing-multiplier.md`. + +**The hopping figure was an instrument artefact.** `122x` divided by an arm-H hopping rate of +89,821 rec/s that was not measuring the reimplementation at all: at 128,000 records the consumer's +local queue passes `queued.max.messages.kbytes`, librdkafka stops fetching and postpones the next +fetch by `fetch.queue.backoff.ms` (1,000 ms), and 78-81 percent of the timed window became fetch +wait charged to the rate. Corrected, arm H reads 393,855-433,285 rec/s and the margin widens to +roughly **540x**. **The tumbling 69x is unaffected** - that arm sits on the winning side of the +same fetcher race at this record count. Cited as a method finding: **an arm whose rate is a +division by elapsed time will silently price a stall as throughput**, and the harness now raises +rather than averaging - `measure_host` fails any window containing a `consume()` over 100 ms. + +**The larger correction is to the floor, not the figure.** F2 was defined as *whatever a stateless +single-threaded reimplementation measures* - no store, no changelog, no restore, no rebalance +recovery, no exactly-once. That is the floor for a product Kafka Streams is not in the business of +being, so the comparison answers *"can a toy beat an engine at toy work"*, which it can at any +transport speed. Removing the crossing entirely does **not** invert it: with sub-microsecond +crossings available (747ns GraalWasm, 19.9ns Numba `@cfunc`) and the engine's own state-store cache +on, the wrapper reaches 69,265 / 169,748 rec/s and still loses 6.64x / 4.70x in-session. + +**So this write-up's title is the durable claim and its numbers are not the argument for it.** The +question that decides the design is the crossover named in the title - *how many of the features a +user actually came for can be added back to the reimplementation before hand-rolling becomes the +worse choice* - and no figure here measures it. That measurement is under way, one feature at a +time, starting with durability. diff --git a/ffi/crossing-ladder/.gitignore b/ffi/crossing-ladder/.gitignore new file mode 100644 index 0000000000..778ba7a0d8 --- /dev/null +++ b/ffi/crossing-ladder/.gitignore @@ -0,0 +1,5 @@ +# build outputs - each source file's header carries its build command +libfold.so +fold.wasm +*.class +graal/target/ diff --git a/ffi/crossing-ladder/GraalPyBench.java b/ffi/crossing-ladder/GraalPyBench.java new file mode 100644 index 0000000000..33392c21d0 --- /dev/null +++ b/ffi/crossing-ladder/GraalPyBench.java @@ -0,0 +1,127 @@ +/* + * Copyright (C) 2026 Antony Stubbs and contributors + * + * Crossing-cost ladder arm (e): a Python function called through the GraalPy polyglot + * API from a JVM host. Measures, post-warmup: no-op call, the 1KB fold over HOST byte + * arrays (every element access crosses the interop boundary - the honest shape when the + * engine owns the bytes), the fold over a GUEST-staged bytearray (pure call overhead + + * guest compute, parallel to the wasm staged arm), and the calibrated ~1us spin + * instrument check. See docs/inflight/perf-crossing-cost-ladder.md. + * + * Run on the GraalVM 25 JDK with the graal/target/deps2502 classpath (matching polyglot + * version, so Truffle compiles rather than interprets). + */ +import java.lang.management.ManagementFactory; +import java.util.Arrays; + +import org.graalvm.polyglot.Context; +import org.graalvm.polyglot.Engine; +import org.graalvm.polyglot.Value; + +public class GraalPyBench { + + static double median(double[] a) { + double[] c = a.clone(); + Arrays.sort(c); + return c[c.length / 2]; + } + + static double p99(double[] a) { + double[] c = a.clone(); + Arrays.sort(c); + return c[Math.max(0, (int) (c.length * 0.99) - 1)]; + } + + interface Callee { void call(); } + + static double[] bench(Callee c, int warmup, int batches, int n) { + for (int i = 0; i < warmup; i++) c.call(); + double[] perBatch = new double[batches]; + for (int b = 0; b < batches; b++) { + long t0 = System.nanoTime(); + for (int i = 0; i < n; i++) c.call(); + perBatch[b] = (System.nanoTime() - t0) / (double) n; + } + return perBatch; + } + + static double report(String label, double[] perBatch) { + System.out.printf("%-38s median %10.1f ns/call p99 %10.1f batches %d%n", + label, median(perBatch), p99(perBatch), perBatch.length); + return median(perBatch); + } + + static final String PY = """ + def noop(key, val, acc): + return 0 + + def fold(key, val, acc): + n = min(len(val), len(acc)) + k = key[0] if len(key) else 0 + for i in range(n): + v = (acc[i] + val[i] + k) & 0xFF + acc[i] = v - 256 if v > 127 else v # host byte[] elements are signed + return acc[n - 1] + + GUEST_VAL = bytearray(b'v' * 1024) + GUEST_ACC = bytearray(1024) + + def fold_guest(key_byte): + n = 1024 + for i in range(n): + GUEST_ACC[i] = (GUEST_ACC[i] + GUEST_VAL[i] + key_byte) & 0xFF + return GUEST_ACC[n - 1] + + def fold_spin(key, val, acc, count): + r = fold(key, val, acc) + s = acc[0] & 0xFF + for i in range(count): + s = (s * 31 + i) & 0xFF + acc[0] = s - 256 if s > 127 else s + return r + """; + + public static void main(String[] args) { + int warmup = 100_000, batches = 30, n = 5_000; + Context ctx = Context.newBuilder("python").allowAllAccess(true).build(); + ctx.eval("python", PY); + Value bind = ctx.getBindings("python"); + Value noop = bind.getMember("noop"); + Value fold = bind.getMember("fold"); + Value foldGuest = bind.getMember("fold_guest"); + Value foldSpin = bind.getMember("fold_spin"); + + byte[] key = new byte[16]; + byte[] val = new byte[1024]; + byte[] acc = new byte[1024]; + Arrays.fill(key, (byte) 'k'); + Arrays.fill(val, (byte) 'v'); + + System.out.printf("load: %.2f warmup %d calls/arm (fold arms %d), %d batches x %d (polyglot %s)%n", + ManagementFactory.getOperatingSystemMXBean().getSystemLoadAverage(), + warmup, warmup / 5, batches, n, Engine.create().getVersion()); + + report("(e) graalpy no-op", bench(() -> noop.execute(key, val, acc), warmup, batches, n)); + double mFold = report("(e) graalpy fold (host byte[])", + bench(() -> fold.execute(key, val, acc), warmup / 5, batches, n)); + report("(e) graalpy fold (guest bytearray)", + bench(() -> foldGuest.execute(107), warmup / 5, batches, n)); + + int count = 0; + double delta = 0; + for (int c : new int[]{4000, 8000, 16000, 32000, 64000, 128000}) { + count = c; + final int fc = c; + double[] d = bench(() -> foldSpin.execute(key, val, acc, fc), 5_000, 10, n); + delta = median(d) - mFold; + if (delta >= 900) break; + } + System.out.printf("calibrated spin count %d -> ~%.0f ns extra%n", count, delta); + final int fc = count; + double mSpin = report("(e) graalpy fold+~1us spin", + bench(() -> foldSpin.execute(key, val, acc, fc), 5_000, batches, n)); + System.out.printf("(e) instrument-check delta: %.1f ns (expect ~1000, spin calibrated to %.0f)%n", + mSpin - mFold, delta); + ctx.close(); + } +} diff --git a/ffi/crossing-ladder/GraalWasmBench.java b/ffi/crossing-ladder/GraalWasmBench.java new file mode 100644 index 0000000000..53e9d569fa --- /dev/null +++ b/ffi/crossing-ladder/GraalWasmBench.java @@ -0,0 +1,118 @@ +/* + * Copyright (C) 2026 Antony Stubbs and contributors + * + * Crossing-cost ladder arm (f), the PRIMARY candidate per owner direction: a WASM UDF + * called through the GraalWasm polyglot API from a JVM host. Measures, post-warmup: + * no-op export call, the 1KB fold with bytes STAGED in wasm linear memory (f1 - call + * overhead + wasm compute), the fold with 1KB copied into wasm memory per call through + * the polyglot buffer API (f2 - what unstaged data handoff costs), and the calibrated + * ~1us spin instrument check. See docs/inflight/perf-crossing-cost-ladder.md. + * + * Run on the GraalVM 25 JDK with the graal/target/deps classpath (Truffle needs the + * Graal compiler to reach peak; on a stock JDK it interprets). + */ +import java.io.IOException; +import java.lang.management.ManagementFactory; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Arrays; + +import org.graalvm.polyglot.Context; +import org.graalvm.polyglot.Source; +import org.graalvm.polyglot.Value; +import org.graalvm.polyglot.io.ByteSequence; + +public class GraalWasmBench { + + static double median(double[] a) { + double[] c = a.clone(); + Arrays.sort(c); + return c[c.length / 2]; + } + + static double p99(double[] a) { + double[] c = a.clone(); + Arrays.sort(c); + return c[Math.max(0, (int) (c.length * 0.99) - 1)]; + } + + interface Callee { void call(); } + + static double[] bench(Callee c, int warmup, int batches, int n) { + for (int i = 0; i < warmup; i++) c.call(); + double[] perBatch = new double[batches]; + for (int b = 0; b < batches; b++) { + long t0 = System.nanoTime(); + for (int i = 0; i < n; i++) c.call(); + perBatch[b] = (System.nanoTime() - t0) / (double) n; + } + return perBatch; + } + + static double report(String label, double[] perBatch) { + System.out.printf("%-36s median %10.1f ns/call p99 %10.1f batches %d%n", + label, median(perBatch), p99(perBatch), perBatch.length); + return median(perBatch); + } + + public static void main(String[] args) throws IOException { + int warmup = 200_000, batches = 30, n = 20_000; + byte[] wasmBytes = Files.readAllBytes(Path.of(args.length > 0 ? args[0] : "fold.wasm")); + Context ctx = Context.newBuilder("wasm").allowAllAccess(true).build(); + Source src = Source.newBuilder("wasm", ByteSequence.create(wasmBytes), "fold").build(); + Value module = ctx.eval(src); + Value exports; + if (module.canInstantiate()) { + exports = module.newInstance().getMember("exports"); + } else { + exports = ctx.getBindings("wasm").getMember("fold"); // older API: instance in bindings + } + Value noop = exports.getMember("noop"); + Value fold = exports.getMember("fold"); + Value foldSpin = exports.getMember("fold_spin"); + Value memory = exports.getMember("memory"); + int bp = exports.getMember("buf_ptr").execute().asInt(); + int keyOff = bp, valOff = bp + 16, accOff = bp + 1040; + + // stage key + value bytes into wasm linear memory once (f1's premise) + for (int i = 0; i < 16; i++) memory.writeBufferByte(keyOff + i, (byte) 'k'); + for (int i = 0; i < 1024; i++) memory.writeBufferByte(valOff + i, (byte) 'v'); + + System.out.printf("load: %.2f warmup %d calls/arm, %d batches x %d (polyglot %s)%n", + ManagementFactory.getOperatingSystemMXBean().getSystemLoadAverage(), warmup, batches, n, org.graalvm.polyglot.Engine.create().getVersion()); + + double mNoop = report("(f) graalwasm no-op", + bench(() -> noop.execute(keyOff, 16, valOff, 1024, accOff, 1024), warmup, batches, n)); + double mFold = report("(f) graalwasm fold (bytes staged)", + bench(() -> fold.execute(keyOff, 16, valOff, 1024, accOff, 1024), warmup, batches, n)); + + // calibrate the spin chain to ~1us + int count = 0; + double delta = 0; + for (int c : new int[]{4000, 8000, 16000, 32000, 64000, 128000}) { + count = c; + final int fc = c; + double[] d = bench(() -> foldSpin.execute(keyOff, 16, valOff, 1024, accOff, 1024, fc), + 20_000, 10, n); + delta = median(d) - mFold; + if (delta >= 900) break; + } + System.out.printf("calibrated spin count %d -> ~%.0f ns extra%n", count, delta); + final int fc = count; + double mSpin = report("(f) graalwasm fold+~1us spin", + bench(() -> foldSpin.execute(keyOff, 16, valOff, 1024, accOff, 1024, fc), 20_000, batches, n)); + System.out.printf("(f) instrument-check delta: %.1f ns (expect ~1000, spin calibrated to %.0f)%n", + mSpin - mFold, delta); + + // f2: per-call 1KB copy through the polyglot buffer API, then the fold + byte[] hostVal = new byte[1024]; + Arrays.fill(hostVal, (byte) 'v'); + double mF2 = report("(f2) graalwasm 1KB copy/call + fold", + bench(() -> { + for (int i = 0; i < 1024; i++) memory.writeBufferByte(valOff + i, hostVal[i]); + fold.execute(keyOff, 16, valOff, 1024, accOff, 1024); + }, 50_000, batches, n)); + System.out.printf("(f2) copy overhead over staged fold: %.1f ns%n", mF2 - mFold); + ctx.close(); + } +} diff --git a/ffi/crossing-ladder/QueueHandoffBench.java b/ffi/crossing-ladder/QueueHandoffBench.java new file mode 100644 index 0000000000..6f1f9adce7 --- /dev/null +++ b/ffi/crossing-ladder/QueueHandoffBench.java @@ -0,0 +1,89 @@ +/* + * Copyright (C) 2026 Antony Stubbs and contributors + * + * Crossing-cost ladder arm (b): the in-process queue handoff - the embedded pull seam's + * shape. Two threads; the caller offers a request through a SynchronousQueue and blocks + * for the response on a second SynchronousQueue; the worker loops take -> fold -> put. + * One round trip = one host-function crossing under the pull model. Measures no-op, the + * 1KB fold, and the ~1us busy-wait instrument check, as ns/round-trip distributions. + * See docs/inflight/perf-crossing-cost-ladder.md. + */ +import java.lang.management.ManagementFactory; +import java.util.Arrays; +import java.util.concurrent.SynchronousQueue; + +public class QueueHandoffBench { + + record Req(byte[] key, byte[] val, byte[] acc, int mode) {} // mode 0=noop 1=fold 2=fold+spin + + static void fold(byte[] key, byte[] val, byte[] acc) { + int n = Math.min(val.length, acc.length); + byte k = key.length > 0 ? key[0] : 0; + for (int i = 0; i < n; i++) { + acc[i] = (byte) (acc[i] + val[i] + k); + } + } + + static void spin1us() { + long start = System.nanoTime(); + while (System.nanoTime() - start < 1_000) { /* spin */ } + } + + public static void main(String[] args) throws Exception { + int warmup = args.length > 0 ? Integer.parseInt(args[0]) : 50_000; + int batches = args.length > 1 ? Integer.parseInt(args[1]) : 30; + int n = args.length > 2 ? Integer.parseInt(args[2]) : 10_000; + + SynchronousQueue reqQ = new SynchronousQueue<>(); + SynchronousQueue respQ = new SynchronousQueue<>(); + Thread worker = new Thread(() -> { + try { + while (true) { + Req r = reqQ.take(); + if (r.mode() >= 1) fold(r.key(), r.val(), r.acc()); + if (r.mode() == 2) spin1us(); + respQ.put(0); + } + } catch (InterruptedException e) { /* end */ } + }, "ladder-worker"); + worker.setDaemon(true); + worker.start(); + + byte[] key = new byte[16]; + byte[] val = new byte[1024]; + byte[] acc = new byte[1024]; + Arrays.fill(key, (byte) 'k'); + Arrays.fill(val, (byte) 'v'); + + System.out.printf("load: %.2f warmup %d round trips/arm, %d batches x %d%n", + ManagementFactory.getOperatingSystemMXBean().getSystemLoadAverage(), warmup, batches, n); + double foldMedian = 0; + for (int mode = 0; mode <= 2; mode++) { + Req req = new Req(key, val, acc, mode); + for (int i = 0; i < (mode == 2 ? warmup / 5 : warmup); i++) { + reqQ.put(req); + respQ.take(); + } + double[] perBatch = new double[batches]; + for (int b = 0; b < batches; b++) { + long t0 = System.nanoTime(); + for (int i = 0; i < n; i++) { + reqQ.put(req); + respQ.take(); + } + perBatch[b] = (System.nanoTime() - t0) / (double) n; + } + Arrays.sort(perBatch); + double median = perBatch[batches / 2]; + double p99 = perBatch[Math.max(0, (int) (batches * 0.99) - 1)]; + String label = switch (mode) { + case 0 -> "(b) queue round trip no-op"; + case 1 -> "(b) queue round trip fold"; + default -> "(b) queue round trip fold+1us spin"; + }; + System.out.printf("%-36s median %10.1f ns/call p99 %10.1f batches %d%n", label, median, p99, batches); + if (mode == 1) foldMedian = median; + if (mode == 2) System.out.printf("(b) instrument-check delta: %.1f ns (expect ~1000)%n", median - foldMedian); + } + } +} diff --git a/ffi/crossing-ladder/bench_ctypes.py b/ffi/crossing-ladder/bench_ctypes.py new file mode 100644 index 0000000000..c81810e819 --- /dev/null +++ b/ffi/crossing-ladder/bench_ctypes.py @@ -0,0 +1,75 @@ +# Copyright (C) 2026 Antony Stubbs and contributors +# +# Crossing-cost ladder arm (c): what Python pays to call C through ctypes, and (c') what a +# native caller pays to call the same functions through a bare function pointer (the +# engine-side proxy). Measures no-op, the 1KB fold, and the ~1us busy-wait instrument +# check, as ns/call distributions (median + p99 over batches). +# See docs/inflight/perf-crossing-cost-ladder.md. +# +# Usage: python3 bench_ctypes.py [batches] [calls-per-batch] + +import ctypes as ct +import os +import statistics +import sys +import time + +HERE = os.path.dirname(os.path.abspath(__file__)) +lib = ct.CDLL(os.path.join(HERE, "libfold.so")) + +SIG = [ct.c_char_p, ct.c_int32, ct.c_char_p, ct.c_int32, ct.c_char_p, ct.c_int32] +for name in ("pc_noop", "pc_fold", "pc_fold_spin"): + fn = getattr(lib, name) + fn.argtypes = SIG + fn.restype = ct.c_int32 + +FOLD_FN = ct.CFUNCTYPE(ct.c_int32, ct.c_char_p, ct.c_int32, ct.c_char_p, ct.c_int32, + ct.c_char_p, ct.c_int32) +lib.pc_drive_ptr.argtypes = [FOLD_FN, ct.c_uint64] + SIG + [ct.POINTER(ct.c_int32)] +lib.pc_drive_ptr.restype = ct.c_uint64 + +KEY = ct.create_string_buffer(b"k" * 16, 16) +VAL = ct.create_string_buffer(b"v" * 1024, 1024) +ACC = ct.create_string_buffer(b"\x00" * 1024, 1024) + +def bench_python_side(fn, warmup, batches, n): + """ns/call: Python loop calling into C; the Python-side marshalling is part of the cost.""" + for _ in range(warmup): + fn(KEY, 16, VAL, 1024, ACC, 1024) + per_batch = [] + for _ in range(batches): + t0 = time.perf_counter_ns() + for _ in range(n): + fn(KEY, 16, VAL, 1024, ACC, 1024) + per_batch.append((time.perf_counter_ns() - t0) / n) + return per_batch + +def bench_c_side(name, warmup, batches, n): + """ns/call: the C driver loops over a function POINTER, timed inside C - engine-side proxy.""" + ptr = FOLD_FN((name, lib)) + sink = ct.c_int32(0) + lib.pc_drive_ptr(ptr, warmup, KEY, 16, VAL, 1024, ACC, 1024, ct.byref(sink)) + per_batch = [] + for _ in range(batches): + ns = lib.pc_drive_ptr(ptr, n, KEY, 16, VAL, 1024, ACC, 1024, ct.byref(sink)) + per_batch.append(ns / n) + return per_batch + +def report(label, per_batch): + med = statistics.median(per_batch) + p99 = sorted(per_batch)[max(0, int(len(per_batch) * 0.99) - 1)] + print(f"{label:34s} median {med:10.1f} ns/call p99 {p99:10.1f} batches {len(per_batch)}") + return med + +if __name__ == "__main__": + batches = int(sys.argv[1]) if len(sys.argv) > 1 else 50 + n = int(sys.argv[2]) if len(sys.argv) > 2 else 20000 + print(f"load: {os.getloadavg()[0]:.2f} warmup 100000 calls/arm, {batches} batches x {n}") + m_noop = report("(c) ctypes py->c no-op", bench_python_side(lib.pc_noop, 100000, batches, n)) + m_fold = report("(c) ctypes py->c fold", bench_python_side(lib.pc_fold, 100000, batches, n)) + m_spin = report("(c) ctypes py->c fold+1us spin", bench_python_side(lib.pc_fold_spin, 10000, batches, n)) + print(f"(c) instrument-check delta: {m_spin - m_fold:.1f} ns (expect ~1000)") + c_noop = report("(c') C drive ptr no-op", bench_c_side("pc_noop", 100000, batches, n)) + c_fold = report("(c') C drive ptr fold", bench_c_side("pc_fold", 100000, batches, n)) + c_spin = report("(c') C drive ptr fold+1us spin", bench_c_side("pc_fold_spin", 10000, batches, n)) + print(f"(c') instrument-check delta: {c_spin - c_fold:.1f} ns (expect ~1000)") diff --git a/ffi/crossing-ladder/bench_numba.py b/ffi/crossing-ladder/bench_numba.py new file mode 100644 index 0000000000..6771238bdc --- /dev/null +++ b/ffi/crossing-ladder/bench_numba.py @@ -0,0 +1,101 @@ +# Copyright (C) 2026 Antony Stubbs and contributors +# +# Crossing-cost ladder arm (d): a Numba @cfunc-compiled fold, called through its raw +# function POINTER by the C driver in libfold.so - the compile-the-function shape, where +# the engine holds a registered pointer and Python is not in the call path at all. +# Timing is done inside C (pc_drive_ptr). The ~1us instrument check is a Numba-side +# clock-calibrated spin (numba can call ctypes-wrapped clock_gettime? no - it spins on a +# calibrated iteration count instead, and the calibration is printed). +# See docs/inflight/perf-crossing-cost-ladder.md. +# +# Run inside the numba venv: numba-venv/bin/python bench_numba.py [batches] [calls-per-batch] + +import ctypes as ct +import os +import statistics +import sys +import time + +from numba import cfunc, types, njit + +HERE = os.path.dirname(os.path.abspath(__file__)) +lib = ct.CDLL(os.path.join(HERE, "libfold.so")) + +SIG_C = [ct.c_char_p, ct.c_int32, ct.c_char_p, ct.c_int32, ct.c_char_p, ct.c_int32] +FOLD_FN = ct.CFUNCTYPE(ct.c_int32, *SIG_C) +lib.pc_drive_ptr.argtypes = [FOLD_FN, ct.c_uint64] + SIG_C + [ct.POINTER(ct.c_int32)] +lib.pc_drive_ptr.restype = ct.c_uint64 + +# the fold, in the numba nopython subset: byte pointers as CPointer(uint8) +u8p = types.CPointer(types.uint8) +fold_sig = types.int32(u8p, types.int32, u8p, types.int32, u8p, types.int32) + +@cfunc(fold_sig, nopython=True, cache=False) +def nb_noop(key, klen, val, vlen, acc, alen): + return 0 + +@cfunc(fold_sig, nopython=True, cache=False) +def nb_fold(key, klen, val, vlen, acc, alen): + n = vlen if vlen < alen else alen + k = key[0] if klen > 0 else 0 + for i in range(n): + acc[i] = (acc[i] + val[i] + k) & 0xFF + return acc[n - 1] if n > 0 else 0 + +# instrument check: calibrated spin. SPIN_COUNT is patched below after calibration. +def make_spin(count): + @cfunc(fold_sig, nopython=True, cache=False) + def nb_fold_spin(key, klen, val, vlen, acc, alen): + n = vlen if vlen < alen else alen + k = key[0] if klen > 0 else 0 + for i in range(n): + acc[i] = (acc[i] + val[i] + k) & 0xFF + # serial data-dependent chain, result written to observable memory - not eliminable + s = acc[0] + for i in range(count): + s = (s * 31 + i) & 0xFF + acc[0] = s + return acc[n - 1] if n > 0 else 0 + return nb_fold_spin + +KEY = ct.create_string_buffer(b"k" * 16, 16) +VAL = ct.create_string_buffer(b"v" * 1024, 1024) +ACC = ct.create_string_buffer(b"\x00" * 1024, 1024) +SINK = ct.c_int32(0) + +def drive(address, warmup, batches, n): + ptr = ct.cast(address, FOLD_FN) + lib.pc_drive_ptr(ptr, warmup, KEY, 16, VAL, 1024, ACC, 1024, ct.byref(SINK)) + per_batch = [] + for _ in range(batches): + ns = lib.pc_drive_ptr(ptr, n, KEY, 16, VAL, 1024, ACC, 1024, ct.byref(SINK)) + per_batch.append(ns / n) + return per_batch + +def report(label, per_batch): + med = statistics.median(per_batch) + p99 = sorted(per_batch)[max(0, int(len(per_batch) * 0.99) - 1)] + print(f"{label:34s} median {med:10.1f} ns/call p99 {p99:10.1f} batches {len(per_batch)}") + return med + +if __name__ == "__main__": + batches = int(sys.argv[1]) if len(sys.argv) > 1 else 50 + n = int(sys.argv[2]) if len(sys.argv) > 2 else 20000 + print(f"load: {os.getloadavg()[0]:.2f} warmup 100000 calls/arm, {batches} batches x {n}") + + # calibrate the spin count to ~1us by measuring the fold-with-spin against the fold + base = drive(nb_fold.address, 100000, 10, n) + count, delta = 0, 0.0 + for count in (4000, 8000, 16000, 32000, 64000): + spin = make_spin(count) + d = drive(spin.address, 10000, 10, n) + delta = statistics.median(d) - statistics.median(base) + if delta >= 900: + break + print(f"calibrated spin count {count} -> ~{delta:.0f} ns extra") + + m_noop = report("(d) numba cfunc ptr no-op", drive(nb_noop.address, 100000, batches, n)) + m_fold = report("(d) numba cfunc ptr fold", drive(nb_fold.address, 100000, batches, n)) + spin = make_spin(count) + m_spin = report("(d) numba cfunc ptr fold+~1us spin", drive(spin.address, 10000, batches, n)) + print(f"(d) instrument-check delta: {m_spin - m_fold:.1f} ns (expect ~1000, spin calibrated to {delta:.0f})") diff --git a/ffi/crossing-ladder/build-streams-native.sh b/ffi/crossing-ladder/build-streams-native.sh new file mode 100755 index 0000000000..f82b9e4e15 --- /dev/null +++ b/ffi/crossing-ladder/build-streams-native.sh @@ -0,0 +1,108 @@ +#!/usr/bin/env bash +# +# Copyright (C) 2026 Antony Stubbs and contributors +# +# Builds the Kafka Streams engine (parallel-consumer-proxy-streams) as a GraalVM native-image +# EXECUTABLE, to settle whether Kafka Streams can run under native-image at all - the companion gap +# docs/inflight/branch-crossing-cost-ladder.md names beside the crossing-cost ladder. +# +# The recipe is inherited from the sidecar's, not invented: the same --no-fallback and the same +# --initialize-at-build-time list, both of which docs/inflight/perf-native-image-sidecar-works.md +# records as having been added to fix a build that had actually failed. What differs is the entry +# point, and that reachability metadata is passed EXPLICITLY here - the metadata that ships at +# META-INF/native-image/reachability-metadata.json was traced over a PC-core session and knows +# nothing about Kafka Streams. +# +# ./build-streams-native.sh # build with whatever metadata is on hand +# PC_STREAMS_NI_CONFIG= ./build-streams-native.sh # ... plus a traced config directory +# +# Cross-platform: macOS and Linux. Missing tools are reported by name rather than worked around. + +set -euo pipefail + +PROBE_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +REPO_ROOT="$(cd "$PROBE_DIR/../.." && pwd)" +BUILD_DIR="$PROBE_DIR/streams-native" +IMAGE_NAME="pc-streams-engine" +MAIN_CLASS="bz.stub.parallelconsumer.streams.StreamsMain" + +case "$(uname -s)" in + Darwin|Linux) ;; + *) echo "unsupported platform $(uname -s): this script knows macOS and Linux only" >&2 + exit 1 ;; +esac + +# GraalVM. GRAALVM_HOME wins; otherwise mise, then sdkman. Never fall back to the default JDK - +# native-image would simply be absent and the error would point at the wrong thing. +if [ -z "${GRAALVM_HOME:-}" ]; then + for candidate in "$HOME"/.local/share/mise/installs/java/graalvm-community-* \ + "$HOME"/.sdkman/candidates/java/*-graal; do + [ -x "$candidate/bin/native-image" ] && GRAALVM_HOME="$candidate" && break + done +fi +if [ -z "${GRAALVM_HOME:-}" ] || [ ! -x "$GRAALVM_HOME/bin/native-image" ]; then + echo "no GraalVM with native-image found. Set GRAALVM_HOME, or: mise install java@graalvm-community-25" >&2 + exit 1 +fi + +# The repo builds on JDK 17 (Jabel), which is NOT the JDK that runs native-image. Set it per +# command rather than exporting it, so this script cannot change the JDK for anything else. +JDK17="${PC_JDK17_HOME:-$HOME/.local/share/mise/installs/java/temurin-17}" +if [ ! -x "$JDK17/bin/java" ]; then + echo "no JDK 17 at $JDK17 - set PC_JDK17_HOME. The repo's Maven build requires 17." >&2 + exit 1 +fi + +echo "==> GraalVM: $("$GRAALVM_HOME/bin/native-image" --version | head -1)" +echo "==> JDK 17: $JDK17" + +mkdir -p "$BUILD_DIR" + +CP_FILE="$REPO_ROOT/parallel-consumer-proxy-streams/target/streams-classpath.txt" +if [ ! -f "$CP_FILE" ] || [ -n "${PC_STREAMS_NI_REBUILD:-}" ]; then + echo "==> resolving the streams module's runtime classpath" + # -am is not optional: the enforcer's ReactorModuleConvergence rule fails the build without it. + # -DincludeScope=runtime keeps core's TEST jar - and its logback-test.xml - out of the image. + (cd "$REPO_ROOT" && JAVA_HOME="$JDK17" ./mvnw --batch-mode -q \ + -pl :parallel-consumer-proxy-streams -am -DskipTests -Dcopyright.skip=true \ + -DincludeScope=runtime package dependency:build-classpath \ + '-Dmdep.outputFile=${project.build.directory}/streams-classpath.txt' \ + >"$BUILD_DIR/maven.log" 2>&1) || { + echo "maven failed; see $BUILD_DIR/maven.log" >&2; exit 1; } +fi + +STREAMS_CLASSES="$REPO_ROOT/parallel-consumer-proxy-streams/target/classes" +CLASSPATH="$STREAMS_CLASSES:$(cat "$CP_FILE")" + +config_args=() +if [ -n "${PC_STREAMS_NI_CONFIG:-}" ]; then + [ -d "$PC_STREAMS_NI_CONFIG" ] || { echo "no config directory at $PC_STREAMS_NI_CONFIG" >&2; exit 1; } + config_args+=("-H:ConfigurationFileDirectories=$PC_STREAMS_NI_CONFIG") + echo "==> reachability config: $PC_STREAMS_NI_CONFIG" +else + echo "==> no traced config passed; only the metadata shipped on the classpath applies" +fi + +# --no-fallback is not optional and is the most important flag here: without it native-image quietly +# emits an image that still needs a JVM at run time, which builds green and proves nothing. +echo "==> native-image ($IMAGE_NAME)" +cd "$BUILD_DIR" +start=$(date +%s) +"$GRAALVM_HOME/bin/native-image" \ + --no-fallback \ + -cp "$CLASSPATH" \ + --initialize-at-build-time=ch.qos.logback,org.slf4j,org.xml.sax,com.sun.org.apache.xerces,javax.xml \ + "${config_args[@]+"${config_args[@]}"}" \ + -H:Name="$IMAGE_NAME" \ + "$MAIN_CLASS" \ + 2>&1 | tee "$BUILD_DIR/native-image.log" +status=${PIPESTATUS[0]} +end=$(date +%s) + +echo +if [ "$status" -ne 0 ]; then + echo "==> native-image FAILED after $((end - start))s; see $BUILD_DIR/native-image.log" >&2 + exit "$status" +fi +echo "==> built $BUILD_DIR/$IMAGE_NAME in $((end - start))s" +ls -l "$BUILD_DIR/$IMAGE_NAME" diff --git a/ffi/crossing-ladder/fold.c b/ffi/crossing-ladder/fold.c new file mode 100644 index 0000000000..13a42cebce --- /dev/null +++ b/ffi/crossing-ladder/fold.c @@ -0,0 +1,67 @@ +/* + * Copyright (C) 2026 Antony Stubbs and contributors + * + * Crossing-cost ladder (docs/inflight/perf-crossing-cost-ladder.md): the shared C side. + * Provides the no-op, the windowed-aggregation-shaped fold (fold ~1KB value into ~1KB + * accumulator), the ~1us busy-wait instrument-check variant, and a C-side driver that + * calls an arbitrary function pointer N times with timing done in C - the proxy for + * what the engine pays to call a registered pointer (arms c' and d). + * + * Build: cc -O2 -shared -fPIC fold.c -o libfold.so + */ +#include +#include + +static inline uint64_t now_ns(void) { + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + return (uint64_t) ts.tv_sec * 1000000000ull + (uint64_t) ts.tv_nsec; +} + +/* the no-op crossing target */ +int32_t pc_noop(const uint8_t *key, int32_t klen, const uint8_t *val, int32_t vlen, + uint8_t *acc, int32_t alen) { + (void) key; (void) klen; (void) val; (void) vlen; (void) acc; (void) alen; + return 0; +} + +/* the fold: element-wise add value into accumulator, seasoned by the key's first byte */ +int32_t pc_fold(const uint8_t *key, int32_t klen, const uint8_t *val, int32_t vlen, + uint8_t *acc, int32_t alen) { + int32_t n = vlen < alen ? vlen : alen; + uint8_t k = klen > 0 ? key[0] : 0; + for (int32_t i = 0; i < n; i++) { + acc[i] = (uint8_t) (acc[i] + val[i] + k); + } + return acc[n > 0 ? n - 1 : 0]; +} + +/* ~1us busy-wait, clock-calibrated - the instrument-check injection */ +void pc_spin_1us(void) { + uint64_t start = now_ns(); + while (now_ns() - start < 1000ull) { /* spin */ } +} + +int32_t pc_fold_spin(const uint8_t *key, int32_t klen, const uint8_t *val, int32_t vlen, + uint8_t *acc, int32_t alen) { + int32_t r = pc_fold(key, klen, val, vlen, acc, alen); + pc_spin_1us(); + return r; +} + +/* engine-side proxy: call fn `iters` times, return elapsed ns measured in C. + * `sink` prevents the calls being optimised out (the fn is behind a pointer anyway). */ +typedef int32_t (*fold_fn)(const uint8_t *, int32_t, const uint8_t *, int32_t, uint8_t *, int32_t); + +uint64_t pc_drive_ptr(fold_fn fn, uint64_t iters, + const uint8_t *key, int32_t klen, const uint8_t *val, int32_t vlen, + uint8_t *acc, int32_t alen, int32_t *sink) { + volatile int32_t s = 0; + uint64_t start = now_ns(); + for (uint64_t i = 0; i < iters; i++) { + s += fn(key, klen, val, vlen, acc, alen); + } + uint64_t elapsed = now_ns() - start; + *sink = s; + return elapsed; +} diff --git a/ffi/crossing-ladder/fold_wasm.rs b/ffi/crossing-ladder/fold_wasm.rs new file mode 100644 index 0000000000..a42b3d4d44 --- /dev/null +++ b/ffi/crossing-ladder/fold_wasm.rs @@ -0,0 +1,64 @@ +// Copyright (C) 2026 Antony Stubbs and contributors +// +// Crossing-cost ladder arm (f): the fold compiled to wasm32. Rust-compiled, not +// C-compiled - this box has no clang/wasm-ld/emcc, and rustc with the +// wasm32-unknown-unknown target is the reachable to-WASM toolchain (recorded in +// docs/inflight/perf-crossing-cost-ladder.md). Exports: buf_ptr (a 4KB scratch buffer +// the host stages bytes in), noop, fold, and fold_spin (fold + caller-calibrated serial +// spin chain, the ~1us instrument check). +// +// Build: rustc --target wasm32-unknown-unknown -C opt-level=3 -C panic=abort \ +// --crate-type=cdylib fold_wasm.rs -o fold.wasm +#![no_std] + +#[panic_handler] +fn panic(_: &core::panic::PanicInfo) -> ! { + loop {} +} + +static mut BUF: [u8; 4096] = [0; 4096]; + +#[no_mangle] +pub extern "C" fn buf_ptr() -> i32 { + unsafe { BUF.as_ptr() as i32 } +} + +#[no_mangle] +pub extern "C" fn noop(_k: i32, _klen: i32, _v: i32, _vlen: i32, _a: i32, _alen: i32) -> i32 { + 0 +} + +#[no_mangle] +pub extern "C" fn fold(k: i32, klen: i32, v: i32, vlen: i32, a: i32, alen: i32) -> i32 { + unsafe { + let n = if vlen < alen { vlen } else { alen }; + let key = k as *const u8; + let val = v as *const u8; + let acc = a as *mut u8; + let kb = if klen > 0 { *key } else { 0 }; + let mut i: isize = 0; + while i < n as isize { + *acc.offset(i) = (*acc.offset(i)).wrapping_add(*val.offset(i)).wrapping_add(kb); + i += 1; + } + if n > 0 { *acc.offset(n as isize - 1) as i32 } else { 0 } + } +} + +/// fold + a serial data-dependent chain of `count` steps written to observable memory - +/// the instrument-check injection, count calibrated to ~1us by the host. +#[no_mangle] +pub extern "C" fn fold_spin(k: i32, klen: i32, v: i32, vlen: i32, a: i32, alen: i32, count: i32) -> i32 { + let r = fold(k, klen, v, vlen, a, alen); + unsafe { + let acc = a as *mut u8; + let mut s = *acc as i32; + let mut i = 0; + while i < count { + s = (s * 31 + i) & 0xFF; + i += 1; + } + *acc = s as u8; + } + r +} diff --git a/ffi/crossing-ladder/graal/pom.xml b/ffi/crossing-ladder/graal/pom.xml new file mode 100644 index 0000000000..967bd4ff4a --- /dev/null +++ b/ffi/crossing-ladder/graal/pom.xml @@ -0,0 +1,39 @@ + + + + 4.0.0 + bz.stub.scratch + crossing-ladder-graal + 0.0.1-SNAPSHOT + pom + + 25.0.2 + + + + org.graalvm.polyglot + polyglot + ${polyglot.version} + + + org.graalvm.polyglot + wasm + ${polyglot.version} + pom + + + org.graalvm.polyglot + python + ${polyglot.version} + pom + + + diff --git a/ffi/crossing-ladder/streams-native/.gitignore b/ffi/crossing-ladder/streams-native/.gitignore new file mode 100644 index 0000000000..d748786154 --- /dev/null +++ b/ffi/crossing-ladder/streams-native/.gitignore @@ -0,0 +1,13 @@ +# Copyright (C) 2026 Antony Stubbs and contributors +# +# build-streams-native.sh writes a ~78MB executable, a JDK shared library and its build logs here. +# None of that belongs in git, and nothing under ffi/ is ignored by the root .gitignore - so an +# orchestrator staging this directory would commit the binary without noticing. +# +# The ONE artifact worth keeping is the traced reachability metadata: it is the expensive half of +# the recipe (it needs a broker, a demo run and the tracing agent), and the build is reproducible +# from it in under a minute. +* +!.gitignore +!trace/ +!trace/reachability-metadata.json diff --git a/ffi/crossing-ladder/streams-native/trace/reachability-metadata.json b/ffi/crossing-ladder/streams-native/trace/reachability-metadata.json new file mode 100644 index 0000000000..53a9bec39c --- /dev/null +++ b/ffi/crossing-ladder/streams-native/trace/reachability-metadata.json @@ -0,0 +1,1073 @@ +{ + "reflection": [ + { + "type": "boolean[]" + }, + { + "type": "byte[]" + }, + { + "type": "char[]" + }, + { + "type": "com.google.common.util.concurrent.AbstractFutureState", + "fields": [ + { + "name": "listenersField" + }, + { + "name": "valueField" + }, + { + "name": "waitersField" + } + ] + }, + { + "type": "com.google.common.util.concurrent.AbstractFutureState$Waiter", + "fields": [ + { + "name": "next" + }, + { + "name": "thread" + } + ] + }, + { + "type": "com.google.protobuf.ExtensionRegistry", + "methods": [ + { + "name": "getEmptyRegistry", + "parameterTypes": [] + } + ] + }, + { + "type": "com.sun.management.GarbageCollectorMXBean" + }, + { + "type": "com.sun.management.GcInfo" + }, + { + "type": "com.sun.management.HotSpotDiagnosticMXBean" + }, + { + "type": "com.sun.management.ThreadMXBean" + }, + { + "type": "com.sun.management.UnixOperatingSystemMXBean" + }, + { + "type": "com.sun.management.VMOption" + }, + { + "type": "com.sun.management.internal.DiagnosticCommandArgumentInfo", + "jniAccessible": true, + "methods": [ + { + "name": "", + "parameterTypes": [ + "java.lang.String", + "java.lang.String", + "java.lang.String", + "java.lang.String", + "boolean", + "boolean", + "boolean", + "int" + ] + } + ] + }, + { + "type": "com.sun.management.internal.DiagnosticCommandArgumentInfo[]" + }, + { + "type": "com.sun.management.internal.DiagnosticCommandInfo", + "jniAccessible": true, + "methods": [ + { + "name": "", + "parameterTypes": [ + "java.lang.String", + "java.lang.String", + "java.lang.String", + "boolean", + "java.util.List" + ] + } + ] + }, + { + "type": "com.sun.management.internal.DiagnosticCommandInfo[]" + }, + { + "type": "com.sun.management.internal.GarbageCollectorExtImpl" + }, + { + "type": "com.sun.management.internal.HotSpotDiagnostic" + }, + { + "type": "com.sun.management.internal.HotSpotThreadImpl" + }, + { + "type": "com.sun.management.internal.OperatingSystemImpl" + }, + { + "type": "com.sun.management.internal.VirtualThreadSchedulerImpls$VirtualThreadSchedulerImpl" + }, + { + "type": "double[]" + }, + { + "type": "float[]" + }, + { + "type": "int[]" + }, + { + "type": "io.grpc.census.InternalCensusStatsAccessor" + }, + { + "type": "io.grpc.census.InternalCensusTracingAccessor" + }, + { + "type": "io.grpc.internal.SerializingExecutor" + }, + { + "type": "io.grpc.netty.shaded.io.grpc.netty.NettyServer$1" + }, + { + "type": "io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler" + }, + { + "type": "io.grpc.netty.shaded.io.grpc.netty.ProtocolNegotiators$GrpcNegotiationHandler" + }, + { + "type": "io.grpc.netty.shaded.io.grpc.netty.ProtocolNegotiators$PlaintextHandler" + }, + { + "type": "io.grpc.netty.shaded.io.grpc.netty.ProtocolNegotiators$WaitUntilActiveHandler" + }, + { + "type": "io.grpc.netty.shaded.io.grpc.netty.WriteBufferingAndExceptionHandler" + }, + { + "type": "io.grpc.netty.shaded.io.netty.bootstrap.ServerBootstrap$1" + }, + { + "type": "io.grpc.netty.shaded.io.netty.bootstrap.ServerBootstrap$ServerBootstrapAcceptor" + }, + { + "type": "io.grpc.netty.shaded.io.netty.buffer.AbstractByteBufAllocator" + }, + { + "type": "io.grpc.netty.shaded.io.netty.buffer.AbstractReferenceCountedByteBuf", + "fields": [ + { + "name": "refCnt" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.ChannelException", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.ChannelOutboundBuffer" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.DefaultChannelConfig" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline$HeadContext" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline$TailContext" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.DefaultFileRegion", + "jniAccessible": true, + "fields": [ + { + "name": "file" + }, + { + "name": "transferred" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.Epoll", + "methods": [ + { + "name": "isAvailable", + "parameterTypes": [] + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.EpollDomainSocketChannel" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoopGroup", + "methods": [ + { + "name": "", + "parameterTypes": [ + "int", + "java.util.concurrent.ThreadFactory" + ] + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.EpollServerSocketChannel", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.EpollSocketChannel" + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.LinuxSocket", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.Native", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.NativeDatagramPacketArray$NativeDatagramPacket", + "jniAccessible": true, + "fields": [ + { + "name": "count" + }, + { + "name": "memoryAddress" + }, + { + "name": "recipientAddr" + }, + { + "name": "recipientAddrLen" + }, + { + "name": "recipientPort" + }, + { + "name": "recipientScopeId" + }, + { + "name": "segmentSize" + }, + { + "name": "senderAddr" + }, + { + "name": "senderAddrLen" + }, + { + "name": "senderPort" + }, + { + "name": "senderScopeId" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.epoll.NativeStaticallyReferencedJniMethods", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.Buffer", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.DatagramSocketAddress", + "jniAccessible": true, + "methods": [ + { + "name": "", + "parameterTypes": [ + "byte[]", + "int", + "int", + "int", + "io.grpc.netty.shaded.io.netty.channel.unix.DatagramSocketAddress" + ] + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.DomainDatagramSocketAddress", + "jniAccessible": true, + "methods": [ + { + "name": "", + "parameterTypes": [ + "byte[]", + "int", + "io.grpc.netty.shaded.io.netty.channel.unix.DomainDatagramSocketAddress" + ] + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.ErrorsStaticallyReferencedJniMethods", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.FileDescriptor", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.LimitsStaticallyReferencedJniMethods", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.PeerCredentials", + "jniAccessible": true, + "methods": [ + { + "name": "", + "parameterTypes": [ + "int", + "int", + "int[]" + ] + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.channel.unix.Socket", + "jniAccessible": true + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.AbstractReferenceCounted", + "fields": [ + { + "name": "refCnt" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.DefaultAttributeMap" + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.Recycler$DefaultHandle" + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.ReferenceCountUtil" + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.ResourceLeakDetector$DefaultResourceLeak" + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.concurrent.DefaultPromise" + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor" + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.internal.NativeLibraryUtil", + "methods": [ + { + "name": "loadLibrary", + "parameterTypes": [ + "java.lang.String", + "boolean" + ] + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.internal.shaded.org.jctools.queues.BaseMpscLinkedArrayQueueColdProducerFields", + "fields": [ + { + "name": "producerLimit" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.internal.shaded.org.jctools.queues.BaseMpscLinkedArrayQueueConsumerFields", + "fields": [ + { + "name": "consumerIndex" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.internal.shaded.org.jctools.queues.BaseMpscLinkedArrayQueueProducerFields", + "fields": [ + { + "name": "producerIndex" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.internal.shaded.org.jctools.queues.unpadded.MpscUnpaddedArrayQueueConsumerIndexField", + "fields": [ + { + "name": "consumerIndex" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.internal.shaded.org.jctools.queues.unpadded.MpscUnpaddedArrayQueueProducerIndexField", + "fields": [ + { + "name": "producerIndex" + } + ] + }, + { + "type": "io.grpc.netty.shaded.io.netty.util.internal.shaded.org.jctools.queues.unpadded.MpscUnpaddedArrayQueueProducerLimitField", + "fields": [ + { + "name": "producerLimit" + } + ] + }, + { + "type": "io.grpc.override.ContextStorageOverride" + }, + { + "type": "io.perfmark.impl.SecretPerfMarkImpl$PerfMarkImpl" + }, + { + "type": "java.io.FileDescriptor", + "jniAccessible": true, + "fields": [ + { + "name": "fd" + } + ] + }, + { + "type": "java.io.IOException", + "jniAccessible": true + }, + { + "type": "java.lang.BaseVirtualThread" + }, + { + "type": "java.lang.Boolean", + "jniAccessible": true, + "fields": [ + { + "name": "TYPE" + } + ], + "methods": [ + { + "name": "getBoolean", + "parameterTypes": [ + "java.lang.String" + ] + } + ] + }, + { + "type": "java.lang.Byte", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.Character", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.Deprecated" + }, + { + "type": "java.lang.Double", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.Float", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.Integer", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.Long", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.OutOfMemoryError", + "jniAccessible": true + }, + { + "type": "java.lang.ProcessHandle", + "methods": [ + { + "name": "current", + "parameterTypes": [] + }, + { + "name": "pid", + "parameterTypes": [] + } + ] + }, + { + "type": "java.lang.RuntimeException", + "jniAccessible": true + }, + { + "type": "java.lang.Short", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.StackTraceElement" + }, + { + "type": "java.lang.String" + }, + { + "type": "java.lang.String[]" + }, + { + "type": "java.lang.Thread", + "methods": [ + { + "name": "isVirtual", + "parameterTypes": [] + } + ] + }, + { + "type": "java.lang.Void", + "fields": [ + { + "name": "TYPE" + } + ] + }, + { + "type": "java.lang.invoke.VarHandle" + }, + { + "type": "java.lang.management.BufferPoolMXBean" + }, + { + "type": "java.lang.management.ClassLoadingMXBean" + }, + { + "type": "java.lang.management.CompilationMXBean" + }, + { + "type": "java.lang.management.LockInfo" + }, + { + "type": "java.lang.management.MemoryMXBean" + }, + { + "type": "java.lang.management.MemoryManagerMXBean" + }, + { + "type": "java.lang.management.MemoryPoolMXBean" + }, + { + "type": "java.lang.management.MemoryUsage" + }, + { + "type": "java.lang.management.MonitorInfo" + }, + { + "type": "java.lang.management.PlatformLoggingMXBean" + }, + { + "type": "java.lang.management.RuntimeMXBean" + }, + { + "type": "java.lang.management.ThreadInfo" + }, + { + "type": "java.math.BigDecimal" + }, + { + "type": "java.math.BigInteger" + }, + { + "type": "java.net.InetSocketAddress", + "jniAccessible": true, + "methods": [ + { + "name": "", + "parameterTypes": [ + "java.lang.String", + "int" + ] + } + ] + }, + { + "type": "java.net.PortUnreachableException", + "jniAccessible": true + }, + { + "type": "java.nio.Bits" + }, + { + "type": "java.nio.Buffer", + "jniAccessible": true, + "fields": [ + { + "name": "address" + }, + { + "name": "limit" + }, + { + "name": "position" + } + ], + "methods": [ + { + "name": "limit", + "parameterTypes": [] + }, + { + "name": "position", + "parameterTypes": [] + } + ] + }, + { + "type": "java.nio.ByteBuffer" + }, + { + "type": "java.nio.DirectByteBuffer" + }, + { + "type": "java.nio.channels.ClosedChannelException", + "jniAccessible": true, + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "java.nio.channels.FileChannel" + }, + { + "type": "java.time.Instant" + }, + { + "type": "java.util.Arrays", + "jniAccessible": true, + "methods": [ + { + "name": "asList", + "parameterTypes": [ + "java.lang.Object[]" + ] + } + ] + }, + { + "type": "java.util.Date" + }, + { + "type": "java.util.concurrent.atomic.LongAdder", + "methods": [ + { + "name": "", + "parameterTypes": [] + }, + { + "name": "add", + "parameterTypes": [ + "long" + ] + } + ] + }, + { + "type": "java.util.zip.CRC32C", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "java.util.zip.Checksum", + "methods": [ + { + "name": "update", + "parameterTypes": [ + "java.nio.ByteBuffer" + ] + } + ] + }, + { + "type": "javax.management.MBeanOperationInfo" + }, + { + "type": "javax.management.MBeanServerBuilder", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "javax.management.ObjectName" + }, + { + "type": "javax.management.StandardEmitterMBean" + }, + { + "type": "javax.management.openmbean.CompositeData" + }, + { + "type": "javax.management.openmbean.CompositeData[]" + }, + { + "type": "javax.management.openmbean.OpenMBeanOperationInfoSupport" + }, + { + "type": "javax.management.openmbean.TabularData" + }, + { + "type": "javax.net.ssl.X509ExtendedTrustManager" + }, + { + "type": "jdk.internal.misc.Unsafe", + "methods": [ + { + "name": "getUnsafe", + "parameterTypes": [] + } + ] + }, + { + "type": "jdk.management.VirtualThreadSchedulerMXBean" + }, + { + "type": "jdk.management.jfr.ConfigurationInfo" + }, + { + "type": "jdk.management.jfr.EventTypeInfo" + }, + { + "type": "jdk.management.jfr.FlightRecorderMXBean" + }, + { + "type": "jdk.management.jfr.FlightRecorderMXBeanImpl" + }, + { + "type": "jdk.management.jfr.RecordingInfo" + }, + { + "type": "jdk.management.jfr.SettingDescriptorInfo" + }, + { + "type": "libcore.io.Memory" + }, + { + "type": "long[]" + }, + { + "type": "org.apache.kafka.clients.consumer.CooperativeStickyAssignor", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.clients.consumer.RangeAssignor", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.common.serialization.Serdes$ByteArraySerde" + }, + { + "type": "org.apache.kafka.common.utils.AppInfoParser$AppInfo" + }, + { + "type": "org.apache.kafka.common.utils.AppInfoParser$AppInfoMBean" + }, + { + "type": "org.apache.kafka.shaded.com.google.protobuf.ExtensionRegistry", + "methods": [ + { + "name": "getEmptyRegistry", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.errors.DefaultProductionExceptionHandler", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.errors.LogAndFailExceptionHandler", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.errors.LogAndFailProcessingExceptionHandler", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.processor.FailOnInvalidTimestamp", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.processor.internals.DefaultKafkaClientSupplier", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.processor.internals.StreamsPartitionAssignor", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.processor.internals.assignment.HighAvailabilityTaskAssignor", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.apache.kafka.streams.state.BuiltInDslStoreSuppliers$RocksDBDslStoreSuppliers", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "org.robolectric.Robolectric" + }, + { + "type": "short[]" + }, + { + "type": "sun.management.ClassLoadingImpl" + }, + { + "type": "sun.management.CompilationImpl" + }, + { + "type": "sun.management.ManagementFactoryHelper$1" + }, + { + "type": "sun.management.ManagementFactoryHelper$PlatformLoggingImpl" + }, + { + "type": "sun.management.MemoryImpl" + }, + { + "type": "sun.management.MemoryManagerImpl" + }, + { + "type": "sun.management.MemoryPoolImpl" + }, + { + "type": "sun.management.RuntimeImpl" + }, + { + "type": "sun.management.VMManagementImpl", + "jniAccessible": true, + "fields": [ + { + "name": "compTimeMonitoringSupport" + }, + { + "name": "currentThreadCpuTimeSupport" + }, + { + "name": "objectMonitorUsageSupport" + }, + { + "name": "otherThreadCpuTimeSupport" + }, + { + "name": "remoteDiagnosticCommandsSupport" + }, + { + "name": "synchronizerUsageSupport" + }, + { + "name": "threadAllocatedMemorySupport" + }, + { + "name": "threadContentionMonitoringSupport" + } + ] + }, + { + "type": "sun.misc.Unsafe", + "fields": [ + { + "name": "theUnsafe" + } + ], + "methods": [ + { + "name": "invokeCleaner", + "parameterTypes": [ + "java.nio.ByteBuffer" + ] + } + ] + }, + { + "type": "sun.nio.ch.FileChannelImpl", + "jniAccessible": true, + "fields": [ + { + "name": "fd" + } + ] + }, + { + "type": "sun.security.provider.NativePRNG", + "methods": [ + { + "name": "", + "parameterTypes": [ + "java.security.SecureRandomParameters" + ] + } + ] + }, + { + "type": "sun.security.provider.SHA", + "methods": [ + { + "name": "", + "parameterTypes": [] + } + ] + }, + { + "type": "sun.text.resources.cldr.FormatData" + }, + { + "type": "sun.text.resources.cldr.FormatData_en" + }, + { + "type": "sun.text.resources.cldr.FormatData_en_US" + }, + { + "type": "sun.util.resources.cldr.CalendarData" + } + ], + "resources": [ + { + "glob": "META-INF/io.netty.versions.properties" + }, + { + "glob": "META-INF/native/libio_grpc_netty_shaded_netty_transport_native_epoll_x86_64.so" + }, + { + "glob": "META-INF/services/java.nio.channels.spi.SelectorProvider" + }, + { + "glob": "META-INF/services/org.slf4j.spi.SLF4JServiceProvider" + }, + { + "glob": "kafka/kafka-streams-version.properties" + }, + { + "glob": "kafka/kafka-version.properties" + }, + { + "glob": "org/slf4j/impl/StaticLoggerBinder.class" + }, + { + "module": "jdk.jfr", + "glob": "jdk/jfr/internal/query/view.ini" + } + ] +} \ No newline at end of file diff --git a/ffi/crossing-ladder/trace-streams-engine.sh b/ffi/crossing-ladder/trace-streams-engine.sh new file mode 100755 index 0000000000..04983dc350 --- /dev/null +++ b/ffi/crossing-ladder/trace-streams-engine.sh @@ -0,0 +1,41 @@ +#!/usr/bin/env bash +# +# Copyright (C) 2026 Antony Stubbs and contributors +# +# A `java` stand-in that runs the Streams engine under GraalVM's tracing agent. +# +# The Python Streams demo launches its engine as ` -cp StreamsMain`, choosing the +# binary through PC_DEMO_JAVA - so pointing that at this script records what a REAL session touches. +# That distinction is the whole point: an agent run that merely starts and stops the engine records +# nothing about the reflection Kafka Streams does while assembling and running a topology, which is +# exactly where the sidecar's first native build failed +# (docs/inflight/perf-native-image-sidecar-works.md). +# +# PC_DEMO_JAVA= demo/run.sh --streams --native +# +# Output goes to PC_STREAMS_TRACE_DIR (default: streams-native/trace beside this script), merging +# across runs so several sessions can be traced into one config. + +set -euo pipefail + +PROBE_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +TRACE_DIR="${PC_STREAMS_TRACE_DIR:-$PROBE_DIR/streams-native/trace}" + +if [ -z "${GRAALVM_HOME:-}" ]; then + for candidate in "$HOME"/.local/share/mise/installs/java/graalvm-community-* \ + "$HOME"/.sdkman/candidates/java/*-graal; do + [ -x "$candidate/bin/java" ] && GRAALVM_HOME="$candidate" && break + done +fi +if [ -z "${GRAALVM_HOME:-}" ] || [ ! -x "$GRAALVM_HOME/bin/java" ]; then + echo "no GraalVM found for the tracing agent. Set GRAALVM_HOME." >&2 + exit 1 +fi + +mkdir -p "$TRACE_DIR" + +# config-merge-dir rather than config-output-dir: a second traced run then ADDS to the first rather +# than replacing it, which is what lets the failure path and the happy path share one config. +exec "$GRAALVM_HOME/bin/java" \ + "-agentlib:native-image-agent=config-merge-dir=$TRACE_DIR" \ + "$@" diff --git a/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_demo.py b/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_demo.py index a103d83a89..ec7dab69af 100644 --- a/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_demo.py +++ b/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_demo.py @@ -130,11 +130,36 @@ def poll_interval_property(args: argparse.Namespace) -> dict[str, str]: return {} +def resolve_engine() -> SidecarCommand: + """How to start the Streams engine, as an **absolute** path - never a ``PATH`` lookup. + + ``PC_DEMO_STREAMS_ENGINE`` names a binary directly, and is the same seam + ``reference_demo.py`` gives the comparison arm as ``PC_DEMO_SIDECAR``: a native-image build of + the engine is an executable that takes no classpath. Otherwise the "binary" is ``java`` plus + ``PC_DEMO_STREAMS_CLASSPATH``, which is an argument about the *binary* rather than + configuration - bootstrap servers, credentials and concurrency still travel only in the + handshake. + """ + binary = os.environ.get("PC_DEMO_STREAMS_ENGINE") + if binary: + return SidecarCommand.coerce(str(pathlib.Path(binary).resolve())) + + return SidecarCommand(executable=pathlib.Path(java_binary()).resolve(), + args=("-cp", resolve_classpath(), _MAIN_CLASS)) + + def resolve_classpath() -> str: + """The JVM engine's classpath, for callers that compose their own ``java`` invocation. + + The windowing lab needs the raw classpath (it injects the eviction instrument's jar beside + it), so this stays a seam of its own; ``resolve_engine`` above is the right entry for anyone + who just wants the engine started, native binary or JVM alike. + """ classpath = os.environ.get("PC_DEMO_STREAMS_CLASSPATH") if not classpath: raise SystemExit( - "set PC_DEMO_STREAMS_CLASSPATH - demo/run.sh --streams builds it. By hand:\n" + "set PC_DEMO_STREAMS_ENGINE to an absolute engine binary, or " + "PC_DEMO_STREAMS_CLASSPATH - demo/run.sh --streams builds the second one. By hand:\n" " ./mvnw -pl :parallel-consumer-proxy-streams -am -DskipTests " "-DincludeScope=runtime package dependency:build-classpath " "'-Dmdep.outputFile=${project.build.directory}/streams-classpath.txt'" @@ -335,7 +360,7 @@ def main(argv: list[str] | None = None) -> int: application_id = f"pc-streams-demo-{run_id}" # Absolute, because the client library refuses a PATH lookup for the executable it spawns. - java, classpath = pathlib.Path(java_binary()).resolve(), resolve_classpath() + engine = resolve_engine() log.info("Creating topics %s and %s (%d partitions)...", source, sink, args.partitions) ensure_topic(args.bootstrap, source, args.partitions) @@ -376,8 +401,8 @@ def upper(key: bytes, value: bytes) -> bytes: invocations += 1 return result - sidecar = Sidecar(SidecarCommand(java, ("-cp", classpath, _MAIN_CLASS))) - log.info("Starting the Streams engine...") + sidecar = Sidecar(engine) + log.info("Starting the Streams engine (%s)...", engine.executable) port = sidecar.start(timeout=90) session = StreamsSession(GrpcStreamsTransport(port)) admin = AdminClient({"bootstrap.servers": args.bootstrap}) diff --git a/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_windowing_lab.py b/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_windowing_lab.py index 2eda95767f..195a57ce4f 100644 --- a/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_windowing_lab.py +++ b/parallel-consumer-proxy-clients/parallel-consumer-proxy-client-python/demo/streams_windowing_lab.py @@ -10,6 +10,13 @@ Experiments are named and selected, so later units add a function here instead of a sibling file. +Experiment ``f2-rerun``: the F2 comparison (wrapper against the reimplementation floor) retaken +in ONE session with arm H interleaved against the cache-on crossing-free arms, because the +engine-floor spike's F2 reading paired arms measured in two different sessions - which KTD18 +forbids. It reuses ``engine-floor``'s ``FloorArm`` definitions and ``measure_placement`` rather +than restating the toggles, and drives arm H from ``--floor-records`` so both sides run at one +load. See ``run_f2_rerun``. + Experiment ``hot-key`` (U2): whether an aggregation over ONE hot key can be rescued by anything the parked bundling work offers. An aggregation is a serial dependency per key - accumulator n+1 needs accumulator n - so it cannot be batched across a hot key. It uses the EXISTING ``reduce`` operator, @@ -96,12 +103,15 @@ from __future__ import annotations import argparse +import contextlib import dataclasses +import gc import logging import os import pathlib import re import statistics +import subprocess import sys import tempfile import threading @@ -114,6 +124,8 @@ OFFSET_BEGINNING, TIMESTAMP_LOG_APPEND_TIME, Consumer, + KafkaError, + KafkaException, Producer, TopicPartition, ) @@ -194,6 +206,70 @@ def parse_args(argv: list[str] | None = None) -> argparse.Namespace: "point; B's per-record cost does not depend on records-per-key, and " "an uncapped B at twelve crossings per record dominates the wall " "time (default 24000)") + # --- engine-floor --- + parser.add_argument("--floor-records", type=int, default=32_000, + help="engine-floor/f2-rerun: records per run, every arm the same - and " + "in f2-rerun arm H too, so the two sides of the comparison are at " + "one load (default 32000). " + "Not a crossings sweep - the arms are crossing-free, so there is no " + "invocation count to normalise on and the term under test is the " + "record") + parser.add_argument("--floor-jfr", action="store_true", + help="engine-floor: attach a JFR profile recording to every engine in " + "this invocation; intended for a SEPARATE single-arm run, because a " + "profiler on every arm taxes the comparison it exists to explain") + parser.add_argument("--floor-arms", default="", + help="engine-floor: comma-separated arm labels to run instead of all " + "(e.g. D0), for the profiled capture and for re-running one arm") + parser.add_argument("--f2-host-control-keys", type=int, default=8_000, + help="f2-rerun: ALSO run arm H at this second key count in each rep, as " + "the control that attributes any disagreement with U6's arm-H " + "figures to the key count rather than to the session (default 8000, " + "U6's; 0 skips it)") + parser.add_argument("--host-fetch-queue-backoff-ms", type=int, default=None, + help="arm H: librdkafka fetch.queue.backoff.ms for the reimplementation " + "consumer. Left unset it is librdkafka's 1,000 ms, which at a " + "record count above the local queue's capacity puts a ~0.65 s " + "fetch stall inside arm H's timed window and reads as a 4.7x " + "slower reimplementation (measured; see the engine-floor note). " + "The stall now fails the run rather than being averaged over") + # --- crossing-ladder --- + parser.add_argument("--ladder-restore-backoff-ms", type=int, default=10, + help="crossing-ladder: every changelog is restored TWICE, once on " + "librdkafka's defaults and once with fetch.queue.backoff.ms set to " + "this. A restore reads more bytes than the arm that wrote them, so " + "the stall that turned arm H's own rate into a 4.7x artefact can " + "land on the restore figure; two configurations price it rather " + "than argue about it (default 10)") + parser.add_argument("--ladder-kill-after-ms", type=int, default=600, + help="ladder-kill: how long the durable writer runs before it is " + "SIGKILLed (default 600). It must be shorter than the run, and a " + "writer that finishes first fails the check rather than passing it") + parser.add_argument("--ladder-child-arm", default="H-dur-per", + help="ladder-kill: which durable arm the killed writer runs") + parser.add_argument("--ladder-child-spec", default="hopping-12", + choices=("tumbling", "hopping-12"), + help="ladder-kill: which window specification the killed writer runs") + parser.add_argument("--ladder-child-source", default="", + help="ladder-kill-child only: the seeded source topic to read") + parser.add_argument("--ladder-child-changelog", default="", + help="ladder-kill-child only: the changelog topic to write") + # --- host-bimodal --- + parser.add_argument("--bimodal-phases", default="observe,toggle,positive", + help="host-bimodal: which phases to run, in order - observe (the " + "untouched loop, many reps, nothing toggled), toggle (paired " + "single-term arms), positive (arms that force each candidate " + "mechanism so it is priced). Default all three") + parser.add_argument("--bimodal-control-reps", type=int, default=12, + help="host-bimodal: reps for the toggle and positive phases; the " + "observational phase uses --reps, which needs to be much larger " + "because the slow mode has appeared about once in twelve " + "(default 12)") + parser.add_argument("--floor-instrument", action="store_true", + help="engine-floor: also run the I0/I100 instrument-check pair, which " + "costs two host-function arms (slow) and proves the figure can " + "move. f2-rerun runs I0/I1000 instead - 0.1 ms was refuted as too " + "small for the client's thread pool to expose") return parser.parse_args(argv) @@ -561,6 +637,11 @@ class ArmSpec: _ARMS: dict[str, ArmSpec] = { "A": ArmSpec(_TUMBLE, "host", 1), + # The engine-floor experiment's multiplier-1 control: arm A's window with arm D's + # crossing-free combine, so the pair A/A-free isolates the crossing and the pair D0/T0 + # isolates the window multiplier. Added rather than folded into A, whose row U6's results + # are reported against. + "A-free": ArmSpec(_TUMBLE, "last", 1), "B": ArmSpec(_HOP5, "host", 12), "C": ArmSpec(_HOP30, "host", 2), "D": ArmSpec(_HOP5, "last", 12), @@ -587,6 +668,23 @@ class PlacementRun: group_state: str log_append: bool emit_band: tuple[int, int] + # The engine-floor experiment's toggles, one per arm; the defaults are U6's conditions, so a + # placement run records them unchanged and a floor run records exactly what it moved. + threads: int = 8 + sink_on: bool = True + changelog_on: bool = True + delay_ms: float = 0.0 + committed_window_s: float = 0.0 # the second clock: committed source offsets, first to last + + @property + def committed_rate(self) -> float: + """Rate on the committed-source-offset clock - the only clock a no-sink arm has. + + Reported beside ``rate`` on every sink-bearing arm precisely so the no-sink comparison is + never the first time this clock is used: two clocks that agree where both exist are what + make the one that stands alone believable. + """ + return self.records / self.committed_window_s if self.committed_window_s > 0 else 0.0 @property def rate(self) -> float: @@ -706,6 +804,64 @@ def _committed_source_records(bootstrap: str, group: str, topic: str, partitions probe.close() +class CommittedClock(threading.Thread): + """The second clock: the engine group's committed source offsets, sampled to completion. + + The sink's log-append clock is the lab's authority and stays so - but the engine-floor + experiment has an arm with NO SINK, and a rate read off a clock that arm cannot have would be + a cross-clock comparison wearing one number. So this clock is sampled on EVERY floor arm: the + two agree wherever both exist, which is what licenses the one that stands alone. + + The window is first observed progress (committed > 0) to the sample that reaches the whole + seeded backlog, so engine startup and the seed are outside it - the same exclusion the sink + clock gets for free by starting at the first append. Its resolution is the commit interval, + so an arm that lengthens the commit interval is read on the sink clock instead. + """ + + def __init__(self, bootstrap: str, group: str, topic: str, partitions: int, records: int, + period_s: float = 0.05) -> None: + super().__init__(daemon=True) + self._probe = Consumer({"bootstrap.servers": bootstrap, "group.id": group, + "enable.auto.commit": False}) + self._partitions = [TopicPartition(topic, p) for p in range(partitions)] + self._records = records + self._period_s = period_s + self._stop = threading.Event() + self.first_progress_s: float | None = None + self.complete_s: float | None = None + self.last_committed = 0 + + def run(self) -> None: + while not self._stop.is_set(): + try: + committed = sum(tp.offset for tp + in self._probe.committed(self._partitions, timeout=30) + if tp.offset >= 0) + except Exception as error: # a clock must never fail the run it is only witnessing + log.warning("committed-offset clock sample failed: %s", error) + committed = self.last_committed + now = time.monotonic() + if committed > 0 and self.first_progress_s is None: + self.first_progress_s = now + if committed >= self._records and self.complete_s is None: + self.complete_s = now + self.last_committed = committed + return + self.last_committed = committed + self._stop.wait(self._period_s) + + @property + def window_s(self) -> float: + if self.first_progress_s is None or self.complete_s is None: + return 0.0 + return self.complete_s - self.first_progress_s + + def close(self) -> None: + self._stop.set() + self.join(timeout=60) + self._probe.close() + + def _slf4j_simple_jar() -> str: """The slf4j binding the eviction instrument rides on - the engine classpath has none.""" root = pathlib.Path.home() / ".m2" / "repository" / "org" / "slf4j" / "slf4j-simple" @@ -748,9 +904,22 @@ def _count_evictions(engine_log: pathlib.Path) -> int: def measure_placement(args: argparse.Namespace, arm: str, records: int, keys: int, cache_bytes: int, *, trace_cache: bool = False, tolerate_evictions: bool = False, - show_topology: bool = False) -> PlacementRun: - """One measured placement run: fresh topics, fresh engine, one arm.""" + show_topology: bool = False, + commit_ms: int | None = None, threads: int | None = None, + sink_on: bool = True, changelog_on: bool = True, + delay_ms: float = 0.0) -> PlacementRun: + """One measured placement run: fresh topics, fresh engine, one arm. + + The keyword toggles are the engine-floor experiment's, one term each, and every default is + U6's condition - so a placement run is unaffected and a floor run's row records exactly what + it moved. ``delay_ms`` is the instrument check only: it sleeps inside the HOST function, so it + is meaningless (and refused) on an arm that registers no function. + """ spec = _ARMS[arm] + commit_ms = args.commit_interval_ms if commit_ms is None else commit_ms + threads = args.stream_threads if threads is None else threads + if delay_ms and spec.placement != "host": + raise SystemExit(f"delay_ms is a host-function toggle; arm {arm} registers no function") load1 = wait_for_quiet(args.load_limit) run_id = time.time_ns() @@ -792,6 +961,8 @@ def aggregate_last(_key: bytes, value: bytes, _accumulator: bytes) -> bytes: nonlocal crossings with accounting: crossings += 1 + if delay_ms: + time.sleep(delay_ms / 1000.0) return value def emit_fold(_key: bytes, value: bytes) -> bytes: @@ -803,6 +974,21 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: crossings += 1 return len(value).to_bytes(8, "big") + # The changelog toggle is a system property on the engine JVM, gated in TopologyAssembler + # (`pcStreams.measure.disableChangelog`) because the protocol has no logging-disabled field and + # this spike is not the place to add one; see docs/inflight/perf-streams-engine-floor.md. Off by + # default, so every other experiment is untouched by its existence. + if not changelog_on: + jvm_args = ("-DpcStreams.measure.disableChangelog=true", *jvm_args) + jfr_file: pathlib.Path | None = None + if getattr(args, "floor_jfr", False): + # ONE profiled capture, of the baseline arm only: a profiler on every arm would tax the + # comparison it is supposed to explain. async-profiler is not on this box; JFR ships with + # the JDK, so the capture is JFR's execution samples. + jfr_file = pathlib.Path(tempfile.gettempdir()) / f"pc-wlab-floor-{run_id}.jfr" + jvm_args = ("-XX:StartFlightRecording=settings=profile," + f"filename={jfr_file},dumponexit=true", *jvm_args) + print(f" JFR capture -> {jfr_file}") sidecar = Sidecar(SidecarCommand(java, jvm_args)) port = sidecar.start(timeout=90) session = StreamsSession(GrpcStreamsTransport(port)) @@ -811,9 +997,9 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: session.open(application_id, { "bootstrap.servers": args.bootstrap, "auto.offset.reset": "earliest", - "num.stream.threads": str(args.stream_threads), + "num.stream.threads": str(threads), "statestore.cache.max.bytes": str(cache_bytes), - "commit.interval.ms": str(args.commit_interval_ms), + "commit.interval.ms": str(commit_ms), }) builder = session.builder() windowed = builder.windowed_by(builder.group_by_key(builder.source(source)), @@ -829,7 +1015,8 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: table = builder.aggregate(windowed, store_name=_STORE, combine=CombineKind.APPEND_BYTES) streamed = builder.map_values(builder.to_stream(table), emit_fold) - builder.sink(streamed, sink) + if sink_on: + builder.sink(streamed, sink) if show_topology: print() print(f"Topology, arm {arm} (window {spec.window.size_ms / 60000:.0f}m advance " @@ -838,14 +1025,27 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: print(f" {line}") session.start() - quiet_s = args.quiescence_intervals * args.commit_interval_ms / 1000.0 + quiet_s = args.quiescence_intervals * commit_ms / 1000.0 # A cap, never the predicate: quiescence ends every healthy run long before this. timeout = 180 + 2 * (spec.multiplier * records * 400e-6 + records * 2e-3) deadline = time.monotonic() + timeout - with GroupWatch(admin, application_id, args.stream_threads) as watch: - emits, window, log_append, premature = read_emits_quiescent( - args.bootstrap, sink, quiet_s, deadline) + clock = CommittedClock(args.bootstrap, application_id, source, args.partitions, records) + clock.start() + with GroupWatch(admin, application_id, threads) as watch: + if sink_on: + emits, window, log_append, premature = read_emits_quiescent( + args.bootstrap, sink, quiet_s, deadline) + else: + # No sink, so no log-append clock and no quiescence to read: the committed-offset + # clock IS the measurement, and its completion is the completion predicate. The + # settle wait afterwards is the same 2x-quiet confirmation the sink arms get. + while time.monotonic() < deadline and clock.complete_s is None: + time.sleep(0.05) + emits, window, log_append, premature = 0, 0.0, True, clock.complete_s is None + time.sleep(2 * quiet_s) group_ok, group_state = watch.verdict() + clock.close() + committed_window = clock.window_s # Read BEFORE the topics are deleted below - deleting a topic purges its group offsets. # By here the engine has been idle for 3x quiet_s (45 commit intervals at the defaults), # so a shortfall is a truncated run, never a commit still in flight. @@ -864,7 +1064,11 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: # Post-hoc emit band (KTD11: on a broker, caching makes the emit count nondeterministic). # With the cache OFF every put forwards, so the band collapses to an exact count. - if cache_bytes == 0: + if not sink_on: + # Nothing is produced out, so there is no emit count to band. The record basis is proven + # by the committed-offset check below exactly as it is on every other arm. + emit_band = (0, 0) + elif cache_bytes == 0: emit_band = (spec.multiplier * records, spec.multiplier * records) else: # Every touched (key, window) entry emits at least once and at most once per put. @@ -876,7 +1080,11 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: "append": emits, # once per emit, at the emit placement }[spec.placement] problems: list[str] = [] - if premature: + if not sink_on and premature: + problems.append("the committed-offset clock never reached the seeded backlog before the " + "deadline - a no-sink arm has no other completion predicate, so the run " + "is unmeasured rather than slow") + elif premature: problems.append("premature quiescence break: sink end offsets advanced during the " "2x-quiet confirmation wait - the engine was stalled, not finished, so " "the window is truncated and the rate would read inflated") @@ -889,7 +1097,10 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: problems.append(f"emits={emits:,} outside band {emit_band[0]:,}..{emit_band[1]:,}") if not group_ok: problems.append(f"group={group_state}") - if not log_append: + if committed_window <= 0: + problems.append("the committed-offset clock produced no window - it is reported on every " + "arm precisely so the no-sink arm's sole clock is corroborated elsewhere") + if sink_on and not log_append: problems.append("sink not on the log-append clock") if evictions and not tolerate_evictions: problems.append(f"cache evictions={evictions:,} (the zero-evictions assertion failed: " @@ -898,12 +1109,18 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: result = PlacementRun(arm=arm, records=records, keys=keys, multiplier=spec.multiplier, crossings=crossings, emits=emits, window_s=window, - cache_bytes=cache_bytes, commit_ms=args.commit_interval_ms, + cache_bytes=cache_bytes, commit_ms=commit_ms, evictions=evictions, load1=load1, group_ok=group_ok, - group_state=group_state, log_append=log_append, emit_band=emit_band) + group_state=group_state, log_append=log_append, emit_band=emit_band, + threads=threads, sink_on=sink_on, changelog_on=changelog_on, + delay_ms=delay_ms, committed_window_s=committed_window) verdict = "ok" if not problems else "INVALID (" + "; ".join(problems) + ")" print(f" arm={arm} records={records:>7,} keys={keys:>5,} cache={cache_bytes:>11,} " + f"commit={commit_ms}ms threads={threads} sink={'on' if sink_on else 'OFF'} " + f"changelog={'on' if changelog_on else 'OFF'} delay={delay_ms:g}ms " f"window={window:7.2f}s rec/s={result.rate:8,.0f} " + f"committed_window={committed_window:6.2f}s " + f"committed_rec/s={result.committed_rate:8,.0f} " f"crossings/rec={result.crossings_per_record:6.2f} emits={emits:>9,} " f"evict={'-' if evictions is None else format(evictions, ',')} " f"load1={load1:.2f} {verdict}") @@ -914,18 +1131,162 @@ def emit_fold(_key: bytes, value: bytes) -> bytes: @dataclasses.dataclass(frozen=True) class HostRun: - """One arm-H run: the single-threaded reimplementation whose rate defines F2.""" + """One arm-H run: the single-threaded reimplementation whose rate defines F2. + + The fields below ``load1`` were added to settle arm H's BIMODAL hopping-12 rate (the + ``host-bimodal`` experiment). They are recorded on every arm-H run, not only that + experiment's, because a rate with no account of where its window went is exactly what left + the bimodality unattributable: twelve samples and nothing beside them to separate a run that + WAITED from a run that WORKED SLOWLY. + """ spec: str # "tumbling" or "hopping-12" records: int keys: int updates: int # dict updates; must equal multiplier x records window_s: float # wall clock, first message to last - H produces nothing to stamp + load1: float = 0.0 # 1-minute load read immediately before the run + arm: str = "H" # which arm-H variant; "H" is the untouched loop + rep: int = 0 # 1-based repetition index - the cold-first-read hypothesis needs it + cpu_s: float = 0.0 # process CPU time across the SAME window; wall >> cpu means waiting + fold_s: float = 0.0 # time inside the aggregation loop only + consume_s: float = 0.0 # time inside ``Consumer.consume`` only; the two ~= window_s + empty_polls: int = 0 # consume() calls returning nothing AFTER the window opened + empty_s: float = 0.0 # and the wall time they burned - each one can cost the 1.0s timeout + max_gap_s: float = 0.0 # longest single consume() call after the window opened + max_gap_at: int = 0 # records already folded when that gap happened - WHERE it stalls + long_polls: int = 0 # consume() calls over 100ms: one big stall or a persistent trickle + stalls: tuple[tuple[int, float], ...] = () # (records folded, seconds) for each of those + batches: int = 0 + gc_gen0: int = 0 # cyclic-collector passes INSIDE the window, by generation + gc_gen1: int = 0 + gc_gen2: int = 0 + gc_pause_s: float = 0.0 # measured collector pause time inside the window + gc_max_pause_s: float = 0.0 + calib_s: float = 0.0 # a fixed pure-CPU loop timed just before the window - box speed + # --- durability (the crossing-ladder's first rung; zero on every non-durable arm) --- + changelog_topic: str = "" # where this run's state was written, "" when it was not + changelog_records: int = 0 # records PRODUCED to it, counted client-side + changelog_end: int = 0 # end offsets summed off the BROKER after the run - the check + boundaries: int = 0 # commit boundaries reached inside the window + delivery_failures: int = 0 # changelog delivery reports that carried an error + produce_s: float = 0.0 # time inside ``produce()`` at the boundaries (coalesced only) + flush_s: float = 0.0 # time inside ``flush()`` - the AWAITED half of durability + commit_s: float = 0.0 # time inside the synchronous source-offset commit + + @property + def durable_s(self) -> float: + """The window time this run spent making its aggregate survive process death.""" + return self.produce_s + self.flush_s + self.commit_s @property def rate(self) -> float: return self.records / self.window_s if self.window_s > 0 else 0.0 + @property + def fold_rate(self) -> float: + """The rate charging ONLY the aggregation loop - no consume wait, no poll timeout. + + If the wall-clock rate is bimodal and this one is not, the bimodality is wait rather + than work, and the wait is a property of the harness's polling rather than of the + reimplementation being measured. + """ + return self.records / self.fold_s if self.fold_s > 0 else 0.0 + + +@dataclasses.dataclass(frozen=True) +class HostArm: + """One arm-H variant with exactly ONE term moved against the untouched loop. + + Added for the bimodality follow-up. Every field defaults to what plain arm H does, so an arm + is defined by the single line that differs - the same discipline ``FloorArm`` uses for the + engine arms, and for the same reason: an arm that moves two terms answers neither. + """ + + label: str + spec: str # "tumbling" or "hopping-12" + gc_disabled: bool = False # H1's paired toggle + force_gen2: bool = False # H1's positive control, mid-window + consumer_extra: tuple[tuple[str, object], ...] = () # H3's fetch-sizing toggles + fresh_topic: bool = False # H2: a topic this rep seeded and nobody read + expect_stall: bool = False # this arm EXHIBITS the stall on purpose, + # so the validity guard below stands down + # --- durability, the crossing-ladder's first rung (astubbs#242) --- + # ONE feature added back to the reimplementation, and nothing else: the aggregate survives + # process death. Two halves, and an arm needs both to claim it - a changelog write per state + # update, and a restore that rebuilds the dict from it (``restore_host``). No exactly-once, + # no rebalance handling, no late-record logic; those are later rungs. + changelog_mode: str = "none" # "none" | "per-update" | "coalesced" + changelog_acks: str = "all" # the delivery guarantee; "0" is the not-really-durable arm + changelog_await: bool = True # await the flush AT EVERY BOUNDARY, inside the window. + # False writes the same records and waits for none of them, + # which is what an accidentally-non-durable arm looks like + why: str = "" + + @property + def window(self) -> TimeWindow: + return _TUMBLE if self.spec == "tumbling" else _HOP5 + + +class _GcWatch: + """Measures CPython cyclic-collector pauses that land INSIDE a timed window. + + ``gc.get_stats()`` deltas count collections but not their cost, and the bimodality question is + a question about a second of wall clock: a hundred cheap gen-0 passes and one expensive gen-2 + pass are indistinguishable in a count and completely different in a window. ``gc.callbacks`` + brackets each pass, so the pause time is measured rather than inferred - and the arm can then + be refuted on MAGNITUDE without any toggle at all. + """ + + def __init__(self) -> None: + self.pause_s = 0.0 + self.max_pause_s = 0.0 + self.counts = [0, 0, 0] + self._started: float | None = None + self._armed = False + + def _callback(self, phase: str, info: dict) -> None: + if not self._armed: + return + if phase == "start": + self._started = time.monotonic() + elif self._started is not None: + elapsed = time.monotonic() - self._started + self.pause_s += elapsed + self.max_pause_s = max(self.max_pause_s, elapsed) + self.counts[min(int(info.get("generation", 0)), 2)] += 1 + self._started = None + + def install(self) -> None: + gc.callbacks.append(self._callback) + + def arm(self) -> None: + """Called when the timed window opens - collections before it are not this run's.""" + self._armed = True + + def remove(self) -> None: + self._armed = False + with contextlib.suppress(ValueError): # cleanup must never fail a valid run + gc.callbacks.remove(self._callback) + + +def _cpu_calibration_s(iterations: int = 400_000) -> float: + """A fixed pure-CPU loop, timed immediately before a measured window. + + The control that separates 'the harness waited' from 'this core was slow'. It allocates + nothing that survives, so it is not itself a cyclic-collector source; it is deliberately the + same shape of integer arithmetic the window-start arithmetic does. + """ + started = time.monotonic() + total = 0 + for i in range(iterations): + total += i * i + # Named rather than discarded: the sum exists only so a future interpreter cannot fold the + # loop away, which would turn the calibration into a constant zero without saying so. + ignored_calibration_sum = total + del ignored_calibration_sum + return time.monotonic() - started + def _window_starts(timestamp_ms: int, size_ms: int, advance_ms: int) -> list[int]: """``TimeWindows.windowsFor``'s arithmetic: every start s with s <= t < s+size, s a multiple @@ -940,8 +1301,138 @@ def _window_starts(timestamp_ms: int, size_ms: int, advance_ms: int) -> list[int return starts +def _new_changelog_topic(args: argparse.Namespace, label: str) -> str: + """A compacted topic for one durable arm-H run, created fresh so its end offsets are that + run's alone - which is what makes the end-offset check below a check rather than a total. + + ``cleanup.policy=compact`` is what a changelog IS; Kafka Streams creates its own the same + way. Compaction is asynchronous and will not have run inside a session this short, so a + restore here reads the UNCOMPACTED log - an upper bound on restore time, named as such. + """ + topic = f"pc-wlab-cl-{label}-{time.time_ns()}" + ensure_topic(args.bootstrap, topic, args.partitions, + config={"cleanup.policy": "compact", "min.cleanable.dirty.ratio": "0.1"}) + return topic + + +def _await_changelog_end(args: argparse.Namespace, topic: str, expected: int, + timeout_s: float = 30.0, strict: bool = True) -> int: + """THE INSTRUMENT CHECK for durability, read off the BROKER rather than the client. + + A durable arm that is accidentally not durable would look wonderfully fast, so the claim + "these records are on the broker" is never taken from the producer's own count: the end + offsets are summed from the cluster and must equal what the arm says it produced. Bounded + retry, because with ``acks=0`` the delivery report races the append. + + ``strict=False`` is for the arm whose whole definition is that it does NOT wait: a shortfall + there is the result rather than a fault, so it is returned and reported instead of raising. + """ + probe = Consumer({"bootstrap.servers": args.bootstrap, + "group.id": f"pc-wlab-clprobe-{time.time_ns()}", + "enable.auto.commit": False}) + deadline = time.monotonic() + timeout_s + total = 0 + try: + while time.monotonic() < deadline: + total = sum(_end_offsets(probe, topic).values()) + if total >= expected: + break + time.sleep(0.5) + finally: + probe.close() + if total != expected and not strict: + log.warning("changelog %s holds %d of the %d records the arm produced - a %.1f%% " + "shortfall, which for a not-awaited arm is the finding rather than a fault", + topic, total, expected, 100.0 * (expected - total) / expected) + return total + if total != expected: + raise RuntimeError( + f"changelog end offsets on {topic} sum to {total:,} against {expected:,} records " + "produced - the arm claims a durability cost it did not pay, which is exactly the " + "failure this check exists to catch") + return total + + +@dataclasses.dataclass(frozen=True) +class RestoreRun: + """One restore: rebuild the reimplementation's dict from its changelog, timed. + + Restore time and steady-state throughput are different quantities and both matter, so this + is reported as its own figure and never folded into a rate. + """ + + arm: str + spec: str + backoff_ms: int | None # the ONE term moved between the two restore configurations + seconds: float + records: int # changelog records read - the UNCOMPACTED log + entries: int # distinct (key, window) entries rebuilt + long_polls: int # consume() calls over 100ms - the fetch stall, if it is here + load1: float + + +def restore_host(args: argparse.Namespace, topic: str, expected_entries: int | None, *, + arm: str, spec: str, backoff_ms: int | None = None) -> RestoreRun: + """The other half of durability: rebuild the dict from the changelog before processing. + + Timed from the moment the restoring process asks the broker where the log ends to the moment + the dict is complete - which is the wait a user actually experiences on restart. + + ``backoff_ms`` moves librdkafka's ``fetch.queue.backoff.ms``, the one term that turned arm H's + own rate into a 4.7x artefact (see the engine-floor note, "Why arm H's hopping-12 rate is + bimodal"). A restore reads far more bytes than the arm that wrote them, so the same stall can + land here; measuring both configurations prices it instead of arguing about it. + """ + load1 = wait_for_quiet(args.load_limit) + config: dict[str, object] = { + "bootstrap.servers": args.bootstrap, + "group.id": f"pc-wlab-restore-{time.time_ns()}", + "enable.auto.commit": False, + } + if backoff_ms is not None: + config["fetch.queue.backoff.ms"] = backoff_ms + consumer = Consumer(config) + state: dict[bytes, bytes] = {} + read = 0 + long_polls = 0 + started = time.monotonic() + try: + ends = _end_offsets(consumer, topic) + total = sum(ends.values()) + consumer.assign([TopicPartition(topic, p, OFFSET_BEGINNING) for p in sorted(ends)]) + deadline = started + 600 + while read < total and time.monotonic() < deadline: + poll_started = time.monotonic() + batch = consumer.consume(num_messages=1000, timeout=5.0) + if time.monotonic() - poll_started > 0.1: + long_polls += 1 + if not batch: + break + for message in batch: + if message.error(): + continue + state[message.key()] = message.value() + read += 1 + finally: + elapsed = time.monotonic() - started + consumer.close() + if read != total or (expected_entries is not None and len(state) != expected_entries): + raise RuntimeError( + f"restore invalid: read {read:,}/{total:,} changelog records and rebuilt " + f"{len(state):,} entries against {expected_entries} expected - a restore that " + "does not reproduce the dict is not a restore") + print(f" restore arm={arm:<13s} {spec:<10s} backoff=" + f"{'default' if backoff_ms is None else f'{backoff_ms}ms':>7s} " + f"{elapsed:7.3f}s for {read:>9,} changelog records -> {len(state):>7,} entries " + f"({read / elapsed:9,.0f} rec/s, {long_polls} polls over 100ms) load1={load1:.2f}") + return RestoreRun(arm=arm, spec=spec, backoff_ms=backoff_ms, seconds=elapsed, + records=read, entries=len(state), long_polls=long_polls, load1=load1) + + def measure_host(args: argparse.Namespace, topic: str, records: int, keys: int, - window: TimeWindow, spec_label: str) -> HostRun: + window: TimeWindow, spec_label: str, *, arm: HostArm | None = None, + rep: int = 0, verbose: bool = False, + changelog_topic: str | None = None) -> HostRun: """Arm H: consume the same input single-threaded and aggregate into a dict. Deliberately stateless and non-durable - no store, no changelog, no rebalance recovery, no @@ -952,29 +1443,176 @@ def measure_host(args: argparse.Namespace, topic: str, records: int, keys: int, Runs while the engine is idle (the lab tears each sidecar down before any H run starts). Timed on this process's wall clock from first message to last - H produces nothing, so there is no log-append record of its progress; the consume loop IS the reimplementation. + + ``arm.changelog_mode`` is the ONE exception to "non-durable", and it is the crossing-ladder's + first rung (astubbs#242): the reimplementer's aggregate is made to survive process death by + writing every state update to a compacted Kafka topic and awaiting it at a commit boundary. + ``restore_host`` is its other half. Nothing else about the arm changes, so a durable arm + differs from ``H-base`` by exactly one feature - the discipline this whole program runs on. + + ``arm`` moves exactly one term (see ``HostArm``); omitted, the loop is the untouched one every + prior session measured. THE UNTOUCHED PATH MUST STAY UNTOUCHED: the instrumentation added for + the bimodality follow-up is two ``time.monotonic()`` calls per BATCH (about 130 of them on a + 128,000-record run) plus a ``gc.callbacks`` entry that runs only when the collector runs, so + it cannot itself account for the second of wall clock under investigation - and the + ``H-base`` arm reproduces the earlier sessions' rate, which is the check that says so. """ + arm = arm or HostArm(label="H", spec=spec_label) load1 = wait_for_quiet(args.load_limit) + calib_s = _cpu_calibration_s() multiplier = -(-window.size_ms // window.advance_ms) - consumer = Consumer({ + config: dict[str, object] = { "bootstrap.servers": args.bootstrap, "group.id": f"pc-wlab-h-{time.time_ns()}", "enable.auto.commit": False, - }) + } + if getattr(args, "host_fetch_queue_backoff_ms", None) is not None: + config["fetch.queue.backoff.ms"] = args.host_fetch_queue_backoff_ms + config.update(dict(arm.consumer_extra)) + consumer = Consumer(config) state: dict[tuple[bytes, int], bytes] = {} + dirty: set[tuple[bytes, int]] = set() updates = 0 seen = 0 started: float | None = None ended = 0.0 + cpu_started = 0.0 + cpu_s = 0.0 + fold_s = 0.0 + consume_s = 0.0 + empty_polls = 0 + empty_s = 0.0 + max_gap_s = 0.0 + max_gap_at = 0 + long_polls = 0 + stalls: list[tuple[int, float]] = [] + batches = 0 + forced = False + changelog_records = 0 + boundaries = 0 + produce_s = 0.0 + flush_s = 0.0 + commit_s = 0.0 + delivery_failures: list[object] = [] + + def _delivered(error: object, _message: object) -> None: + if error is not None: + delivery_failures.append(error) + + producer: Producer | None = None + if arm.changelog_mode != "none": + if not changelog_topic: + raise SystemExit(f"arm {arm.label} writes a changelog but no topic was given") + # STATED EXPLICITLY, because an unstated producer config is an unreproducible run - the + # same rule this lab already applies to commit.interval.ms. acks is the arm's term. + # enable.idempotence stays OFF: exactly-once is a LATER rung of the ladder and turning it + # on here would move two features at once. The two buffering ceilings are raised past the + # whole backlog so that a BufferError-driven wait can never be mistaken for produce cost; + # seed_keyed already raises the first for the same reason. + producer = Producer({ + "bootstrap.servers": args.bootstrap, + "acks": arm.changelog_acks, + "enable.idempotence": False, + "queue.buffering.max.messages": 2_000_000, + "queue.buffering.max.kbytes": 2_097_152, + }) + + def _produce_entry(entry: tuple[bytes, int], value: bytes) -> None: + """One changelog record for one (key, window) state entry. + + The key is the STATE key, so the topic's compaction can collapse the history to the + current value - which is the whole reason a changelog is a compacted topic rather than + a log of deltas. + """ + nonlocal changelog_records + entry_key, entry_start = entry + while True: + try: + producer.produce(changelog_topic, + key=entry_key + b"|" + str(entry_start).encode(), + value=value, on_delivery=_delivered) + break + except BufferError: # ceilings are raised past the backlog, so this is a backstop + producer.poll(0.5) + changelog_records += 1 + + def _boundary() -> None: + """The reimplementer's commit point: get the state durable, THEN move the resume point. + + Flush before commit is the ordering that makes the pair meaningful - committing first + would advance past records whose state had not reached the broker. A restored dict with + no resume point is not durability either, which is why the source-offset commit is part + of this rung rather than a separate one; it is ~10 synchronous calls per run, and + ``commit_s`` is reported separately so it can be seen not to dominate. + """ + nonlocal boundaries, produce_s, flush_s, commit_s + opened = time.monotonic() + if arm.changelog_mode == "coalesced": + # KAFKA STREAMS' STATE-STORE CACHE, hand-rolled: one write per (key, window) touched + # since the last boundary, not one per update. The engine-floor decomposition priced + # exactly this coalescing at 4.05x (D-cache), so it is a rung of the same ladder. + for entry in dirty: + _produce_entry(entry, state[entry]) + dirty.clear() + produced = time.monotonic() + produce_s += produced - opened + if not arm.changelog_await: + # The arm that writes a changelog and waits for none of it. It is here as the + # instrument's other half: a durable arm that is accidentally not durable looks + # wonderfully fast, and this prices exactly how fast. + boundaries += 1 + return + producer.flush() + flushed = time.monotonic() + flush_s += flushed - produced + try: + consumer.commit(asynchronous=False) + except KafkaException as failure: + # _NO_OFFSET means the previous boundary already committed everything consumed so + # far - which the FINAL boundary hits whenever the last batch happened to trigger + # one. It is "nothing new to commit", not a failed commit, and treating it as an + # error aborted a five-rep pass mid-run. + if failure.args[0].code() != KafkaError._NO_OFFSET: + raise + commit_s += time.monotonic() - flushed + boundaries += 1 + + boundary_s = args.commit_interval_ms / 1000.0 + last_boundary = 0.0 + watch = _GcWatch() + watch.install() + gc_was_enabled = gc.isenabled() + if arm.gc_disabled: + gc.disable() try: consumer.assign([TopicPartition(topic, p, OFFSET_BEGINNING) for p in range(args.partitions)]) deadline = time.monotonic() + 120 + records * 1e-3 while seen < records and time.monotonic() < deadline: + poll_started = time.monotonic() batch = consumer.consume(num_messages=1000, timeout=1.0) + poll_ended = time.monotonic() + if started is not None: + # Charged to the window whether or not the poll returned anything - which is + # precisely the accounting the bimodality question turns on. + gap = poll_ended - poll_started + consume_s += gap + if gap > max_gap_s: + max_gap_s, max_gap_at = gap, seen + if gap > 0.1: + long_polls += 1 + stalls.append((seen, gap)) if not batch: + if started is not None: + empty_polls += 1 + empty_s += poll_ended - poll_started continue if started is None: - started = time.monotonic() + started = poll_ended + cpu_started = time.process_time() + last_boundary = poll_ended + watch.arm() + batches += 1 for message in batch: if message.error(): continue @@ -987,19 +1625,112 @@ def measure_host(args: argparse.Namespace, topic: str, records: int, keys: int, for start in _window_starts(timestamp_ms, window.size_ms, window.advance_ms): state[(key, start)] = value updates += 1 + if producer is not None: + if arm.changelog_mode == "per-update": + # The naive reimplementer: every state update is a changelog write. + _produce_entry((key, start), value) + else: + dirty.add((key, start)) + if producer is not None and time.monotonic() - last_boundary >= boundary_s: + _boundary() + last_boundary = time.monotonic() + ended = time.monotonic() + fold_s += ended - poll_ended + if arm.force_gen2 and not forced and seen >= records // 2: + # H1's POSITIVE control: put a full generation-2 collection inside the window on + # purpose and let the same instrument price it. A mechanism that cannot produce + # the observed excess when forced cannot have produced it by accident. + forced = True + gc.collect(2) + ended = time.monotonic() + if producer is not None and started is not None: + # THE FINAL BOUNDARY IS INSIDE THE TIMED WINDOW, and it has to be: an arm whose last + # 200 ms of state reached the broker only after the clock stopped was not durable at + # the moment it claimed a rate. + final_opened = time.monotonic() + _boundary() ended = time.monotonic() + fold_s += ended - final_opened finally: + if arm.gc_disabled and gc_was_enabled: + gc.enable() + if started is not None: + cpu_s = time.process_time() - cpu_started + watch.remove() consumer.close() + if producer is not None and not arm.changelog_await: + # OUTSIDE the window on purpose: this arm's whole definition is that it does not pay + # for the wait. The records still have to arrive for the end-offset check below to + # mean anything, so the wait happens - it is just not charged to the rate, which is + # precisely the accounting error the arm exists to price. + producer.flush() window_s = (ended - started) if started is not None else 0.0 + changelog_end = 0 + if producer is not None: + if delivery_failures and arm.changelog_await: + raise RuntimeError(f"arm {arm.label} invalid: the changelog producer reported " + f"{len(delivery_failures)} delivery failure(s), first " + f"{delivery_failures[0]} - a changelog that did not arrive is " + "not durability") + changelog_end = _await_changelog_end(args, changelog_topic, changelog_records, + strict=arm.changelog_await) result = HostRun(spec=spec_label, records=seen, keys=keys, updates=updates, - window_s=window_s) + window_s=window_s, load1=load1, arm=arm.label, rep=rep, cpu_s=cpu_s, + fold_s=fold_s, consume_s=consume_s, empty_polls=empty_polls, + empty_s=empty_s, max_gap_s=max_gap_s, max_gap_at=max_gap_at, + long_polls=long_polls, stalls=tuple(stalls), batches=batches, + gc_gen0=watch.counts[0], gc_gen1=watch.counts[1], gc_gen2=watch.counts[2], + gc_pause_s=watch.pause_s, gc_max_pause_s=watch.max_pause_s, + calib_s=calib_s, changelog_topic=changelog_topic or "", + changelog_records=changelog_records, changelog_end=changelog_end, + boundaries=boundaries, produce_s=produce_s, flush_s=flush_s, + commit_s=commit_s, delivery_failures=len(delivery_failures)) + stalled = (long_polls or empty_polls) and not arm.expect_stall ok = seen == records and updates == multiplier * records - print(f" arm=H {spec_label:<10s} records={seen:>7,} keys={keys:>5,} " - f"window={window_s:7.2f}s rec/s={result.rate:8,.0f} dict-updates={updates:>9,} " - f"load1={load1:.2f} {'ok' if ok else 'INVALID'}") + print(f" arm={arm.label:<9s} {spec_label:<10s} records={seen:>7,} keys={keys:>5,} " + f"window={window_s:7.3f}s rec/s={result.rate:8,.0f} dict-updates={updates:>9,} " + f"load1={load1:.2f} " + f"{'ok' if ok and not stalled else ('STALLED' if ok else 'INVALID')}") + if verbose: + print(f" where the window went: fold={fold_s:6.3f}s consume={consume_s:6.3f}s " + f"(empty={empty_polls} for {empty_s:.3f}s, {long_polls} over 100ms, max gap " + f"{max_gap_s:.3f}s after {max_gap_at:,} records, {batches} batches) " + f"cpu={cpu_s:6.3f}s cpu/wall={cpu_s / window_s:5.2f} " + f"fold-only rec/s={result.fold_rate:8,.0f}") + if stalls: + # Capped: H-starve produces 154 of these by construction and the point is their + # LENGTH, which is identical, not the list. + shown = ", ".join(f"{gap:.3f}s after {at:,} records" for at, gap in stalls[:6]) + more = f" ... and {len(stalls) - 6} more" if len(stalls) > 6 else "" + print(f" polls over 100ms ({len(stalls)}): {shown}{more}") + print(f" collector inside the window: gen0={watch.counts[0]} gen1={watch.counts[1]} " + f"gen2={watch.counts[2]} pause={watch.pause_s:.3f}s " + f"(max {watch.max_pause_s:.3f}s) cpu-calibration={calib_s * 1e3:.1f}ms") + if producer is not None: + print(f" durability: changelog {changelog_records:,} records produced, " + f"{changelog_end:,} on the broker (end offsets, " + f"{changelog_records - changelog_end:,} MISSING, " + f"{len(delivery_failures)} failed reports), {boundaries} boundaries, " + f"acks={arm.changelog_acks} await={arm.changelog_await} " + f"produce={produce_s:.3f}s flush={flush_s:.3f}s commit={commit_s:.3f}s " + f"= {result.durable_s:.3f}s of a {window_s:.3f}s window " + f"({result.durable_s / window_s:.0%})") if not ok: raise RuntimeError(f"arm H invalid: saw {seen:,}/{records:,} records, " f"{updates:,} updates against {multiplier * records:,} expected") + if stalled: + raise RuntimeError( + f"arm H invalid: {long_polls} consume() call(s) over 100ms inside the timed window " + f"({empty_polls} of them empty), the longest {max_gap_s:.3f}s after " + f"{max_gap_at:,} records - {consume_s / window_s:.0%} of this window was fetch " + "wait, not aggregation, so the rate is a property of the fetch path rather than of " + "the reimplementation. This is what made arm H's hopping-12 rate read 89,821 rec/s " + "at 128,000 records in U6 and ~460,000 at 64,000: librdkafka stops fetching when " + "the local queue passes queued.max.messages.kbytes and then postpones the next " + "fetch by fetch.queue.backoff.ms (1,000ms by default). Raise the queue or lower " + "the backoff (--host-fetch-queue-backoff-ms) rather than averaging over it; see " + "docs/inflight/perf-streams-engine-floor.md, 'Why arm H's hopping-12 rate is " + "bimodal'.") return result @@ -1074,6 +1805,183 @@ def run_host_reimpl(args: argparse.Namespace) -> int: return 0 +"""Arm-H variants for ``host-bimodal``. Each moves ONE term against ``H-base``. + +``H-base`` and ``T-base`` are the untouched loop at the two specifications - hopping-12 is the +bimodal one, tumbling the arm that has been stable in every session and therefore the in-session +stability control. The rest are named by the hypothesis they can refute. +""" +_H_BASE = HostArm(label="H-base", spec="hopping-12", + expect_stall=True, + why="the untouched loop - the arm every prior session measured") +_H_ARMS: tuple[HostArm, ...] = ( + _H_BASE, + HostArm(label="T-base", spec="tumbling", + why="the untouched loop at the specification that has never been bimodal"), + HostArm(label="H-gcoff", spec="hopping-12", gc_disabled=True, + expect_stall=True, + why="H1's paired toggle: the cyclic collector cannot run inside the window"), + HostArm(label="H-queue", spec="hopping-12", + consumer_extra=(("queued.max.messages.kbytes", 2_097_151), + ("queued.min.messages", 2_000_000)), + why="H3's paired toggle: the whole backlog fits in the local fetch queue, so the " + "loop can never outrun the fetcher"), + HostArm(label="H-fresh", spec="hopping-12", fresh_topic=True, + expect_stall=True, + why="H2's toggle: a topic seeded for this rep and never read, against the shared " + "topic every other rep has already read"), + HostArm(label="H-gcforce", spec="hopping-12", force_gen2=True, + expect_stall=True, + why="H1's POSITIVE control: one full generation-2 collection forced inside the " + "window, so the mechanism is PRICED rather than argued about"), + HostArm(label="H-first", spec="hopping-12", + expect_stall=True, + why="the untouched loop in the FIRST slot of the rep - added after a smoke pass " + "showed the slot, not the arm, tracking the slow mode"), + HostArm(label="H-second", spec="hopping-12", + expect_stall=True, + why="the same untouched loop in a LATER slot, after another arm has already read " + "the same topic in this rep - one term moved: read position, nothing else"), + HostArm(label="H-backoff100", spec="hopping-12", + consumer_extra=(("fetch.queue.backoff.ms", 100),), + why="the mechanism's dose-response middle rung: if the stall IS librdkafka's " + "fetch-queue backoff timer, its length tracks this setting"), + HostArm(label="H-backoff10", spec="hopping-12", + consumer_extra=(("fetch.queue.backoff.ms", 10),), + why="the bottom rung of the same ladder - predicted stall ~10ms, and the arm's rate " + "predicted to land on the fold-only rate"), + HostArm(label="H-starve", spec="hopping-12", + consumer_extra=(("queued.max.messages.kbytes", 1_024), + ("queued.min.messages", 100)), + expect_stall=True, + why="H3's POSITIVE control: a local queue too small to stay ahead of the loop, so " + "the fetch-stall signature is produced on demand and can be compared"), +) +_H_PHASES: dict[str, tuple[str, ...]] = { + # Observational first, and nothing is toggled in it: the correlations have to be visible in + # the untouched arm before any toggle is worth running (docs/investigating.md). + "observe": ("H-base", "T-base"), + "toggle": ("H-base", "H-gcoff", "H-queue", "H-fresh"), + "positive": ("H-base", "H-gcforce", "H-starve"), + # Added after the smoke pass, not planned: H-base ran first in every rep and was slow in + # both, where f2-rerun ran tumbling first and found hopping mostly fast. Read position is a + # term the pre-registration did not name, so it gets an arm of its own before anything else + # is toggled - the same move the key-count control made in the section above. + "order": ("H-first", "T-base", "H-second"), + # A ladder rather than a toggle: the observational pass localised the stall to one poll of + # 0.57-0.66s at a fixed point in the stream, which is what a partially-elapsed 1,000 ms + # librdkafka fetch-queue backoff looks like. Moving the timer and predicting the stall's + # LENGTH is a stronger claim than removing it. + "backoff": ("H-base", "H-backoff100", "H-backoff10"), +} + + +def _print_host_runs(title: str, runs: list[HostRun]) -> None: + """Per-arm distribution AND the per-run correlation table, because a bimodal quantity has no + median worth printing on its own - the finding is which runs are slow and what else was true + of them.""" + print(f"\n {title}") + by_arm: dict[str, list[HostRun]] = {} + for run in runs: + by_arm.setdefault(f"{run.arm} {run.spec}", []).append(run) + for label, arm_runs in by_arm.items(): + rates = sorted(run.rate for run in arm_runs) + folds = sorted(run.fold_rate for run in arm_runs) + print(f" {label:<22s} n={len(rates):<3d} median {statistics.median(rates):9,.0f} " + f"rec/s min-max {min(rates):,.0f}-{max(rates):,.0f} " + f"spread {max(rates) / min(rates):.2f}x") + print(" wall-clock samples: " + + " / ".join(f"{rate:,.0f}" for rate in rates)) + print(f" fold-only rate: median {statistics.median(folds):9,.0f} " + f"min-max {min(folds):,.0f}-{max(folds):,.0f} " + f"spread {max(folds) / min(folds):.2f}x") + stalled = [run for run in arm_runs if run.empty_polls] + print(f" empty polls: {sum(run.empty_polls for run in arm_runs)} across " + f"{len(stalled)}/{len(arm_runs)} runs; gen2 collections " + f"{sum(run.gc_gen2 for run in arm_runs)}; collector pause total " + f"{sum(run.gc_pause_s for run in arm_runs):.3f}s") + print("\n every run, sorted by rate - the correlation table:") + print(f" {'arm':<10s} {'spec':<11s} {'rep':>3s} {'rec/s':>9s} {'window':>8s} " + f"{'fold':>7s} {'consume':>8s} {'empty':>6s} {'>100ms':>7s} {'maxgap':>7s} " + f"{'gap@rec':>9s} {'cpu/wall':>8s} {'gen2':>5s} {'gcpause':>8s} {'calib':>7s} " + f"{'load1':>6s}") + for run in sorted(runs, key=lambda r: r.rate): + print(f" {run.arm:<10s} {run.spec:<11s} {run.rep:>3d} {run.rate:>9,.0f} " + f"{run.window_s:>8.3f} {run.fold_s:>7.3f} {run.consume_s:>8.3f} " + f"{run.empty_polls:>6d} {run.long_polls:>7d} {run.max_gap_s:>7.3f} " + f"{run.max_gap_at:>9,d} " + f"{(run.cpu_s / run.window_s if run.window_s else 0):>8.2f} {run.gc_gen2:>5d} " + f"{run.gc_pause_s:>8.3f} {run.calib_s * 1e3:>6.1f}m {run.load1:>6.2f}") + + +def run_host_bimodal(args: argparse.Namespace) -> int: + """Settle WHY arm H's hopping-12 rate is bimodal, with control arms rather than argument. + + The F2 retake (``f2-rerun``) found arm H's hopping-12 rate bimodal across twelve samples - + one at 92,254 rec/s, ten between 372,571 and 487,071 - while its tumbling rate reproduced + across sessions. Until that is settled F2 at hopping-12 has no median worth quoting, so this + experiment exists to attribute it. + + THREE PHASES, IN THIS ORDER, AND THE ORDER IS THE METHOD: + + 1. ``observe`` - the untouched loop at both specifications, many reps, nothing toggled, with + every run's window decomposed (fold vs consume vs empty-poll wait), its CPU time, its + collector passes and pauses, and a pure-CPU calibration beside it. A hypothesis that + cannot show its signature HERE does not deserve a toggle. + 2. ``toggle`` - paired single-term arms, interleaved within each rep, for the hypotheses the + observational pass leaves live. + 3. ``positive`` - arms that force each candidate mechanism to happen, so it is priced. This + is the phase the previous round said the follow-up needed: the slow mode appeared once in + twelve, so a toggle arm showing 'no slow runs' proves almost nothing at any affordable n, + whereas an arm that makes the mode appear ON DEMAND settles the mechanism in three reps. + + Record count and key count come from ``--floor-records`` and ``--keys`` so this can be run at + U6's exact arm-H conditions (128,000 records, 8,000 keys) - the condition under which every + slow sample so far was taken. + """ + records = args.floor_records + keys = args.keys + phases = [p.strip() for p in args.bimodal_phases.split(",") if p.strip()] + by_label = {arm.label: arm for arm in _H_ARMS} + print("host-bimodal - why arm H's hopping-12 rate is bimodal, with control arms") + print(f" records per run {records:,}") + print(f" keys {keys:,}") + print(f" partitions {args.partitions}, {args.payload_bytes} B payloads") + print(f" reps observe {args.reps}, toggle/positive " + f"{args.bimodal_control_reps} (arms interleaved within each rep)") + print(f" phases {', '.join(phases)}") + print(f" load limit {args.load_limit:g} (1-minute load read and recorded " + "beside every run)") + print(" engine none - arm H needs no engine, no sidecar and no classpath") + + admin = AdminClient({"bootstrap.servers": args.bootstrap}) + shared = _seed_host_topic(args, records, keys, "bimodal") + fresh_topics: list[str] = [] + try: + for phase in phases: + labels = _H_PHASES[phase] + reps = args.reps if phase == "observe" else args.bimodal_control_reps + print(f"\n=== phase {phase}: {', '.join(labels)}, {reps} reps ===") + for label in labels: + print(f" {label:<10s} {by_label[label].why}") + runs: list[HostRun] = [] + for rep in range(1, reps + 1): + print(f"\n rep {rep}/{reps}") + for label in labels: + arm = by_label[label] + topic = shared + if arm.fresh_topic: + topic = _seed_host_topic(args, records, keys, f"fresh-{rep}") + fresh_topics.append(topic) + runs.append(measure_host(args, topic, records, keys, arm.window, arm.spec, + arm=arm, rep=rep, verbose=True)) + _print_host_runs(f"phase {phase}", runs) + finally: + if not args.keep_topics: + delete_run_topics(admin, [shared, *fresh_topics]) + return 0 + + def _shared_phase(args: argparse.Namespace, sweep: list[int]) -> tuple[ list[PlacementRun], list[HostRun], tuple[PlacementRun, PlacementRun] | None]: """Arms A, B, C, D and H at the shared load, interleaved, swept in crossings.""" @@ -1343,10 +2251,585 @@ def run_placement(args: argparse.Namespace) -> int: return 0 +@dataclasses.dataclass(frozen=True) +class FloorArm: + """One engine-floor arm: a label, the placement arm it borrows its topology from, and the + ONE term it moves against the baseline. Everything unstated is U6's condition.""" + + label: str + arm: str # "D" (hop 1h/5m, crossing-free) or "A" (tumbling, host function) + toggle: str # what this arm moves; "-" for the baseline + cache_bytes: int = 0 + commit_ms: int | None = None + threads: int | None = None + sink_on: bool = True + changelog_on: bool = True + delay_ms: float = 0.0 + + +_FLOOR_ARMS: tuple[FloorArm, ...] = ( + FloorArm("D0", "D", "-"), + FloorArm("D-cache", "D", "statestore.cache.max.bytes 0 -> 64 MB", cache_bytes=64 * 1024 * 1024), + FloorArm("D-nolog", "D", "changelog on -> off", changelog_on=False), + FloorArm("D-commit", "D", "commit.interval.ms 200 -> 5000", commit_ms=5000), + FloorArm("D-nosink", "D", "sink on -> off", sink_on=False), + FloorArm("D-t1", "D", "num.stream.threads 8 -> 1", threads=1), + FloorArm("T0", "A-free", "hopping 1h/5m -> tumbling 1h (multiplier 12 -> 1)"), + # The two toggles that turned out to matter, applied together: the best case a crossing-free + # wrapper can reach at all, which is the number the F2 comparison actually wants. + FloorArm("T0-cache", "A-free", "tumbling AND cache 64 MB (both winning toggles)", + cache_bytes=64 * 1024 * 1024), +) + +_INSTRUMENT_ARMS: tuple[FloorArm, ...] = ( + FloorArm("I0", "A", "instrument check control: host fn, no delay"), + FloorArm("I100", "A", "instrument check: +0.1 ms per record in the host fn", delay_ms=0.1), + # 0.1 ms did not move the figure, and the reason is structural rather than instrumental: the + # client dispatches invocations to a thread pool, so a delay smaller than the crossing it rides + # on is absorbed by concurrency rather than added to the critical path. 1 ms exceeds what the + # pool can hide, which is what makes it a check the instrument can actually fail. + FloorArm("I1000", "A", "instrument check: +1 ms per record in the host fn", delay_ms=1.0), +) + + +def _run_floor_arm(args: argparse.Namespace, arm: FloorArm, records: int, + show_topology: bool = False) -> PlacementRun: + """One engine-floor arm, run through the shared ``measure_placement`` machinery. + + Extracted from ``run_engine_floor`` when the in-session F2 re-run needed the SAME arm + definitions in a different order beside arm H. A second copy of the toggle plumbing would + have drifted from this one the first time an arm learned a new term - the lab's KTD14, the + reason every experiment here is a function rather than a sibling file. + + ``arm.arm`` names a row of ``_ARMS``: "D" is the hopping-12 crossing-free topology and + "A-free" the tumbling one, both with NO host function registered, so their zero crossings are + measured (an engine-side invocation would name an unregistered token and fail the run). + """ + return measure_placement( + args, arm.arm, records, args.keys, arm.cache_bytes, + show_topology=show_topology, commit_ms=arm.commit_ms, threads=arm.threads, + sink_on=arm.sink_on, changelog_on=arm.changelog_on, delay_ms=arm.delay_ms) + + +def _print_floor_table(arms: tuple[FloorArm, ...], runs: dict[str, list[PlacementRun]], + baseline_label: str = "D0") -> None: + """The per-arm table: median over reps, min-max beside, ratio against the baseline arm.""" + print("\n results - rec/s on the sink's log-append clock (committed-offset clock beside it)") + print(f" {'arm':10s} {'toggle':46s} {'rec/s (min-max)':>26s} {'us/rec':>9s} " + f"{'us/rec/window':>14s} {'emits':>10s}") + baseline = statistics.median(r.rate or r.committed_rate + for r in runs.get(baseline_label, next(iter(runs.values())))) + for arm in arms: + got = runs.get(arm.label) + if not got: + continue + rates = [r.rate or r.committed_rate for r in got] + median = statistics.median(rates) + multiplier = got[0].multiplier + print(f" {arm.label:10s} {arm.toggle:46s} " + f"{median:9,.0f} ({min(rates):,.0f}-{max(rates):,.0f}) " + f"{1e6 / median:9.1f} {1e6 / median / multiplier:14.1f} " + f"{statistics.median(r.emits for r in got):10,.0f}" + f" x{median / baseline:.2f} vs {baseline_label}") + + +def run_engine_floor(args: argparse.Namespace) -> int: + """The engine-floor decomposition: U6 arm D's crossing-free run, one term moved per arm. + + Registered in docs/inflight/perf-streams-engine-floor.md before any arm ran. Arms are + INTERLEAVED within each repetition rather than blocked, so machine drift lands on all of them + - the same rule every prior crossing measurement here was re-learned by. + """ + records = args.floor_records + print("engine-floor experiment - where the microseconds go with NOTHING crossing") + print(f" records per run {records:,}") + print(f" keys {args.keys:,}") + print(f" reps {args.reps} (arms interleaved within each rep)") + print(f" baseline conditions cache 0 B, commit {args.commit_interval_ms} ms, " + f"{args.stream_threads} threads, sink on, changelog on") + runs: dict[str, list[PlacementRun]] = {} + arms = _FLOOR_ARMS + (_INSTRUMENT_ARMS if args.floor_instrument else ()) + if args.floor_arms: + wanted = {label.strip() for label in args.floor_arms.split(",")} + arms = tuple(a for a in _FLOOR_ARMS + _INSTRUMENT_ARMS if a.label in wanted) + if not arms: + raise SystemExit(f"no engine-floor arm matches {sorted(wanted)}") + for rep in range(args.reps): + print(f"\n rep {rep + 1}/{args.reps}") + for arm in arms: + runs.setdefault(arm.label, []).append( + _run_floor_arm(args, arm, records, show_topology=(rep == 0))) + _print_floor_table(arms, runs) + if args.floor_instrument: + control = statistics.median(r.rate for r in runs["I0"]) + slowed = statistics.median(r.rate for r in runs["I100"]) + moved = 1e6 / slowed - 1e6 / control + print(f"\n INSTRUMENT CHECK: +100us/record injected moved the per-record figure by " + f"{moved:,.0f}us ({1e6 / control:,.0f} -> {1e6 / slowed:,.0f} us/rec). " + f"A figure that cannot move is not measuring the engine.") + return 0 + + +_F2_ANCHOR_RATES: dict[str, float] = {"D0": 16_758.0, "T0": 81_946.0} +"""The 2026-08-25 medians of the two CACHE-OFF arms, at exactly these conditions (1,000 keys, +64,000 records, 8 partitions, 8 stream threads, commit 200 ms, 1 KB payloads). + +They are re-run here as ANCHORS, not as filler. Nothing else ties this session's box to that one: +the cache-on arms and arm H are being compared for the first time in a single session, and their +ratio is only readable against a decomposition taken on a different day if the two arms both days +share land in the same place. A disagreeing anchor is a finding about the box - it is reported, +never tuned away. Source: docs/inflight/perf-streams-engine-floor.md, section +"The decomposition, measured 2026-08-25".""" + +_F2_HOST_CONTROL_LABEL = "H@{keys}k" +"""How the arm-H key-count control is labelled in the summary - it is arm H with exactly one term +moved (the key count), so it reads as an arm rather than as a footnote.""" + +_F2_ENGINE_ORDER: tuple[str, ...] = ("T0-cache", "D-cache", "D0", "T0") +"""The engine arms of the F2 re-run, in the order they run WITHIN each repetition - after arm H, +which goes first while no sidecar is up (``_shared_phase``'s rule, inherited: the engine is idle +there, and a broken H arm surfaces before the rep's engine runs rather than after them). The two +cache-on arms lead because they carry the verdict; the two cache-off anchors follow.""" + + +def run_f2_rerun(args: argparse.Namespace) -> int: + """F2 retaken IN ONE SESSION: arm H interleaved with the cache-on crossing-free arms. + + The engine-floor decomposition established that ~75 percent of the measured floor was an + instrument choice (``statestore.cache.max.bytes=0``) and reported the consequence for F2 - + the reimplementation floor - by reading this note's cache-on arms against arm H figures + measured in U6's session. That is a cross-session comparison, which the project's + pre-registered discipline (U6's KTD18, in-session control arms) forbids: two sessions differ + by ambient load, page cache and broker state, and a ratio taken across them attributes drift + to the term under test. + + So every arm here runs in one session, interleaved within each repetition, at ONE record + count and ONE key count: + + - arm H at both specifications first, on this process's wall clock (H produces nothing, so it + has no log-append record of its own progress) while no engine is up; + - ``T0-cache`` and ``D-cache``, the wrapper's best case at each specification; + - ``D0`` and ``T0``, the cache-off anchors that tie this box to 2026-08-25's; + - arm H again at ``--f2-host-control-keys``, the key-count control. The engine arms run at + 1,000 keys rather than U6's 8,000 because a 64 MB cache over an 8,000-key hopping working + set would measure eviction thrash - but that deviation lands on arm H too, and U6's arm-H + figures were taken at 8,000. Moving only the key count, in this session, says whether a + disagreement with U6's arm H is the key count or the box. + + THE RECORD COUNT IS RECONCILED DELIBERATELY. ``run_engine_floor`` reads ``--floor-records`` + and ``run_host_reimpl`` reads ``max(--crossings-sweep)``; a comparison whose two sides ran at + different loads is void, so this experiment drives BOTH sides from ``--floor-records`` and + arm H's own record count follows the engine's. + """ + records = args.floor_records + by_label = {arm.label: arm for arm in _FLOOR_ARMS + _INSTRUMENT_ARMS} + engine_arms = tuple(by_label[label] for label in _F2_ENGINE_ORDER) + # I100 is deliberately NOT run: 0.1 ms was refuted as too small in the 2026-08-25 session - + # the client dispatches invocations onto a thread pool, which absorbs a delay smaller than + # the crossing it rides on. I0 is the crossing control against T0 (same topology, one + # registered host function between them); I1000 is the injected-cost check at a magnitude + # the pool cannot hide. + instrument_arms = (tuple(by_label[label] for label in ("I0", "I1000")) + if args.floor_instrument else ()) + + print("f2-rerun - the F2 comparison retaken IN-SESSION, arm H interleaved with the " + "cache-on arms") + print(f" records per run {records:,} (engine arms AND arm H - one count, " + "reconciled)") + print(f" keys {args.keys:,}") + print(f" reps {args.reps} (arms interleaved within each rep, H first)") + print(f" partitions {args.partitions}, {args.stream_threads} stream threads, " + f"{args.payload_bytes} B payloads") + print(f" commit.interval.ms {args.commit_interval_ms} (set explicitly)") + print(f" quiescence {args.quiescence_intervals} commit intervals, each break " + "confirmed against sink end offsets after a further 2x, and the engine group must " + "have committed the whole seeded backlog") + print(f" event time constant {_EVENT_TIME_MS} ms for every record") + print(f" load limit {args.load_limit:g} (1-minute load read and recorded " + "beside every run)") + print(" crossings every engine arm registers NO host function, so its zero " + "crossings are measured client-side rather than assumed") + print(f" order within a rep H tumbling, H hopping-12, " + f"{', '.join(_F2_ENGINE_ORDER)}" + + (f", {', '.join(a.label for a in instrument_arms)}" if instrument_arms else "")) + print(f" JAVA_TOOL_OPTIONS {os.environ.get('JAVA_TOOL_OPTIONS', '(unset)')}") + + control_keys = args.f2_host_control_keys + if control_keys: + print(f" arm-H key control {control_keys:,} keys beside the {args.keys:,} the " + "engine arms run at - the ONE term that differs from U6's arm H, moved in-session " + "so a disagreement with U6's figures is attributed rather than explained") + + h_topic = _seed_host_topic(args, records, args.keys, "f2") + control_topic = (_seed_host_topic(args, records, control_keys, "f2-control") + if control_keys else None) + runs: dict[str, list[PlacementRun]] = {} + h_runs: list[HostRun] = [] + control_runs: list[HostRun] = [] + try: + for rep in range(args.reps): + print(f"\n rep {rep + 1}/{args.reps}") + h_runs.append(measure_host(args, h_topic, records, args.keys, _TUMBLE, "tumbling")) + h_runs.append(measure_host(args, h_topic, records, args.keys, _HOP5, "hopping-12")) + if control_topic is not None: + # Arm H again with exactly ONE term moved - the key count. Nothing else differs: + # same session, same records, same payload, same partitions, same consume loop. + control_runs.append(measure_host(args, control_topic, records, control_keys, + _TUMBLE, "tumbling")) + control_runs.append(measure_host(args, control_topic, records, control_keys, + _HOP5, "hopping-12")) + for arm in engine_arms + instrument_arms: + runs.setdefault(arm.label, []).append( + _run_floor_arm(args, arm, records, show_topology=(rep == 0))) + finally: + if not args.keep_topics: + topics = [h_topic] + ([control_topic] if control_topic is not None else []) + delete_run_topics(AdminClient({"bootstrap.servers": args.bootstrap}), topics) + + _print_floor_table(engine_arms + instrument_arms, runs) + + print("\n arm H, this session - single-threaded, NON-DURABLE (no store, no changelog, no " + "rebalance recovery,") + print(" no late-record handling), so F2 is an UPPER bound on a real reimplementation:") + h_median: dict[str, float] = {} + for spec_label in ("tumbling", "hopping-12"): + rates = [h.rate for h in h_runs if h.spec == spec_label] + h_median[spec_label] = statistics.median(rates) + print(f" arm H {spec_label:<12s} {h_median[spec_label]:9,.0f} " + f"({min(rates):,.0f}-{max(rates):,.0f}) rec/s, {1e6 / h_median[spec_label]:.1f} " + f"us/rec, n={len(rates)}") + + print("\n THE F2 VERDICT, RETAKEN IN-SESSION (wrapper best case vs arm H at the SAME " + "specification, same session, interleaved):") + for spec_label, wrapper in (("tumbling", "T0-cache"), ("hopping-12", "D-cache")): + wrapper_rate = statistics.median(r.rate for r in runs[wrapper]) + host_rate = h_median[spec_label] + print(f" {spec_label:<11s} {wrapper:9s} {wrapper_rate:9,.0f} rec/s arm H " + f"{host_rate:9,.0f} rec/s -> H is {host_rate / wrapper_rate:.2f}x the wrapper") + + if control_runs: + print(f"\n ARM-H KEY-COUNT CONTROL - the same consume loop at {control_keys:,} keys " + f"(U6's) instead of {args.keys:,}, one term moved, same session:") + for spec_label in ("tumbling", "hopping-12"): + rates = [h.rate for h in control_runs if h.spec == spec_label] + control_median = statistics.median(rates) + print(f" H {spec_label:<11s} {args.keys:>6,} keys {h_median[spec_label]:9,.0f} " + f"rec/s {control_keys:>6,} keys {control_median:9,.0f} " + f"({min(rates):,.0f}-{max(rates):,.0f}) rec/s -> the key count is worth " + f"{h_median[spec_label] / control_median:.2f}x on arm H alone") + + print("\n ANCHORS - the two cache-off arms against their 2026-08-25 medians at the same " + "conditions:") + for label, then in _F2_ANCHOR_RATES.items(): + now = statistics.median(r.rate for r in runs[label]) + print(f" {label:9s} this session {now:9,.0f} rec/s 2026-08-25 {then:9,.0f} rec/s " + f"-> {now / then:.2f}x") + + if instrument_arms: + t0_us = 1e6 / statistics.median(r.rate for r in runs["T0"]) + i0_us = 1e6 / statistics.median(r.rate for r in runs["I0"]) + i1000_us = 1e6 / statistics.median(r.rate for r in runs["I1000"]) + print("\n INSTRUMENT CHECK, both halves - a figure that cannot move is not measuring " + "the engine:") + print(f" crossing: T0 -> I0 adds exactly one registered host function to the same " + f"tumbling topology, {t0_us:,.1f} -> {i0_us:,.1f} us/rec, delta " + f"{i0_us - t0_us:,.0f}us against U6's independently fitted 135us per crossing") + print(f" injected: I0 -> I1000 adds +1,000us/record host-side, {i0_us:,.1f} -> " + f"{i1000_us:,.1f} us/rec, delta {i1000_us - i0_us:,.0f}us - the client's thread " + "pool absorbs the rest, a known property of this harness rather than a new result") + + loads = ([r.load1 for arm_runs in runs.values() for r in arm_runs] + + [h.load1 for h in h_runs + control_runs]) + print(f"\n 1-minute load beside the {len(loads)} runs: {min(loads):.2f}-{max(loads):.2f} " + f"(median {statistics.median(loads):.2f}, limit {args.load_limit:g})") + return 0 + + +_LADDER_ARMS: tuple[HostArm, ...] = ( + HostArm(label="H-base", spec="hopping-12", + why="the control: plain arm H, stateless and non-durable, unchanged"), + HostArm(label="H-dur-per", spec="hopping-12", changelog_mode="per-update", + why="durability, written the naive way - one awaited changelog record per state " + "update, which is what a reimplementer writes first"), + HostArm(label="H-dur-coal", spec="hopping-12", changelog_mode="coalesced", + why="durability, written the careful way - the dirty (key, window) set flushed once " + "per commit interval, which is what the engine's state-store cache does"), + HostArm(label="H-dur-nowait", spec="hopping-12", changelog_mode="per-update", + changelog_acks="0", changelog_await=False, + why="the same changelog volume with the wait removed - not durable, and here to " + "price how fast an accidentally-non-durable arm would have looked"), +) +"""The first rung of the crossover ladder (astubbs#242), each arm ONE feature from ``H-base``. + +Spec-agnostic: the experiment replaces ``spec`` per specification, so an arm is defined by its +durability term alone and the two window specifications cannot drift apart.""" + +_LADDER_ENGINE_ORDER: tuple[str, ...] = ("T0-cache", "D-cache", "D0", "T0") +"""The engine arms, in the order they run within a repetition - after the host arms, which go +first while no sidecar is up (``_shared_phase``'s inherited rule). The two cache-on arms carry +the comparison; ``D0`` and ``T0`` are the cache-off anchors that tie this box to the two prior +sessions through ``_F2_ANCHOR_RATES``.""" + + +def run_crossing_ladder(args: argparse.Namespace) -> int: + """The crossover ladder, rung 1: what does DURABILITY cost the reimplementation? + + Every F2 verdict in this program compares the wrapper against arm H - a bare dict, stateless + and non-durable. The owner's judgement, recorded in ``STRATEGY.md`` and in + ``docs/solutions/architecture-patterns/`` + ``a-per-record-crossing-loses-to-reimplementation-before-features-enter.md``, is that this + comparison decides nothing: a toy beats an engine at toy work at any transport speed. The + question that decides it is the CROSSOVER - how many of the features a user actually came for + can be added back to that dictionary before hand-rolling becomes the worse choice. + + This experiment takes the first step. It adds ONE feature - durability, meaning a changelog + per state update plus a restore that rebuilds the dict from it - and measures what it costs, + at two write granularities, against ``H-base`` and against the wrapper's cache-on + crossing-free arms IN THE SAME SESSION (KTD18). It reports restore time as its own figure, + because steady-state throughput and restart latency are different quantities. + """ + records = args.floor_records + by_label = {arm.label: arm for arm in _FLOOR_ARMS + _INSTRUMENT_ARMS} + engine_arms = tuple(by_label[label] for label in _LADDER_ENGINE_ORDER) + + print("crossing-ladder rung 1 - what DURABILITY costs the reimplementation") + print(f" records per run {records:,} (host arms AND engine arms - one count)") + print(f" keys {args.keys:,}") + print(f" reps {args.reps} (arms interleaved within each rep, host first)") + print(f" partitions {args.partitions}, {args.stream_threads} stream threads, " + f"{args.payload_bytes} B payloads") + print(f" commit.interval.ms {args.commit_interval_ms} - the engine's commit cadence AND " + "the durable arms' boundary interval, so both sides flush at the same rate") + print(f" quiescence {args.quiescence_intervals} commit intervals (engine arms)") + print(f" event time constant {_EVENT_TIME_MS} ms for every record") + print(f" load limit {args.load_limit:g} (1-minute load beside every run)") + backoff = args.host_fetch_queue_backoff_ms + print(" fetch.queue.backoff.ms " + (f"{backoff} (set explicitly)" if backoff is not None + else "librdkafka's default 1,000 - the record count " + "sits below the 80,000-96,000 stall threshold " + "measured in the bimodality section")) + print(f" restore control a second read of every changelog with " + f"fetch.queue.backoff.ms={args.ladder_restore_backoff_ms}") + print(f" JAVA_TOOL_OPTIONS {os.environ.get('JAVA_TOOL_OPTIONS', '(unset)')}") + print(" arms " + ", ".join(f"{a.label} ({a.why})" for a in _LADDER_ARMS)) + + h_topic = _seed_host_topic(args, records, args.keys, "ladder") + admin = AdminClient({"bootstrap.servers": args.bootstrap}) + host_runs: list[HostRun] = [] + restores: list[RestoreRun] = [] + runs: dict[str, list[PlacementRun]] = {} + try: + for rep in range(args.reps): + print(f"\n rep {rep + 1}/{args.reps}") + for spec_label, window in (("tumbling", _TUMBLE), ("hopping-12", _HOP5)): + multiplier = -(-window.size_ms // window.advance_ms) + for base_arm in _LADDER_ARMS: + arm = dataclasses.replace(base_arm, spec=spec_label) + changelog = (_new_changelog_topic(args, f"{arm.label}-{spec_label}") + if arm.changelog_mode != "none" else None) + try: + run = measure_host(args, h_topic, records, args.keys, window, spec_label, + arm=arm, rep=rep + 1, verbose=True, + changelog_topic=changelog) + host_runs.append(run) + if changelog is not None and arm.changelog_await: + # The nowait arm's changelog is byte-for-byte the same shape as + # H-dur-per's, so restoring it would re-measure the same quantity. + for backoff in (None, args.ladder_restore_backoff_ms): + restores.append(restore_host( + args, changelog, args.keys * multiplier, + arm=arm.label, spec=spec_label, backoff_ms=backoff)) + finally: + if changelog is not None and not args.keep_topics: + delete_run_topics(admin, [changelog]) + for arm in engine_arms: + runs.setdefault(arm.label, []).append( + _run_floor_arm(args, arm, records, show_topology=(rep == 0))) + finally: + if not args.keep_topics: + delete_run_topics(admin, [h_topic]) + + _print_floor_table(engine_arms, runs) + + print("\n THE LADDER - arm H with one feature added back, per specification") + print(f" {'arm':14s} {'spec':11s} {'rec/s (min-max)':>28s} {'us/rec':>9s} " + f"{'changelog recs':>15s} {'durable share':>14s}") + ladder: dict[tuple[str, str], float] = {} + for spec_label in ("tumbling", "hopping-12"): + for base_arm in _LADDER_ARMS: + got = [h for h in host_runs if h.arm == base_arm.label and h.spec == spec_label] + if not got: + continue + rates = [h.rate for h in got] + median = statistics.median(rates) + ladder[(base_arm.label, spec_label)] = median + share = statistics.median( + (h.durable_s / h.window_s if h.window_s else 0.0) for h in got) + print(f" {base_arm.label:14s} {spec_label:11s} " + f"{median:11,.0f} ({min(rates):,.0f}-{max(rates):,.0f}) " + f"{1e6 / median:9.1f} " + f"{statistics.median(h.changelog_records for h in got):15,.0f} " + f"{share:13.0%}") + + print("\n WHERE DURABILITY PUTS THE CROSSOVER - wrapper best case against each rung, same " + "session, interleaved:") + for spec_label, wrapper in (("tumbling", "T0-cache"), ("hopping-12", "D-cache")): + wrapper_rate = statistics.median(r.rate for r in runs[wrapper]) + print(f" {spec_label}: wrapper {wrapper} {wrapper_rate:,.0f} rec/s " + "(cache on, changelog ON, so it is durable too)") + for base_arm in _LADDER_ARMS: + rate = ladder.get((base_arm.label, spec_label)) + if rate is None: + continue + ratio = rate / wrapper_rate + side = "reimplementation ahead" if ratio >= 1 else "WRAPPER AHEAD" + print(f" {base_arm.label:14s} {rate:11,.0f} rec/s " + f"H/wrapper = {ratio:6.2f}x {side}") + + if restores: + print("\n RESTORE - rebuilding the dict from the changelog, its own figure:") + print(f" {'arm':14s} {'spec':11s} {'backoff':>9s} {'seconds (min-max)':>26s} " + f"{'changelog recs':>15s} {'entries':>9s} {'>100ms polls':>13s}") + seen_keys = [] + for restore in restores: + probe_key = (restore.arm, restore.spec, restore.backoff_ms) + if probe_key in seen_keys: + continue + seen_keys.append(probe_key) + matching = [r for r in restores + if (r.arm, r.spec, r.backoff_ms) == probe_key] + seconds = [r.seconds for r in matching] + print(f" {restore.arm:14s} {restore.spec:11s} " + f"{'default' if restore.backoff_ms is None else f'{restore.backoff_ms}ms':>9s} " + f"{statistics.median(seconds):9.3f} ({min(seconds):.3f}-{max(seconds):.3f}) " + f"{restore.records:15,} {restore.entries:9,} " + f"{max(r.long_polls for r in matching):13d}") + + print("\n INSTRUMENT CHECK - the durability term must be visible on the broker, not just " + "claimed by the producer:") + for spec_label in ("tumbling", "hopping-12"): + for base_arm in _LADDER_ARMS: + got = [h for h in host_runs if h.arm == base_arm.label and h.spec == spec_label + and h.changelog_records] + if not got: + continue + produced = [h.changelog_records for h in got] + landed = [h.changelog_end for h in got] + lost = [h.changelog_records - h.changelog_end for h in got] + print(f" {base_arm.label:14s} {spec_label:11s} n={len(got)} produced " + f"{min(produced):,}-{max(produced):,} changelog records/run; broker end " + f"offsets {min(landed):,}-{max(landed):,}; MISSING {min(lost):,}-" + f"{max(lost):,} -> " + f"{'MATCH' if max(lost) == 0 else 'SHORTFALL - this arm is NOT durable'}") + + print("\n ANCHORS - the two cache-off arms against their 2026-08-25 medians:") + for label, then in _F2_ANCHOR_RATES.items(): + if label not in runs: + continue + now = statistics.median(r.rate for r in runs[label]) + print(f" {label:9s} this session {now:9,.0f} rec/s 2026-08-25 {then:9,.0f} rec/s " + f"-> {now / then:.2f}x") + + loads = ([r.load1 for arm_runs in runs.values() for r in arm_runs] + + [h.load1 for h in host_runs] + [r.load1 for r in restores]) + print(f"\n 1-minute load beside the {len(loads)} runs: {min(loads):.2f}-{max(loads):.2f} " + f"(median {statistics.median(loads):.2f}, limit {args.load_limit:g})") + return 0 + + +def run_ladder_kill_child(args: argparse.Namespace) -> int: + """One durable arm-H run, as a CHILD process the parent is about to SIGKILL. + + A separate entry point rather than a fork, because forking a process that already holds + librdkafka handles is not safe; the child builds its own clients from the flags it was + given. It runs until it is killed - which is the point - so a clean exit means the parent + was too slow and the parent says so. + """ + arm = dataclasses.replace( + next(a for a in _LADDER_ARMS if a.label == args.ladder_child_arm), + spec=args.ladder_child_spec) + window = _TUMBLE if args.ladder_child_spec == "tumbling" else _HOP5 + measure_host(args, args.ladder_child_source, args.floor_records, args.keys, window, + args.ladder_child_spec, arm=arm, verbose=True, + changelog_topic=args.ladder_child_changelog) + return 0 + + +def run_ladder_kill(args: argparse.Namespace) -> int: + """KILL AND REBUILD, literally: SIGKILL a durable arm mid-run, restore from its changelog. + + ``restore_host`` on a complete changelog already measures the rebuild, but it never proves + the thing durability is FOR - that state written before an uncontrolled death is still there + afterwards. Here the writer is a separate process, killed with SIGKILL so nothing flushes, + nothing closes and no ``finally`` runs; the parent then rebuilds from whatever reached the + broker and reports how much state survived and how long it took to get back. + """ + print("ladder-kill - SIGKILL a durable arm-H writer mid-run, then rebuild from its changelog") + print(f" arm {args.ladder_child_arm} {args.ladder_child_spec}, {args.floor_records:,} " + f"records, {args.keys:,} keys, kill after {args.ladder_kill_after_ms} ms") + source = _seed_host_topic(args, args.floor_records, args.keys, "kill") + admin = AdminClient({"bootstrap.servers": args.bootstrap}) + multiplier = 1 if args.ladder_child_spec == "tumbling" else 12 + try: + for rep in range(args.reps): + changelog = _new_changelog_topic(args, f"kill-{rep}") + try: + command = [sys.executable, str(pathlib.Path(__file__).resolve()), + "ladder-kill-child", + "--bootstrap", args.bootstrap, + "--keys", str(args.keys), + "--partitions", str(args.partitions), + "--payload-bytes", str(args.payload_bytes), + "--commit-interval-ms", str(args.commit_interval_ms), + "--floor-records", str(args.floor_records), + "--load-limit", str(args.load_limit), + "--ladder-child-arm", args.ladder_child_arm, + "--ladder-child-spec", args.ladder_child_spec, + "--ladder-child-source", source, + "--ladder-child-changelog", changelog] + child = subprocess.Popen(command, stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL) + time.sleep(args.ladder_kill_after_ms / 1000.0) + if child.poll() is not None: + raise RuntimeError( + f"the writer finished before it could be killed (exit {child.returncode})" + " - lower --ladder-kill-after-ms; a clean exit proves nothing about " + "surviving a kill") + child.kill() + # SIGKILL, so nothing flushed, nothing closed and no finally ran. Everything on + # the broker got there through a boundary the writer had already awaited. + child.wait(timeout=30) + restored = restore_host(args, changelog, None, arm="kill-rebuild", + spec=args.ladder_child_spec) + full = args.keys * multiplier + print(f" rep {rep + 1}: writer SIGKILLed after " + f"{args.ladder_kill_after_ms} ms; {restored.records:,} changelog records " + f"survived and rebuilt {restored.entries:,} of the {full:,} entries a " + f"complete run holds ({restored.entries / full:.0%}) in " + f"{restored.seconds:.3f}s") + if restored.entries == 0: + raise RuntimeError( + "nothing survived the kill - the arm was not durable at any point, " + "which makes every steady-state figure it produced meaningless") + finally: + if not args.keep_topics: + delete_run_topics(admin, [changelog]) + finally: + if not args.keep_topics: + delete_run_topics(admin, [source]) + return 0 + + EXPERIMENTS = { "hot-key": run_hot_key, "placement": run_placement, "host-reimpl": run_host_reimpl, + "engine-floor": run_engine_floor, + "f2-rerun": run_f2_rerun, + "host-bimodal": run_host_bimodal, + "crossing-ladder": run_crossing_ladder, + "ladder-kill": run_ladder_kill, + "ladder-kill-child": run_ladder_kill_child, } diff --git a/parallel-consumer-proxy-streams/src/main/java/bz/stub/parallelconsumer/streams/TopologyAssembler.java b/parallel-consumer-proxy-streams/src/main/java/bz/stub/parallelconsumer/streams/TopologyAssembler.java index 3995dd023e..f366737963 100644 --- a/parallel-consumer-proxy-streams/src/main/java/bz/stub/parallelconsumer/streams/TopologyAssembler.java +++ b/parallel-consumer-proxy-streams/src/main/java/bz/stub/parallelconsumer/streams/TopologyAssembler.java @@ -389,14 +389,21 @@ private long windowedAggregate(long handle, Initializer initializer, TimeWindowSpec window = handles.get(handle).type().getWindow(); HandleType resultType = windowedType(HandleKind.HANDLE_KIND_TABLE, window); storeValueTypes.put(storeName, resultType.getValueType()); - return mint(upstream.aggregate( - initializer, - aggregator, + Materialized> materialized = Materialized.>as(storeName) .withStoreType(Materialized.StoreType.IN_MEMORY) .withRetention(Duration.ofMillis(window.getRetentionMs())) .withKeySerde(operatorSerde(resultType.getKeyType())) - .withValueSerde(operatorSerde(resultType.getValueType()))), resultType); + .withValueSerde(operatorSerde(resultType.getValueType())); + // MEASUREMENT-ONLY ESCAPE HATCH, off by default: the engine-floor spike needs one arm with the + // changelog term removed and nothing else changed. It is deliberately NOT on the protocol - see + // docs/inflight/perf-streams-engine-floor.md; a real capability would be an additive field on + // Aggregate. A system property rather than an environment variable because the lab already owns + // the engine's JVM arguments and does not own its environment. + if (Boolean.getBoolean("pcStreams.measure.disableChangelog")) { + materialized = materialized.withLoggingDisabled(); + } + return mint(upstream.aggregate(initializer, aggregator, materialized), resultType); } /**