Skip to content

Codex re-pin: get the rollout walk off the event loop - #45

Open
thomwolf wants to merge 2 commits into
mainfrom
perf/slow-fs-probe
Open

Codex re-pin: get the rollout walk off the event loop#45
thomwolf wants to merge 2 commits into
mainfrom
perf/slow-fs-probe

Conversation

@thomwolf

@thomwolf thomwolf commented Aug 7, 2026

Copy link
Copy Markdown
Member

Fixes the multi-second freezes in the Space, and leaves a tripwire so this class
of bug cannot hide again.

The bug

The codex re-pin watcher walks $CODEX_HOME/sessions synchronously — a
readdirSync per day-directory plus a statSync per rollout, then a readSync
of up to a megabyte of the winner — on the REPIN_MS beat, once per codex
session. Node runs JS on one thread, so that is a freeze of every pane the
server is carrying.

CODEX_HOME is on local disk, which is why this looked safe. Its sessions
child is not: it is a symlink onto the FUSE bucket, where a stat costs ~85ms
against 0.01ms locally (98% of stats there exceed 50ms).

It stayed hidden because both the obvious checks lie about it. find on that
path reports the directory empty — it does not follow a symlink given as its
starting point without -L. And the kernel's pressure accounting reads zero:
FUSE parks the caller in wait_event_interruptible (state S, never D), not
io_schedule, so the wait is never counted as iowait and /proc/pressure/io
shows 0.00 while the loop is stuck.

Evidence

Measured on the live Space, on loopback with no network in the path:

  • stalls >250ms at 2.5/minute, worst 3.9s
  • stall-to-stall intervals of 20.455, 40.589, 20.682, 21.142, 40.491, 20.663,
    20.461, 20.686, 20.935s — REPIN_MS, to within sampling error
  • during stalls the process burns less CPU than when healthy (0% on-CPU vs
    10.8%) and read syscalls fall from 1434/s to 18/s — asleep, not busy
  • /proc/1/task/1/wchan puts the main thread in FUSE's
    request_wait_answer 3.67% of wall time (async fs would sit on the libuv
    threadpool instead)
  • a restart does not help: a fresh heap stalled 2.57/min against 2.60/min, so it
    is not a leak

The fix

Make the walk and the head-read async, exactly as claudeTranscriptsSince
already is, and sequential for the same stated reason — parallel FUSE stats
would saturate the 4-thread libuv pool and push every other fs operation in the
process behind them.

Awaiting reintroduces the hazards #35 fixed for the claude watcher, so it takes
the same three remedies:

  • one rearm per tick, from a single place, so a tick that throws neither
    kills the watcher nor arms two timers;
  • a host-identity guard, so a relaunch landing mid-walk cannot leave two
    chains beating with only one reachable by clearTimeout;
  • claims and pins re-read after the awaits rather than snapshotted before
    them, so a rollout claimed while we walked is not stolen from its owner.

The stale-pin check moves off the launch path into the first beat, since it
reads the bucket too.

The tripwire (second commit)

Any sync fs call over AM_SLOWFS_MS (default 50) logs the path and the
caller's own source line
. This bug class has now hit three times —
claudeTranscriptsSince, codexRolloutsSince — and nothing in the stack
reports it, as above. Silent on a normal filesystem; AM_SLOWFS_MS=0 disables
it; rate-limited to one line per call site per 10s; the wrapper never throws
from its own logging and never swallows the call's errors.

Tests

server/test/codex-repin.test.mjs (10): walks the real YYYY/MM/DD layout,
newest-first ordering, sinceMs filtering, ignores non-rollouts, respects the
depth cap, tolerates an absent root, and asserts the function is actually async.
server/test/slowfs.test.mjs (17): behaviour, error propagation and
realpathSync.native unchanged; attribution points at the caller; repeats
collapse to one line.

Full suite passes: repin 30, opencode-resume 16, terminal-modes, trace-tail, and
both boot suites (migration, resize).

Verified on a separate test Space

thomwolf/am-perftest, private, with its own bucket mounted at /data
(never the live one — two Spaces writing the same sessions.json would corrupt
it). stat -f inside confirms fuseblk. Seeded with 10 rollouts across 3
day-dirs, mirroring the live layout. Both implementations run verbatim against
that tree while a 20ms heartbeat records its own drift, which is event-loop
block time.

Order is the whole experiment: the FUSE attribute cache is cold only for
whichever phase runs first, and cold is ~1s against ~2ms warm — so
sync-first/async-second would flatter this PR for free. Run in the hostile
order, handing the cold cache to the new code:

phase in the COLD slot walk I/O wall time event-loop block
sync (shipped) 1091 ms 1071 ms
async (this PR) 819 ms 1 ms

Same mount, same tree, same cold cache. The new version does the full ~819ms of
I/O and blocks the loop for 1ms — 0.1%, against sync's 98%. Warm walks are
1-2ms either way, which is exactly why the live stalls are intermittent: they
are cold-cache events. Control: on tmpfs both versions are identical (1ms), so
the harness does not manufacture a difference.

