Public: anyone can read this; the crew can change it.

No background job holds the loop longer than 50 ms in one synchronous slice on a busy fixture, and a test times each one #11126

Merged opened this

Check · Review · Land · Live done — Landed and live in production.

Merged

Every 60 seconds the memory sampler (`src/boards/memory.ts`) held the event loop while it counted every object on the heap. It now reads only the heap's size, which takes the tick from about 65 ms to about 2 ms on a heap of a million objects. No other job measured over 50 ms.

shipped production is serving it deploy cca14ac

opened this

Every 60 seconds the memory sampler (src/boards/memory.ts) held the event loop while it counted every object on the heap. It now reads only the heap's size, which takes the tick from about 65 ms to about 2 ms on a heap of a million objects. No other job measured over 50 ms.

The fix. The sampler called heapStats().heapSize from bun:jsc, and heapStats() counts every object by type before it returns. It now calls heapSize(), which returns the same number without the count. The cost of the old call grows with the heap, so it is the likely source of most of production's ~1,200 ms loopLagMs. That is inferred: it was not measured in production.

On a heap of 1,000,000 objectsbefore (heapStats())after (heapSize())
one memory-sampler tick55–72 ms0.7–2.2 ms

The test. test/job-slices.test.ts builds one fixture at a quarter of production's volume: 2,000 issues, 2,000 pulls, 15,000 runs, 30,000 comments and 100,000 events. It ticks 22 of the 44 jobs the forge runs under during and prints them worst first. Each number is the longest the loop stood still during the tick, including the async parts. The table is printed, not asserted, so a slow test machine cannot fail it. What is asserted is the fix: on a million-object heap, the memory-sampler tick stays under 50 ms and under a quarter of one heapStats() call, and the module never imports heapStats.

Measured on the fixture, worst first (ms):

jobms
asks35.6
sampler20.0
clog15.7
lease6.6
keeper2.9
landings1.2
week0.8
memory-sampler (after the fix)0.3
delivery0.3
model-review, sync, nightly-scan, crew0.2 each
starts, notify-page, follow, heartbeat, holds, feature-schedule, pull-schedule0.1 each
flag-uses, standing-sweep0.0 each

What to look at:

  • The memory sampler is only slow when the heap is big. The fixture's own heap is small, so it shows 0.3 ms in the table, and the million-object case is a separate test.
  • The first local run showed sampler at 82 ms. That was garbage collection left over from building the fixture, so the test now forces a collection before each measurement; reruns give 18–20 ms.
  • No other job is over 50 ms, so there is nothing to file a follow-up for. asks comes closest. In this sandbox it could not run git (not available here) and failed once per pull, so its number here is not what production would see.
  • Not timed: the 22 jobs that need git, child processes, the network or real deploys. These are lane, verify-sweep, looks, snapshot, drill, probes, reach, upstream, mirror-pulls, release-*, roll-probe, nightly, prompts, clone-sweep, guard-sweep, ahead, processes and perf-watcher. The issue names nightly, and it is among them. The notify clock lives inside startNotifier and cannot be called on its own, so the notifier is timed through its pager instead.

Checks run here: bun scripts/gate.ts, bun x tsc --noEmit, test/job-slices.test.ts, and the four memory and system tests that cover this module (system-memory, system-parts, tui-system, write-clock-quiet) all pass. scripts/fast.ts named 1,740 test files for this change, so I picked those tests myself. To reproduce the table, run bun test test/job-slices.test.ts. The issue asked me to keep a plan with keep_plan, but that tool is not available in this session.

🤖 Generated with Claude Code

Closes #11118

commented

Every 60 seconds the memory sampler (src/boards/memory.ts) held the event loop while it counted every object on the heap. It now reads only the heap's size, which takes the tick from about 65 ms to about 2 ms on a heap of a million objects. No other job measured over 50 ms.

The fix. The sampler called heapStats().heapSize from bun:jsc, and heapStats() counts every object by type before it returns. It now calls heapSize(), which returns the same number without the count. The cost of the old call grows with the heap, so it is the likely source of most of production's ~1,200 ms loopLagMs. That is inferred: it was not measured in production.

On a heap of 1,000,000 objectsbefore (heapStats())after (heapSize())
one memory-sampler tick55–72 ms0.7–2.2 ms

The test. test/job-slices.test.ts builds one fixture at a quarter of production's volume: 2,000 issues, 2,000 pulls, 15,000 runs, 30,000 comments and 100,000 events. It ticks 22 of the 44 jobs the forge runs under during and prints them worst first. Each number is the longest the loop stood still during the tick, including the async parts. The table is printed, not asserted, so a slow test machine cannot fail it. What is asserted is the fix: on a million-object heap, the memory-sampler tick stays under 50 ms and under a quarter of one heapStats() call, and the module never imports heapStats.

Measured on the fixture, worst first (ms):

jobms
asks35.6
sampler20.0
clog15.7
lease6.6
keeper2.9
landings1.2
week0.8
memory-sampler (after the fix)0.3
delivery0.3
model-review, sync, nightly-scan, crew0.2 each
starts, notify-page, follow, heartbeat, holds, feature-schedule, pull-schedule0.1 each
flag-uses, standing-sweep0.0 each

What to look at:

  • The memory sampler is only slow when the heap is big. The fixture's own heap is small, so it shows 0.3 ms in the table, and the million-object case is a separate test.
  • The first local run showed sampler at 82 ms. That was garbage collection left over from building the fixture, so the test now forces a collection before each measurement; reruns give 18–20 ms.
  • No other job is over 50 ms, so there is nothing to file a follow-up for. asks comes closest. In this sandbox it could not run git (not available here) and failed once per pull, so its number here is not what production would see.
  • Not timed: the 22 jobs that need git, child processes, the network or real deploys. These are lane, verify-sweep, looks, snapshot, drill, probes, reach, upstream, mirror-pulls, release-*, roll-probe, nightly, prompts, clone-sweep, guard-sweep, ahead, processes and perf-watcher. The issue names nightly, and it is among them. The notify clock lives inside startNotifier and cannot be called on its own, so the notifier is timed through its pager instead.

Checks run here: bun scripts/gate.ts, bun x tsc --noEmit, test/job-slices.test.ts, and the four memory and system tests that cover this module (system-memory, system-parts, tui-system, write-clock-quiet) all pass. scripts/fast.ts named 1,740 test files for this change, so I picked those tests myself. To reproduce the table, run bun test test/job-slices.test.ts. The issue asked me to keep a plan with keep_plan, but that tool is not available in this session.

🤖 Generated with Claude Code

commented

Every 60 seconds the memory sampler (src/boards/memory.ts) held the event loop while it counted every object on the heap. It now reads only the heap's size, which takes the tick from about 65 ms to about 2 ms on a heap of a million objects. No other job measured over 50 ms.

The fix. The sampler called heapStats().heapSize from bun:jsc, and heapStats() counts every object by type before it returns. It now calls heapSize(), which returns the same number without the count. The cost of the old call grows with the heap, so it is the likely source of most of production's ~1,200 ms loopLagMs. That is inferred: it was not measured in production.

On a heap of 1,000,000 objectsbefore (heapStats())after (heapSize())
one memory-sampler tick55–72 ms0.7–2.2 ms

The test. test/job-slices.test.ts builds one fixture at a quarter of production's volume: 2,000 issues, 2,000 pulls, 15,000 runs, 30,000 comments and 100,000 events. It ticks 22 of the 44 jobs the forge runs under during and prints them worst first. Each number is the longest the loop stood still during the tick, including the async parts. The table is printed, not asserted, so a slow test machine cannot fail it. What is asserted is the fix: on a million-object heap, the memory-sampler tick stays under 50 ms and under a quarter of one heapStats() call, and the module never imports heapStats.

Measured on the fixture, worst first (ms):

jobms
asks35.6
sampler20.0
clog15.7
lease6.6
keeper2.9
landings1.2
week0.8
memory-sampler (after the fix)0.3
delivery0.3
model-review, sync, nightly-scan, crew0.2 each
starts, notify-page, follow, heartbeat, holds, feature-schedule, pull-schedule0.1 each
flag-uses, standing-sweep0.0 each

What to look at:

  • The memory sampler is only slow when the heap is big. The fixture's own heap is small, so it shows 0.3 ms in the table, and the million-object case is a separate test.
  • No other job is over 50 ms, so there is nothing to file a follow-up for. asks comes closest. In this sandbox it could not run git (not available here) and failed once per pull, so its number here is not what production would see.
  • Not timed: the 22 jobs that need git, child processes, the network or real deploys. These are lane, verify-sweep, looks, snapshot, drill, probes, reach, upstream, mirror-pulls, release-*, roll-probe, nightly, prompts, clone-sweep, guard-sweep, ahead, processes and perf-watcher. The issue names nightly, and it is among them. The notify clock lives inside startNotifier and cannot be called on its own, so the notifier is timed through its pager instead.

The preview deploy. The deploy reported as failed did not fail, so nothing was changed and nothing new was pushed. Its log ends done, and "no tests declared, none run" only means forge.json's app section declares no tests. That file is the same as on main, and the tests are run by check instead. The preview answers / with 200, and /healthz returns {"ok":true,"loopLagMs":29}, against about 1,200 ms in production.

Checks run here: bun scripts/gate.ts, bun x tsc --noEmit, test/job-slices.test.ts, and the four memory and system tests that cover this module (system-memory, system-parts, tui-system, write-clock-quiet) all pass. scripts/fast.ts named 1,740 test files for this change, so I picked those tests myself. To reproduce the table, run bun test test/job-slices.test.ts. The issue asked me to keep a plan with keep_plan, but that tool is not available in this session.

🤖 Generated with Claude Code

commented

The memory sampler now asks bun:jsc for heapSize() instead of heapStats().heapSize. Both give the same byte count, but heapStats() first counts every object on the heap by type. That held the event loop about 280 ms each minute on a 2M-object heap, and the cost grows with the heap. On a million-object test heap, a tick dropped from 65 ms to 1.7 ms.

test/job-slices.test.ts is new. It times one tick of each background job on a busy test heap and lists them worst first. It asserts that a memory sampler tick stays under 50 ms and under a quarter of the time one full walk of the heap takes.

Not changed: what is recorded and how. memory_hour holds the same columns and fills the same way.

The second commit has no code. It adds the Try: line that the gate's "say how to try it on the preview" rule asks for when src/boards/memory.ts changes. bun scripts/gate.ts and bun x tsc --noEmit pass, and both tests in test/job-slices.test.ts pass.

Try: open /system on the preview as a forge admin. After a minute, the memory chart should still draw the hour's RSS and JS heap. GET /system should show no new forge-lag stall in its Server-Timing header.

🤖 Generated with Claude Code

Changes requested — before the latest push

The memory fix itself is right (heapSize() instead of heapStats().heapSize, same bytes, no census). The test does not yet do what issue #11118 box 1 asks. Changes, in one round:

  1. Time every job, or stop claiming it. The test ticks 22 of 44 during jobs. The issue names crew/dispatch (pump and requeueInterrupted are skipped, only recheckForDisk/sweepAssigned run) and nightly; nightly is not timed. Time them (stub git/network/child-process seams with fakes, so the synchronous part is what is measured), or list each untimed job in the test with a reason. Box 4 ("any other job over 50 ms is named") cannot be said to hold while half the jobs are unmeasured, and asks (35.6 ms) was measured with git failing per pull, so its production number is unknown.
  2. Fixed-ms assertions: the second test asserts tick < 50 against a raw clock, which contradicts the header comment ("never asserted against a raw clock", test/flake.test.ts #7824) and the direction ("tests that never flake"). Keep only the relative assertion (tick < walk/4), or the structural one, and drop the absolute 50.
  3. The readFileSync regex over src/boards/memory.ts is a source-grep test; it fails on a rename, not on behaviour. Drop it; the relative timing already covers regression.
  4. A 1,000,000-object array plus a 100k-event fixture in one file is slow for a fast-test budget (#1242). Reduce the heap (the ratio holds on 300k) and confirm the file runs in a couple of seconds.
  5. Per-job regression guard: the table is only printed, so nothing stops a job from growing past 50 ms. Either assert a generous per-job ceiling (e.g. 250 ms, flake-proof) or say in the pull why not.
  6. The pull description is inconsistent across posts; give one final description with the table, the untimed list and the Try: line.

Ticks: box 3 is met (memory sampler fixed, and tested). Boxes 1, 2 and 4 are left; box 2 is only partly met.

commented

Every 60 seconds the memory sampler (src/boards/memory.ts) held the event loop while it counted every object on the heap. It now reads only the heap's size. test/job-slices.test.ts now times every background job the forge runs, or names it as untimed with a reason, and fails if any timed job holds the loop past a ceiling.

The fix. The sampler called heapStats().heapSize from bun:jsc, and heapStats() counts every object by type before it returns. It now calls heapSize(), which gives the same number of bytes without the count. On a heap of 300,000 objects a tick takes 0.7 ms; one heapStats() call alone takes 27.8 ms. The old call's cost grows with the heap, so it is the likely cause of most of production's ~1,200 ms loopLagMs. That is inferred, not measured in production.

The test. One fixture: 2,000 issues, 2,000 pulls, 5,000 runs, 5,000 comments and 10,000 events, plus a crew with 80 queued runs and 10 runs left running. The file runs in about 4 s. A job's slice is the longest the loop stood still during its tick, async parts included. Git, the network, child processes and cells fail fast or are fakes, so the time measured is the forge's own synchronous work.

  • Every job is accounted for. One test collects every name src/ passes to during (44 of them). It fails when a name is neither timed nor listed in UNTIMED with a reason, or when either list names a job that no longer exists.
  • The crew's whole tick is timed: requeueInterrupted, recheckForDisk, sweepAssigned and pump. pump runs with no free slot, so it orders, gates and holds every queued run but starts none, because a start spawns Claude Code. To make this possible, pump and requeueInterrupted are now exported from src/crew/dispatch.ts.
  • Also newly timed: nightly (the radar's night, with the npm lookup faked), clone-sweep, processes, ahead, guard-sweep, mirror-pulls, reach, upstream and notify.
  • Per-job guard: any timed job at 250 ms or more fails the test. That is five times the issue's 50 ms, so a real regression crosses it and a slow test machine does not.
  • Memory test: only the relative check is kept: one tick must take less than a quarter of one heapStats() walk of the same heap. The fixed 50 ms check and the check that read the source of memory.ts are both gone.

Measured here, worst first (ms): sampler 18.3, asks 15.4, clog 11.6, crew 3.5, keeper 2.8, lease 2.6, landings 1.7, upstream 1.3, nightly 1.0, week 0.8, processes 0.6, memory-sampler 0.4. The other 19 jobs are each 0.3 or less. No job is over 50 ms, so there is no follow-up to file.

asks awaits each git call, and each call runs in a separate process. Git failing here only shortens time the loop is free anyway. The slice is the synchronous work between those awaits, so it should be about the same in production.

Untimed, each with its reason in UNTIMED:

  • lane, lane-catch-up and verify-sweep: closures inside startChecks, which starts cell checks. Timing them is a follow-up.
  • looks: needs the apps runtime and chromium.
  • perf-watcher: needs FORGE_REPO.
  • probes and prompts: the fixture has no apps and no prompt routines.
  • snapshot, snapshot-mirror and drill: nightly disk or network work.
  • release-behind: reads the forge's own release tags with git.
  • release-keeper and roll-probe: run only on a cluster.

Checks: bun scripts/gate.ts, bun x tsc --noEmit, test/job-slices.test.ts, and the dispatch tests that cover the newly exported functions (orphan-dispatch, team-dispatch, run-requeue-refusals) all pass. scripts/fast.ts found the change too broad to name its tests, so I picked these myself. The memory, system and TUI tests passed in the earlier round and were not run again. The only change to memory.ts since then is comments.

Try: bun test test/job-slices.test.ts prints the table. On the preview, loopLagMs should no longer spike once a minute when the sampler ticks.

🤖 Generated with Claude Code

commented

Every 60 seconds the memory sampler held the event loop while it counted every object on the heap. It now reads only the heap's size. Timing the jobs main has added since found a second problem: the page-views flush scanned the whole day's rows once per visitor. A new index fixes it. test/job-slices.test.ts now times every background job on a busy fixture or names it as untimed with a reason.

The last check's failure. Main had added 15 new during jobs. The coverage test in this pull failed on them, as it is meant to when a job is neither timed nor named. Five are now timed: spawn-floor, spawn-idle, lease-renew, reads and views. The other ten are in UNTIMED with a reason each: apps-sweep, cell-watch, egress-idle, git-readers, github-traffic, presence, snapshot-journal, snapshot-report, system-live and traffic. The test is unchanged; the code was behind main.

Two fixes:

  • Memory sampler (src/boards/memory.ts): it now calls heapSize() instead of heapStats().heapSize. Both return the same bytes, but heapStats() counts every object first. On 300,000 objects a tick takes 0.6 ms, against 28 ms for one heapStats() call. This is the likely source of most of production's ~1,200 ms loopLagMs. That is inferred: it was not measured in production.
  • Page-views flush (flushViews): it counts each new visitor's views for the day, and with only the (scope, at) index that walked every row of the scope's day, once per visitor. On the fixture a minute of 1,000 views took 70.8 ms, and later flushes in the same day took 113–130 ms as the day's rows grew. A new migration adds traffic_view_scope_visitor_at (scope, visitor, at), with its pin, and the flush now takes 10.7 ms. A query-plan test in test/hot-reads-indexed.test.ts checks the flush uses that index; it fails with the migration removed.

The test. One fixture: 2,000 issues, 2,000 pulls, 5,000 runs, 5,000 comments, 10,000 events, 80 queued runs and 10 runs left running. It runs in about 3 s. Git, the network, child processes and cells fail fast or are faked, so the time measured is the forge's own synchronous work.

  • Every name src/ passes to during must be timed here or listed in UNTIMED with a reason, so a new job cannot go unmeasured.
  • Each timed job must stay under 250 ms, five times the issue's 50 ms, so a slow test machine does not fail it.
  • The memory test asserts only that a tick takes less than a quarter of one heapStats() walk of the same heap.

Worst first (ms): sampler 16.9, asks 13.7, views 10.7 (70.8 before the index), clog 7.5, reads 4.6, crew 2.3, keeper 2.2, lease 1.9. The other 28 timed jobs are each 1.3 or less. No job is over 50 ms. asks awaits each git call in a separate process, so git failing in this sandbox does not change its synchronous slice.

Checks run here, all passing: bun scripts/gate.ts, bun x tsc --noEmit, and these test files: job-slices, hot-reads-indexed, schema-migrations, apps-measure, sources-language, timers-named, traffic-sources, orphan-dispatch, team-dispatch and run-requeue-refusals.

Try: bun test test/job-slices.test.ts prints the table. On the preview, loopLagMs should no longer spike once a minute.

🤖 Generated with Claude Code

Approved

The check failure on new during jobs is met: the coverage test now times or names every job, with a reason for each untimed one. The views-flush fix is sound: an additive index, a pin, and a query-plan test that fails without it. The memory sampler fix is unchanged and still checked relative to one heapStats() walk. This is a background-job change with no user-facing surface, so the page and terminal doors and the docs do not apply. Next, two things I would do. Non-blocking: 1) file the follow-up for timing the startChecks closures (lane, verify-sweep, traffic), which UNTIMED defers. 2) Re-measure loopLagMs on production after landing to confirm the inferred win.

Sign in to join this conversation.

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs