Skip to content

test(perf): add ingest-ceiling harness for the audit write path - #6479

Draft
odedlaz wants to merge 4 commits into
block:mainfrom
odedlaz:olazar/perf-phase0-ingest-harness
Draft

test(perf): add ingest-ceiling harness for the audit write path#6479
odedlaz wants to merge 4 commits into
block:mainfrom
odedlaz:olazar/perf-phase0-ingest-harness

Conversation

@odedlaz

@odedlaz odedlaz commented Aug 21, 2026

Copy link
Copy Markdown

The backend perf deep-dive predicts a hard ingest ceiling from the six sequential round trips in AuditService::log, which sits on the OK path. Nothing in this repo could measure it: there are no criterion benches, and perf/ deliberately covers only the Redis fan-out boundary. This adds the missing instrument. No production code changes.

Three pieces:

  • scripts/start-perf-ingest-rig.sh — one relay process serving two communities resolved by Host (a.localhost / b.localhost both reach 127.0.0.1, so the URL host is the header), on the isolated buzz-harness Compose project. --skip-relay attaches to a relay someone else supervises.
  • crates/buzz-test-client/src/bin/ingest_load.rs — paced generator driving those communities at independently settable rates from one clock.
  • perf/relay_ingest_ceiling.py — owns the experiment and the verdict, exits non-zero on a violated contract, --mode model for review without services. Follows relay_bus_scaling.py.

Two measurement choices that carry the result

Pacing. The generator advances a fixed schedule and never rebases it on the response, and it reports latency from the intended slot as well as from the actual send. A generator that paces with a self-correcting timer and times from the send — the shape wamp_bench.rs uses — silently redefines its own offered rate downward when the relay slows, caps throughput at connections / latency, and keeps the queueing delay out of its percentiles. That hides the damage exactly when the damage is the measurement.

Admission limits. The rig raises them, and this is not incidental. At defaults one identity is capped at 50 events per 5s (human_ws_events_per_sec = 10, widened by ws_admission_budget into a 5s window), and a rejected EVENT gets a NOTICE, which carries no event id — so a NIP-01 client waiting for OK blocks for its whole publish timeout instead of learning it was rejected. Measured here: 50 events land in 2.4s, the next send stalls 30s, the run self-truncates, and the surviving numbers read as a textbook saturation knee at ~1.5/s. A sweep at defaults measures the limiter. The runner therefore invalidates any run where buzz_admission_rejections_total{reason="quota"} moves, and prints the configured limits in the run metadata.

What it measured, and what has since been withdrawn

Standing: the arm separation. With the audit log enabled, delivered/offered collapses
to 0.62 at 800/s and 0.25 at 1600/s. With BUZZ_AUDIT_ENABLED=false, the same rates
deliver 1.0000, and audit_log stayed flat at 63,723 rows through that sweep, so the
control is verified positive rather than assumed. Round 1 also recorded zero quota
rejections, zero admission-unavailable warnings across 302,531 relay log lines, and
zero rejected events or transport errors across all 20 runs. Splitting the same offer
across two communities did not raise the combined ceiling.

Withdrawn: every absolute ceiling figure, including the "~400–494/s plateau" and the
round-trip time back-solved from it. Review found that an initially-empty 1000-slot audit
queue lends up to 1000/duration free accepts to every fixed-duration run — +100/s at
10s — so the numbers are biased upward by an unmeasured amount, consistently, in a way no
number of repeats corrects. The repeats were also run back-to-back inside the queue's
drain window, so they inherited each other's backlog rather than being independent draws.

That was a defect in this harness, and it is fixed in ac64b0bf0 along with the rest of two review panels' findings.

What changed after review

The pass predicate was the load-bearing problem. It derived a threshold from the spread of repeated runs, which is ~0 in the region where accepted/offered is pinned at 1.0 and is the system's own throughput variability in the region where it is not — so no placement of that control made it mean anything. The contract is now that the two arms separate: repeats give each arm an interval and the verdict asks whether the difference between audit-off and audit-on excludes zero at some rate. Nothing gates on the knee, and no comparison reads overlapping intervals as evidence of equality.