The fixed build then deployed and ran clean there (/api/health ok, no
[codex] repin tick failed).

Not covered: the fixed build's effect on the live 20s beat end-to-end — the
test Space has no codex sessions and starting real ones needs codex auth. The
walk A/B proves the mechanism; the end-to-end stall rate is unmeasured.

The tripwire paid for itself on the first boot

It named ten more sync-FUSE call sites, with file:line — about 3s of blocked
startup, all boot-path (so not the recurring stall, but the same bug class):

[slowfs] 609ms mkdirSync    /data/home/.agents/skills/environment — at distributeSkill (index.js:1257)
[slowfs] 521ms readFileSync /data/am-config.json                  — at loadAmConfig (index.js:889)
[slowfs] 260ms readFileSync /data/secret-notes.json               — at loadSecretNotes (index.js:881)
[slowfs] 212ms readFileSync /data/demo.json                       — at Module.init (demo.js:16)
[slowfs] 152ms readFileSync /data/state/claude/settings.json      — at installClaudeRepinHook (runner.js:1143)

loadAmConfig logged twice, so it may sit on a warm path too. Follow-up, not
this PR.

🤖 Generated with Claude Code

On the Space, DATA_DIR / HOME / CLAUDE_CONFIG_DIR are on the FUSE bucket, where
a statSync costs ~85ms against 0.01ms on local disk (98% of stats there exceed
50ms). Node runs JS on one thread, so a single such call freezes every pane the
server is carrying for that long.

This has now bitten us three times: claudeTranscriptsSince, and then
codexRolloutsSince, which is still sync and walks $CODEX_HOME/sessions — a
symlink onto the bucket — on the repin beat. It is hard to spot because nothing
in the stack reports it. In particular the kernel's pressure accounting cannot:
FUSE parks the caller in wait_event_interruptible (state S), not io_schedule, so
the wait is never counted as iowait and /proc/pressure/io reads 0.00 while the
loop is stuck. Finding the last one needed a wchan sample of the main thread.

So leave a tripwire. Any sync fs call over AM_SLOWFS_MS (default 50) logs the
path and the caller's own source line, which is the part that turns "something
is slow" into a diff.

Silent on a normal filesystem, where nothing approaches the threshold, and
AM_SLOWFS_MS=0 disables it. Overhead when nothing is slow is two
performance.now() calls against a ~10us syscall; a stack is captured only for a
call that already blocked. Rate-limited to one line per call site per 10s so a
stalled mount cannot become a log storm, and the wrapper neither throws from its
own logging nor swallows the call's errors — it sits in front of every sync fs
call in the process, including ones inside catch blocks.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@thomwolf
thomwolf force-pushed the perf/slow-fs-probe branch from a78bc81 to a8abb3d Compare August 7, 2026 12:39
@thomwolf thomwolf changed the title Name the sync fs call that freezes every terminal Warn when a sync fs call blocks the event loop, and name the caller Aug 7, 2026
The Space freezes for 400-750ms, several times a minute. It is this: the codex
re-pin watcher walks $CODEX_HOME/sessions synchronously — a readdirSync per
day-directory plus a statSync per rollout, then a readSync of up to a megabyte
of the winner — on the REPIN_MS beat, once per codex session.

CODEX_HOME is on local disk, which is why this looked safe. Its `sessions` child
is not: it is a symlink onto the FUSE bucket. `stat -f` reports fuseblk, and a
stat there costs ~85ms against 0.01ms locally. `find` on that path reports it
empty, because find does not follow a symlink given as its starting point
without -L — which is how it stayed hidden.

Measured on the live Space before this change: event-loop stalls over 250ms at
2.5/minute, worst 3.9s, with stall-to-stall intervals of 20.4-20.9s — REPIN_MS,
to within sampling error. During those stalls the process burns LESS cpu than
when healthy (0% on-CPU vs 10.8%) and read syscalls fall from 1434/s to 18/s: it
is asleep in the bucket, not busy. /proc/1/task/1/wchan puts the main thread in
FUSE's request_wait_answer 3.67% of wall time.

So make it async, exactly as claudeTranscriptsSince already is, and sequential
for the same reason — parallel FUSE stats would saturate the 4-thread libuv pool
and push every other fs operation in the process behind them.

Awaiting brings the hazards PR #35 fixed for the claude watcher, so it takes the
same three remedies:
  - one rearm per tick, from a single place, so a tick that throws neither kills
    the watcher nor arms two timers;
  - a host-identity guard, so a relaunch landing mid-walk cannot leave two
    chains beating with only one reachable by clearTimeout;
  - claims and pins re-read after the awaits rather than snapshotted before
    them, so a rollout claimed while we walked is not stolen from its owner.

The stale-pin check moves off the launch path into the first beat, since it too
reads the bucket.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@thomwolf thomwolf changed the title Warn when a sync fs call blocks the event loop, and name the caller Codex re-pin: get the rollout walk off the event loop Aug 7, 2026
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