diff --git a/docs/zlay-gcloop-stall-2026-04-09.md b/docs/zlay-gcloop-stall-2026-04-09.md new file mode 100644 index 0000000..0a7c0f7 --- /dev/null +++ b/docs/zlay-gcloop-stall-2026-04-09.md @@ -0,0 +1,108 @@ +# zlay gcLoop stall — 2026-04-09 + +## tl;dr + +zlay pods were flapping on a ~10 minute cadence: ~10 min healthy, then /metrics +and /_readyz stop responding, kubelet marks NotReady, pod eventually restarts, +cycle repeats. Initial hypothesis was broadcaster writeLoop starvation +(see [zlay-broadcaster-starvation-2026-04-09.md] — now superseded as primary +cause). The actual cadence lines up precisely with `gcLoop` (main.zig), which +became functional again on 2026-04-06 via commit 3dc21b9 ("fix gcLoop: silently +exited after one tick"). Prior to that fix, gc was silently dead after one tick +per pod, masking the underlying problem. + +## causal chain (suspected) + +1. `gcLoop` fires every 10 minutes (main.zig). +2. `dp.gc()` holds `DiskPersist.mutex` for its entire duration + (event_log.zig:977-1033). That critical section includes: + - `SELECT` of expired log_file_refs + - per-file `DELETE FROM log_file_refs` + `unlink` + - `gcBySize()` — another pass of queries + `stat` + `unlink` +3. `DiskPersist.persist()` (event_log.zig:864-899) takes the same mutex on the + frame-worker hot path. For the duration of gc, every frame worker blocks on + persist → the broadcast queue dries up → consumers see ~0 events/sec. This + alone explains the "zlay only delivers 0.035 events/sec" symptom that was + previously blamed on writeLoop polling. +4. After `dp.gc()` returns, `gcLoop` called `malloc_trim(0)`. The pod runs with + `MALLOC_ARENA_MAX=4`, so glibc holds per-arena locks while walking free + lists. On a ~1.5 GiB RSS process this can stall every allocator user for + seconds. The Evented fiber serving /metrics and /_readyz would stall on its + next malloc → kubelet liveness/readiness probes time out → pod marked + NotReady → restart. + +Two separable suspects (important for isolation): +- **`dp.gc()` mutex hold** freezes ingest via the persist hot path. +- **`malloc_trim(0)`** freezes everything via arena locks. + +Either alone is sufficient to flunk probes. Don't conflate them when +investigating. + +## stabilization shipped + +Commit on top of 795cc41: + +- **Disabled `malloc_trim(0)`** in `gcLoop` (main.zig:502). Comment preserved + so future maintainers know why. If RSS growth becomes an issue, prefer + tuning `MALLOC_MMAP_THRESHOLD_` or running trim out-of-band. +- **Bumped gc interval from 10 min → 1 hour** (main.zig:473). Reduces + frequency and blast radius of the persist-mutex hold while the real fix + (mutex narrowing) is prepared. Not a cure — a stall at hour boundaries is + still possible if gc runs long. +- **Added timing log** around `dp.gc()` using `clock_gettime(.MONOTONIC)` + (plain thread — no Io available). Next incident will tell us how long + `dp.gc()` actually runs on a production dataset. + +These changes are in main.zig only. No dependency or schema changes. Safe to +revert by undoing the single commit. + +## validation plan post-deploy + +After deploying on top of 795cc41: + +1. Pod uptime should exceed 10 minutes with no NotReady flap. +2. Grep logs for `gc: dp.gc complete in` — verify gc runs and record its + duration on production data. +3. `frames_broadcast_total` should climb at ingest rate (~300/sec), not + the previously measured ~0.035/sec. +4. `tap run --relay-url https://zlay.waow.tech` for 60 seconds should + deliver thousands of events, not single digits. + +If the pod still flaps after this change, the hypothesis is wrong or +incomplete — do **not** proceed to the follow-up fixes until we re-diagnose. +Most likely remaining suspect in that case is the `dp.gc()` mutex hold on +a dataset big enough that even hourly gc takes long enough to trip probes. +Mitigation in that case: temporarily comment out the `dp.gc()` call body to +isolate. + +## follow-up work (not in this change) + +1. **Narrow `DiskPersist.mutex` scope in `gc()`**. The mutex protects + `evtbuf`/`outbuf`/`cur_seq`/`current_file_path`/`flushLocked`. Nothing in + gc's DB iteration or per-file unlink genuinely needs that lock. The only + shared state is a read of `current_file_path` to skip the active file. + Plan: do DB discovery and file discovery without the lock; acquire briefly + only to re-check `current_file_path` against each candidate before unlink. + Same treatment for `gcBySize()` and `takeDownUser()`. +2. **Broadcaster writeLoop polling** (broadcaster.zig:447-453). Real bug — + `cond.signal` at line 413 is a no-op because writeLoop polls with + `io.sleep(100ms)` instead of `cond.wait`. This caps per-consumer drain at + ~10/sec even under zero contention. Fix: use `cond.wait`, schedule pings + via a separate timer fiber or piggyback on next wakeup. + **Do NOT** move writeLoop off Evented to pool_io — commit 6674812 documents + that cross-Io path crashes via `Thread.current()` NULL deref. +3. **Consider whether `malloc_trim` should ever run on-process**. For a + steady-state relay, the answer is probably no; mmap threshold tuning is a + better choice. + +## code pointers + +- main.zig:467-510 — `gcLoop` +- event_log.zig:977-1033 — `DiskPersist.gc` +- event_log.zig:1036-1099 — `DiskPersist.gcBySize` +- event_log.zig:864-899 — `DiskPersist.persist` (hot path, same mutex) +- broadcaster.zig:439-477 — `Consumer.writeLoop` (secondary bug, not fixed here) +- commit 3dc21b9 — "fix gcLoop: silently exited after one tick" (the fix that + unmasked this) +- commit 6674812 — "fix SIGSEGV: plain threads calling Evented Io.Mutex" + (cross-Io landmine, read before touching Consumer) diff --git a/src/main.zig b/src/main.zig index ffb9696..52f509f 100644 --- a/src/main.zig +++ b/src/main.zig @@ -465,7 +465,12 @@ fn runWsServer(server: *websocket.Server(broadcaster.Handler), listener: *Io.net } fn gcLoop(dp: *event_log_mod.DiskPersist) void { - const gc_interval_s: u64 = 10 * 60; // 10 minutes + // gc cadence: 1 hour (was 10 min before 2026-04-09 incident). DiskPersist.gc() + // currently holds DiskPersist.mutex for its entire duration — covering DB + // iteration and per-file unlinks — which blocks persist() on every frame + // worker. until the mutex scope is narrowed (follow-up), run hourly to + // bound blast radius. see docs/zlay-gcloop-stall-2026-04-09.md. + const gc_interval_s: u64 = 60 * 60; // 1 hour while (!shutdown_flag.load(.acquire)) { // sleep in 1s ticks so shutdown is checked frequently. uses // std.c.nanosleep directly — this is a plain OS thread, so calling @@ -480,15 +485,27 @@ fn gcLoop(dp: *event_log_mod.DiskPersist) void { } if (shutdown_flag.load(.acquire)) return; + // time the gc call so the next incident log tells us whether gc itself + // or something around it is the stall. plain-thread context — use + // clock_gettime directly rather than Io.Timestamp. + var ts_start: std.c.timespec = undefined; + _ = std.c.clock_gettime(.MONOTONIC, &ts_start); dp.gc() catch |err| { log.warn("event log GC failed: {s}", .{@errorName(err)}); }; - - // return freed pages to OS (glibc-specific, no-op on other platforms) - if (comptime malloc_trim) |trim| { - _ = trim(0); - log.info("gc: malloc_trim complete", .{}); - } + var ts_end: std.c.timespec = undefined; + _ = std.c.clock_gettime(.MONOTONIC, &ts_end); + const elapsed_ns: i64 = (@as(i64, ts_end.sec) - @as(i64, ts_start.sec)) * std.time.ns_per_s + + (@as(i64, ts_end.nsec) - @as(i64, ts_start.nsec)); + log.info("gc: dp.gc complete in {d}ms", .{@divTrunc(elapsed_ns, std.time.ns_per_ms)}); + + // NOTE: malloc_trim(0) disabled 2026-04-09. with MALLOC_ARENA_MAX=4 it + // walks free lists holding per-arena locks, which on a ~1.5 GiB RSS + // process can stall every allocator user (including the Evented http + // fiber serving /metrics and /_readyz) long enough to flunk liveness + // probes. if memory reclamation becomes an issue, prefer tuning + // MALLOC_MMAP_THRESHOLD_ or calling trim from a dedicated maintenance + // window rather than on a hot process. } }