Also closed, each of them a route to passing without establishing anything:

  • a single-arm dataset returning ok with attribution never tested, and an audit-off null indistinguishable from a control that never ran — the verdict now carries an explicit ran/skipped marker;
  • --combine accepting halves from different durations, rate grids, limiter settings or source revisions;
  • only quota rejections invalidating a cell, when unavailable rejections take the same NOTICE-without-OK path and cost Redis round trips against the rig the sweep is loading, so they are load-correlated and can forge a knee that survives repeats;
  • the generator failing with its error context captured into an exception instead of reaching the operator, and a null percentile aborting the sweep before any report was written;
  • the rig killing a pid from a stale file without checking it still belongs to this harness.

Cells now carry outstanding_delta and audit_busy_fraction, and the worker-rate estimate is drawn only from cells where the worker was demonstrably busy in steady state. The steady-state criterion is stability, not emptiness — a saturating cell settles with the channel full, and a gate demanding an empty queue would have made every cell that matters unmeasurable.

Scope and limits, stated in the doc

The harness characterizes the mechanism, not deployability at scale — a raised-limit sweep cannot show that a real community reaches these rates, since production defaults would need hundreds of concurrent identities each paying its own admission round trip. Sensitivity to round-trip latency is unmeasured; a sweep of injected delays should predeclare six added exchange delays plus a durability intercept, since disabling synchronous_commit removes the flush wait but not the COMMIT exchange. And the per-community lock ceiling is structurally blind in this round: the worker ceiling is lower and masks it, so a passing run is not evidence the lock is fine.

Verification

cargo clippy --workspace --all-targets -- -D warnings and cargo fmt --all --check clean; cargo test -p buzz-test-client green; python3 -m unittest discover -s perf -p 'test_*.py' 51 tests green; shellcheck clean. The unit tests pair every passing case with a mutant that must fail — a lone dip that must not count as a knee, a control that did not run, an arm separation in the wrong direction, a cell that banked the whole channel, a --combine across mismatched durations — because a contract that cannot go red is decoration.

Larger than the usual single-pass PR, and I'd rather not split it: the generator, the rig, and the verdict logic are not independently useful, and the doc and the mutant tests are the parts that make the numbers trustworthy.

The backend perf findings predict a hard ingest ceiling from the six
sequential round trips in the audit log write, and nothing in this repo
could measure it: there are no criterion benches, and perf/ only covers
the Redis fan-out boundary.

Three pieces. scripts/start-perf-ingest-rig.sh stands up one relay serving
two communities resolved by Host, on the isolated buzz-harness stack.
ingest_load drives them at independently settable rates. relay_ingest_
ceiling.py owns the experiment and exits non-zero on a violated contract,
following relay_bus_scaling.py.

Two measurement choices are load-bearing. The generator paces on a fixed
schedule and reports latency from the intended slot as well as the actual
send: a self-correcting timer measured from the send silently redefines
the offered rate downward under saturation and keeps the queueing delay
out of the percentiles. And the rig raises the admission limits, because
at defaults one identity is capped at 50 events per 5s and a rejected
EVENT gets a NOTICE with no OK, so a sweep would measure the limiter and
draw a knee at a plausible-looking rate; the runner invalidates any run
where the quota-rejection counter moves.

Signed-off-by: Oded Lazar <olazar@neo.ai>
Co-authored-by: Oded Lazar <olazar@neo.ai>
Two review panels found that the harness could report a ceiling from evidence
that did not support one. The pass predicate was the load-bearing problem: it
derived a threshold from the spread of repeated runs, which is ~0 where the
metric is pinned at 1.0 and is the system-under-test's own throughput
variability where it is not. Either placement makes it meaningless.

The contract is now that the two arms separate: repeats give each arm an
interval, and the verdict asks whether the difference between audit-off and
audit-on excludes zero at some rate. Nothing gates on the knee, which is a grid
point rather than a measurement, and no comparison treats overlapping intervals
as evidence of equality.

Also closed, all of them paths by which a run could pass without establishing
anything: a single-arm dataset returning ok with attribution never tested, and
reporting an audit-off null indistinguishable from a control that never ran;
--combine accepting halves from different durations, rate grids, limiter
settings or revisions; only quota rejections invalidating a cell, when
unavailable rejections take the same NOTICE-without-OK path and are
load-correlated, so they can forge a knee that survives repeats; and the
generator dying with its error context captured into an exception.

The bounded audit channel lends a cell up to its full depth in accepted events
before backpressure -- measured as exactly +1000 from an empty start and 0 from
a full one. That is a bias, identical across repeats, so more repeats converge
on a wrong number. Cells now carry outstanding-work and busy-fraction readings,
and the worker-rate estimate is drawn only from cells where the worker was
demonstrably busy in steady state. Accepted throughput stays the arm-separation
quantity, because the audit-off arm has no worker and therefore no completion
series at all.

Trailer order corrected here rather than by amending the pushed commit, which
would need a force-push.

Co-authored-by: Oded Lazar <olazar@neo.ai>
Signed-off-by: Oded Lazar <olazar@neo.ai>
The steady-state gate made every genuine saturating dataset fail its own
contract. Three of the harness's own parts composed into it: a cell is not
steady if outstanding audit work moves by more than a fraction of the channel's
depth, any non-steady cell failed the run, and a saturating cell starting with
that channel empty banks its whole depth in accepted events. The first repeat of
the first saturating rate always starts empty, because the unsaturated rates
before it never filled the channel, so it always banked and always failed. A
rate just above the drain rate is worse: it accumulates over several repeats,
and that is the transition region where the bracket is decided.

A cell that cannot be evidence is now dropped from the arm intervals and the
worker-rate estimate and listed with its reason. That also removes the bias
rather than only the failure -- the banked credit lands in accepted, inflating
that cell's accepted/offered, so it did not belong in the interval either. A
rate needs two surviving repeats per arm to yield a difference interval, and the
run fails when no rate clears that, so exclusion cannot become a way to pass by
discarding almost everything. An audit *enqueue* failure stays fatal: send errors
only when the receiver is dropped, so the worker is gone and later cells are
suspect too.

The suite had been green because the model set every cell steady, including at a
rate above its own ceiling. It now runs the queue forward across repeats and
reproduces the fill, so the green path is tested against the physics.

Also: two-community cells carry problem and steady annotations, since they are
report-only and an unannotated contaminated cell is how a bad number gets quoted
later; and the script header no longer documents the unguarded kill the code
stopped performing.

Co-authored-by: Oded Lazar <olazar@neo.ai>
Signed-off-by: Oded Lazar <olazar@neo.ai>
Two review panels found paths by which the harness could be internally precise
and still answer the wrong experiment. The three that could flip the verdict:

The control was never required to be positive. Audit-off only had to beat
audit-on, so two collapsed arms separated cleanly and passed -- which does not
show that removing the audit path restores ingest. It now has to hold its offer
at the primary contrast, and its audit series has to stay flat, because the rig
JSON claiming audit is off is a claim about how the relay was started and under
--skip-relay nobody verified it.

The pass ran an unadjusted interval at every rate and accepted any positive one.
Measured against this module with identical populations, five rates and n=5, that
passes 9.8% of the time rather than 5%. There is now one predeclared primary
contrast at the highest comparable rate; a reverse separation anywhere
contradicts the hypothesis instead of being ignored.

Counter deltas were read around the whole subprocess while every rate divided by
the post-connect window, so backlog draining during setup landed in the delta but
not the divisor -- overstating completions, allowing a busy fraction above 1.0,
and feeding the exclusion decision. The generator now samples the relay's
counters at its own window edges over a plain TCP GET, needing no new dependency,
and a cell without aligned samples is not evidence.

The default grid also never reached saturation. Its top rate was set before any
drain measurement existed and sat at 81-102% utilisation, so the only informative
cell was a coin flip and a miss printed "the audit path is not shown to limit
ingest" -- a false negative phrased as a conclusion. The grid now spans the
measured band, and more importantly a run that never reaches a busy worker
reports inconclusive rather than exonerating the audit path, so the next stale
constant cannot be read as a finding.

Also: combine validates the cell payload against the identity it claims rather
than only comparing identities; the identity carries a working-tree digest and
whether the database was reset, so two dirty trees at one commit are two builds
and a pair where only one arm was reset is not one experiment; worker rates are
reported per rate instead of pooling load regimes; the sparse t-table rounds to
the conservative side; a generator that misses its scheduled slots disqualifies
its cell; and the pid guard matches this rig's exact binary path.

Co-authored-by: Oded Lazar <olazar@neo.ai>
Signed-off-by: Oded Lazar <olazar@neo.ai>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant