diff --git a/docs/handoffs/HANDOFF-2026-08-05-zio-canary.md b/docs/handoffs/HANDOFF-2026-08-05-zio-canary.md new file mode 100644 index 0000000..31f8bf6 --- /dev/null +++ b/docs/handoffs/HANDOFF-2026-08-05-zio-canary.md @@ -0,0 +1,162 @@ +# handoff 2026-08-05 — zio canary #2: root cause found, fixed, verified + +The 2026-08-04 canary failure is **root-caused and fixed**. It was a bug in +zio, not in zlay: sub-millisecond sleeps never actually parked, so any fiber +polling on a database request busy-spun the single scheduler thread and +starved everything else on it — including both accept loops. That is the +"serving deaf, ingest fine, process alive" signature you saw. + +The fix is verified against the exact conditions that produced the failure: +**30 of 30 accept probes over 9 minutes at full fleet scale**, where the +same setup previously went deaf in about four minutes. + +This supersedes the canary #2 section of +[HANDOFF-2026-08-04-zio-backend.md](HANDOFF-2026-08-04-zio-backend.md), +which proposed deploying an instrumented-but-unfixed build. Don't use that +plan; use this one. + +## what to deploy + +``` +zlay branch canary/obs-2026-08-04 @ aa7b3a4 +zio branch canary/obs-2026-08-04 @ beb13c8 (pinned by sha in the zon) +``` + +Same build as last time otherwise: `-Dbackend=zio`, +`-Dtarget=x86_64-linux-gnu`, ReleaseSafe, glibc. Rollback is unchanged — +redeploy without `-Dbackend=zio`. Data formats are untouched, so rollback +needs no migration or cleanup. + +## the bug + +zio's fiber scheduler keeps time in **milliseconds**. `Io.Timeout` durations +were converted to that clock with `@divTrunc`, so a sub-millisecond sleep +truncated to **zero**: + +```zig +// deadline = now + 0 +// sleepUntil: while (nowMs() < deadline) -> false immediately +// the sleep returns WITHOUT EVER PARKING +``` + +zlay uses the ordinary "poll until done" shape in three places: + +| file | what waits there | +|---|---| +| `src/internal/event_log.zig:111` | `DbRequest.wait` — **every** database request | +| `src/internal/broadcaster.zig:708` | consumer buffer wait | +| `src/internal/slurper.zig:330` | host check wait | + +each of the form `while (!done) io.sleep(100us)`. + +Under `Io.Threaded` this is harmless: the spinning happens on one of ~2,800 +OS threads and the kernel preempts it. Under zio there is **one** scheduler +thread, and a fiber that never parks owns it. One spinner is enough to +starve every other fiber on that thread: the accept loops on :3000 and :3001 +stop being serviced, io throughput collapses, and the process still looks +healthy — ingest keeps trickling because subscriber fibers are already in +the run cycle. + +It gets worse with fleet size, because more hosts means more database +traffic means more spinners. That is why production (2,763 hosts) failed +where our 1,830-host soaks only showed `/metrics` latency spikes we wrongly +dismissed as noise. + +**Fix:** zio `beb13c8` rounds any non-zero duration **up** to at least 1 ms, +so a sleep actually parks. Also on zio `main` as `d5c0a2e`. + +## the evidence + +Measured on the test box with loop-internal counters printed to stderr +(deliberately not over HTTP — the failure breaks the HTTP path itself): + +| | before fix | after fix | +|---|---:|---:| +| live fibers | 227 | **1,811** | +| polls returning events | 13% | **49%** | +| fibers run per loop iteration | 0.62 | **4.7** | +| accept probes succeeding | 0–1 of 12 | **30 of 30 over 9 min** | +| upstream connections held | ~250 | **1,818** | + +Before the fix the loop did 1,772 polls/sec that returned 238 events/sec — +spinning on nothing. After, the same relay carries 8x the fibers with the +full fleet connected, `/metrics` answering, `relay_seq` advancing, and zero +poller arm failures. + +Regression test in zio: `Zio: a sub-millisecond sleep parks instead of +busy-spinning` — 200 sub-millisecond sleeps must consume at least 150 ms of +wall time. Confirmed to **fail** (completing instantly) when the truncating +conversion is restored, so it genuinely guards the bug. + +## also in this build + +Four other real bugs found and fixed on the way, each independently +justified: + +1. **fibers stranded on closed fds** (zio `71a66ba`) — `netClose` was never + overridden, and the kernel drops closed fds from the epoll set without an + event, so a fiber parked on one waited forever. Leaked one fiber per + connection under churn. Has a regression test that hangs without the fix. +2. **unbounded group-member accumulation** — a long-lived `Io.Group` (the + websocket server spawns one member per connection) held every member's + task until teardown. Now unlinked in O(1) as each finishes. +3. **silently swallowed poller arm failures** — a failed arm turned into a + retry spin; now counted with its errno and surfaced as an error. +4. **per-direction epoll arms** — a second fiber arming an fd used to steal + the first fiber's wakeup. + +Plus observability, which is the other reason to run this canary: + +- `zio_sched_*`, `zio_poller_*`, `zio_dns_*` on `/metrics`, computed only + when scraped and compiled out entirely on the Threaded backend +- `scripts/zlay-forensics.sh` — read-only, ~10 s, run it **in-pod before any + rollback** + +## what to watch + +Usual relay metrics, plus these. Healthy values from the verification run +are in parentheses: + +| metric | what a bad value means | +|---|---| +| `zio_sched_switches_total` (climbing steadily) | flat between scrapes = scheduler loop wedged | +| `zio_sched_fibers{state="parked"}` (~= live) | climbing while `ready`≈0 = fibers stuck on lost wakes | +| `zio_poller_registrations` (~= connection count) | collapsing while conns hold = registration erosion | +| `zio_poller_arm_failures_total` (0) | nonzero = new connections/reconnects cannot be armed | +| `zio_dns_spill{kind="queued"}` (0) | climbing with `idle`=0 = DNS spill pool saturated | + +And the one that cost us the most time: **check `relay_seq` first.** A flat +`relay_seq` with everything else healthy means ingest is dead and consumers +have nothing to receive — which reads exactly like "serving is broken" if +you only probe the serving side. + +## if it goes wrong again + +1. run `scripts/zlay-forensics.sh` in-pod and keep the output +2. grab a metrics dump: `kubectl exec ... -- curl -sm10 localhost:3001/metrics` +3. then roll back — same one-liner as last time + +Step 1 matters. Last time the pod died with its evidence and only the +prometheus timeline survived. + +## caveats, honestly + +- **One diagnostic should come out before this is permanent.** The build + sets `zio_debug_loop_stats = true`, which prints one `[loop] …` line to + stderr every 5 seconds. Useful during a canary, noise in steady state. + Flip it off in `src/main.zig` for a permanent deployment. +- **Verified at ~1,830 hosts, not prod's 2,763.** The mechanism is + understood and scales in the right direction, but that gap is real. +- **Longest single observation is under an hour.** Hours-scale behaviour is + what the canary phase is for. +- **Two zlay changes reach production regardless of the backend flag**, from + the earlier work: the frame-pool sync change (behaviourally identical + under Threaded) and sequential per-address connect (a real change — no + more racing v4/v6 on reconnects, strictly simpler). + +## the memory result, for context + +The reason to do any of this: on identical live load the zio build held +**1.26–1.37 GiB RSS against the Threaded build's flat 2.27 GiB** — about 45% +lower — with ~90 OS threads instead of ~2,800. That number came from your +own canary on 2026-08-04 and still stands.