diff --git a/docs/ingest-speedup-2026-08-06.md b/docs/ingest-speedup-2026-08-06.md new file mode 100644 index 0000000..d43d040 --- /dev/null +++ b/docs/ingest-speedup-2026-08-06.md @@ -0,0 +1,81 @@ +# live ingest: 1.5 → 3,016 events/s in three deploys + +The catch-up campaign of 2026-08-05/06, written down so the method survives. +Companion: `ingest-pacing-evidence-2026-08-05.md` (the initial evidence), +`receipts/{6a511fa,2fdc32e,f9e41b2}.json` (every build fully admitted). + +## the ladder + +| build | change | sustained rate | limiter removed | +|---|---|---:|---| +| 29705cb | (baseline, post-OOM restart) | **1.5/s** | — | +| 6a511fa | `--no-verify` (+128 GB resize) | **360/s** | plc.directory in the hot path: verify key cache missed ~50%, each miss an external HTTP call, rate-limited. Every OOM restart re-cleared the cache. | +| 2fdc32e | decode moved off the dispatch path into the worker pool | **768/s** | full CAR hydration ran on the single websocket reader thread — the 32 verify workers did literally nothing with verification off. Atmos decodes only the envelope on dispatch; its block parse runs in parallel workers. Stream had mirrored the letter ("decode on dispatch") and inverted the design. | +| f9e41b2 | `approxBytes` O(n)→O(1) | **3,016/s** | `Compactor.onAppend` → `publishTombstoneGauges` walked all ~119k live-tombstone hashmap entries **per appended event** to update two prometheus gauges — 81% of the pinned core, measured by perf. Replaced with a counter maintained at insert/evict; parity test asserts equality with the walk. | + +Reference points: a bare Python websocket client on the same box drains +~3,700 frames/s from the relay (the transport ceiling); the merge wrote +~70,000 events/s through the same archive (the storage ceiling). At 3,016/s +we sit at ~80% of transport, ~4% of storage — the pipe is now the limit. + +Effect on catch-up: lag 58.6h shrinking at slope ~0.5 (i.e. *growing*) +became lag→0 overnight at slope ~5. The permanent-hole deadline stopped +being a deadline. + +## the method (this is the part to reuse) + +1. **Bound the problem from outside before reading code.** The bare-client + drain test (12 lines of python) proved the relay offered 10x what we + consumed; iostat proved disk idle; per-thread CPU proved one core pinned + while 31 slept. That eliminated relay, disk, hardware, and "need more + workers" in twenty minutes. +2. **Profile with real tools on the real workload.** `apt install + linux-tools-generic`, `perf record -F 397 -g -p -- sleep 20`, + `perf report`. The gauge walk was 81% of the profile with a full call + stack attached — no amount of code reading would have ranked it first. + (An agent's static trace of the pipeline found the decode serialization + and ranked hypotheses; perf then found the thing static reading missed.) +3. **Check what upstream actually does, in its source.** The pinned Atmos + is on disk (`~/go/pkg/mod/github.com/jcalabro/atmos@v0.2.14`). + `decodeFrame` there is one envelope unmarshal; `commit.Blocks` stays raw + until the scheduler workers. Ten minutes of reading settled what the + "matching Atmos" comment had gotten wrong. +4. **Ship through the admission gauntlet every time.** All three deploys ran + the full suite set (lifecycle + powerloss oracles first) and pinned a + registry digest. Cost per iteration: ~35 min admission + ~2.4h rebuild + after restart. The rebuild tax made batching fixes tempting; measuring + one variable per deploy is what made attribution certain. +5. **Measure with monotonic counters over stated windows.** Every rate above + is a 5-10 min window of `stream_upstream_seq` deltas (or a 1h PromQL + rate), never a warm-up burst. The campaign's one false report ("1.65x, + catching up") came from violating exactly this. + +## traps hit on the way + +- **Fixed-tick sampling of a cyclical walk reads as linear progress.** The + compaction fd-walk "went backwards" because chunked passes re-walk; + "52%...99% done" was one sweep, not the pass. +- **A fresh simulator is part of the test contract.** The lifecycle oracle + timed out against a simulator that had been accumulating world state for + 18h. `scripts/admit` documents this; the operator (me) still hit it. +- **Container rebuilds change the container IP.** Probes pinned to + `172.18.0.2` silently read nothing after a recreate; go through + prometheus's PromQL API (`127.0.0.1:9090`) instead. +- **rkeys are not timestamps.** Estimating event-time lag from a frame's + rkey TID works only for `create` ops filtered to the current TID era + (`3m…`); a delete's rkey carries the *original* creation time and one + sample said the cursor had time-traveled 26h backwards. +- **`git+https` zig fetches fail from container builds against tangled.org** + (ProtocolError); commit-sha tarball URLs produce the identical + content-addressed hash and work everywhere. + +## still on the table (known, unexploited) + +- The writer emits one event at a time (`pipeline.zig` writer loop) — the + batch it builds is not used for a batched archive append. +- The reader thread still lax-parses the envelope twice (consumer + `inspectFrame` + submit `peekEnvelope`) and dupes every frame. +- The websocket client read buffer is 4 KiB (zat default); large commit + frames take several syscalls. +- 3,016/s is ~6 cores of 32. If the instance ever needs the storage + ceiling's 70k/s (e.g. re-backfill), those three are the next ladder.