#1131 · Synchronous SQLite on the event loop: one cold query froze all clients for 11s on a 1.7GB bb.db
TL;DR
Plain-language framing. bb's server keeps everything in one SQLite file (bb.db) and reads it with better-sqlite3, which is synchronous: while a query runs, the single Node event loop that serves every HTTP request, every WebSocket and every host-daemon message does nothing else. So a slow read for one client is a freeze for all clients. The issue has two halves: (1) an 11.2 s freeze on a cold bb thread list, and (2) a later comment (0.37.0) reporting a 3.4 s freeze when opening the latest page of a 44k-event thread. Both are the same structural fact (sync reads on the loop) plus a specific query that reads far more of the file than the response needs.
Half 1 is already fixed. The 11.2 s thread-list stall was traced in #1204 (merged 2026-08-08, shipped in 0.36) to listLatestGoalEventRowsByThreadIds walking every event row of every listed thread; a partial index and an INDEXED BY pin cut cold reads from 444,010 to 357. On the base commit, the first GET /api/v1/threads after a cold server start (page cache evicted before the start) over 3,287 visible threads in a 1.57 GB seeded database takes 52 ms and adds 16 KB of disk reads on top of the 4.4 MB the server start itself faulted in. The reporter confirmed this on 0.36.1-nightly.
Half 2 is real on the base commit and I reproduced its mechanism. I built a 1.57 GB bb.db (704k events, 1.03 GiB event JSON, one 44k-event / 70 MB thread) with the repo's own perf-fixture seeder, restarted the server, evicted the OS page cache and requested the thread's latest timeline page. The build ran 276–460 ms on the loop across five runs (event-query stage 213–384 ms) and a concurrent GET /health probe stalled for 231–332 ms, i.e. the whole build. The server read 77–100 MB from disk (918 major page faults in the standalone profiler) to return a 1.7 MiB page of 1,599 rows. Per-statement attribution shows the bytes come from two helpers the latest page always runs and that are not bounded by the page window: listTodoSnapshotEventRowsForThread (fetches the payload of every tool-call event in the thread to evaluate json_extract($.item.tool); 73 MB) and listStoredEventRowsByParentToolCallIds called with sequenceBounds: null (walks every event of the thread through events_thread_sequence_idx evaluating json_extract($.parentToolCallId); 20 MB cold, and 64 ms of pure CPU even warm). Their cost scales with the size of the whole thread, not the page — exactly the shape the reporter measured (1,212 rows / 1.74 MiB returned, 3.4 s in the event query). On my local NVMe with 16 cores the absolute time is ~10x smaller than the reporter's Hetzner VM; the read volume and fault count are the transferable numbers.
Retention claims. The 32 KB truncation threshold is verified (COMPLETED_EVENT_OUTPUT_TRUNCATION_THRESHOLD_CHARS = 32 * 1024) and on my production-shaped seed 0 of 56,166 command outputs exceed it while 91% exceed 4 KB, so "the sweep reclaims ~0" is credible. The "250/hour" batch claim is refuted: the sweep runs every 10 s (job cadenceMs: 0, setInterval(…, 10_000)) and scans 250 candidate rows per output path per tick (up to ~90k rows/hour/path); it advanced through 6 weeks of my fixture in 15 minutes. It is a scan batch, not a truncation quota, so batch size is not what limits reclamation — the threshold is.
Also observed (not in the issue). On this database shape the periodic sweeps that start 10 s after server start are synchronous multi-second writes on the same loop: the destroyed-environment prune deleted 1,543 stale environments in one statement whose ON DELETE SET NULL rewrote ~297k events rows (5.0 s here at load ~2, 26.8 s on the verifier's run at load ~68), and each output-truncation tick reads 250 scattered rows per output path (0.1 s per tick here, 0.1–4.7 s on the loaded run). If you run the repro right after the first start you will see those stalls in the /health probe too; the script now waits for them to settle and prints the sweep log lines so any stall can be attributed.
Claims vs findings
| Claim | Status | Evidence |
|---|---|---|
Cold bb thread list --json stalled the loop 11.2 s (0.35.1, 1.7 GB db) | Verified historically, fixed | #1204 rebuilt a 1.45 GB db and measured 10.5 s cold in listLatestGoalEventRowsByThreadIds; fixed by events_goal_thread_sequence_idx + INDEXED BY (migration 0088). Base commit: first GET /api/v1/threads after a cold server start (cache evicted before start), 3,287 threads → 52 ms, +16 KB read (out; the earlier kill-9-and-evict measurement out is effectively warm, see Control). Reporter confirmed on 0.36.1-nightly. |
While stalled, static / TTFB went 2 ms → 7.3 s: one sync query freezes every route | Verified (mechanism) | buildThreadTimeline runs inside runEventLoopWorkSync (timeline.ts#L1809-L1821); during 276–320 ms cold builds my /health probe (100 ms cadence) measured 231–293 ms TTFB. In the packaged app the same server serves index.html (server.ts#L623-L623). |
| better-sqlite3 is synchronous on the serving loop; stall scales with cache misses | Verified | All reads use better-sqlite3 via Drizzle on the main thread; no worker (#1198 was closed). Cold vs warm for the same page: 354 ms / 99.9 MB read vs 171 ms / 0 bytes (cold, warm). Connection uses mmap_size = 1 GiB, so cold pages are major faults with kernel readahead (~108 KB per fault observed). |
| Stalls up to 22 s under memory pressure / leak to 4.2 G | Unverifiable | No data; not investigated. |
events = 1,447 MB of 1.7 GB; item/completed = 913 MB, 815 MB of it commandExecution.aggregatedOutput | Their data; plausible | My seed at the same scale: 1.57 GB file, 1.03 GiB event JSON, 831 MB in commandExecution item/completed rows. |
| Truncation threshold 32 KB; real payload median 5–10 KB, so the sweep reclaims ~0 | Threshold verified; effect plausible | sweeps.ts#L22-L27. Seed: 0 of 56,166 outputs > 32 KB, 51,453 (91%) > 4 KB, 0 rows truncated after 15 min of sweeps although the cursor advanced through ~6 weeks of rows. |
| Batch 250/hour is below the generation rate; a threshold fix could never work down a backlog | Refuted | Job completed-event-output-truncation has cadenceMs: 0 (periodic-sweeps.ts#L528-L533) and the sweep interval is 10 s (start-server.ts#L254-L257); 250 is a per-tick, per-output-path scan limit (sweeps.ts#L160-L180) → up to 90k rows/hour/path. Same at 0.35.1 (checked desktop-v0.35.1). |
automation_runs retention is unbounded | Verified | Only DELETE FROM automation_runs WHERE automation_id = ? on automation delete (data.ts#L495-L498); no age/size prune. |
| 0.37.0: latest timeline page, 44,246 events / 131.7 MiB thread: total 3,578 ms, event-query 3,462 ms for 1,212 rows / 1.74 MiB | Verified (mechanism, smaller magnitude) | Base commit, 44k-event / 70 MB thread, cold: build 276–459 ms, event-query 213–384 ms, 1,599 rows / 1.69 MiB, 77–100 MB disk reads, 918 major faults; two whole-thread scans account for the bytes (below). #1716 (merged Aug 17, in base, not in 0.37.0/0.38.0) fixed two other timeline queries but not these. |
| Suggestion: worker thread / async driver for heavy reads | Design opinion | Would bound blast radius but not cost; the two scans below are fixable at the query level first (see Proposed fix). #1207 tracks the worker option. |
Environment
- bb
16ceb3a54(main, 2026-08-18) in worktree/home/sawyer/projects/bb/.claude/worktrees/wf_242c3e11-a10-26; dev instance app:13609, server:21609, host daemon:29609, data dir/home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_242c3e11-a10-26-5256c67149d9. Revision run (same commit) in worktree/home/sawyer/projects/bb/.claude/worktrees/wf_570fde41-63f-8: app:11384, server:19384, host daemon:27384, data dir/home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_570fde41-63f-8-cd8a2b804171; the seed is deterministic (same 704,206 events, same giant thread idthr_v67duphyr7, same 1,571,041,280-byte file). - Linux 7.0.0-29-generic, 16 cores, 57 GB RAM, local NVMe (CT1000E100SSD8); node v24.18.0; better-sqlite3 12.10.0 (SQLite 3.53.1); sqlite3 CLI 3.46.1. The reporter runs a Hetzner 4 vCPU / 8 GB VM — cold I/O there is much slower than here, so compare read bytes / fault counts, not milliseconds.
- Database: seeded with the repo's
pnpm seed:perfplus two env knobs I added to the fixture (diff): 4,000 threads, 704,206 events, 1.57 GB file afterwal_checkpoint(TRUNCATE); giant threadthr_v67duphyr7= 44,004 events / 70.7 MB (3,673 commandExecution completions = 54.7 MB, 2,524 toolCall rows = 1.5 MB, 520 of them TodoWrite/Task*). No providers were run; nothing about this repro needs a real agent.
Minimal reproduction
All scripts live in 1131/repro/ (paths below are relative to /tmp/bb-reports/issues/; the commands are run from your bb worktree root) and take BB_REPO=<abs path to your bb worktree>; they derive the server URL and data dir from scripts/bb-dev-app env|status. python3, curl, sqlite3 on PATH. Side effects in the worktree: the seed script applies 1131-seed-fixture.diff to packages/scripts/src/lib/seed-perf-fixture.ts, and the profiler script copies issue-1131-profile.ts into apps/server/; git checkout . / rm apps/server/issue-1131-profile.ts undo them.
- Build and start once, then stop:
pnpm install --frozen-lockfile --prefer-offline && pnpm exec turbo run build && scripts/bb-dev-app current && pnpm dev:stop. - Seed the database at scale (≈35 s):
BB_REPO=$PWD bash /tmp/bb-reports/issues/1131/repro/1131-seed.sh(script). It prints the giant thread id (thr_v67duphyr7; the seed is deterministic). - Start the dev instance again:
scripts/bb-dev-app current. Ten seconds after start the periodic sweeps begin; on this seeded db the first destroyed-environment prune is a single 5–27 s synchronous DELETE (see below) and the output-truncation sweep runs every 10 s. Step 4 waits for these to settle; if you probe/healthyourself in the first minute, expect stalls that are not the timeline. - Run the cold-timeline experiment:
BB_REPO=$PWD /tmp/bb-reports/issues/1131/repro/1131-cold-timeline.sh thr_v67duphyr7(script). Itkill -9s the server (the dev supervisor restarts it, so its in-memory timeline cache and SQLite page cache are empty), waits until the stale destroyed environments are pruned and a 12 s window of/healthsamples is all < 50 ms (so startup sweeps cannot be mistaken for the timeline), evicts the OS page cache forbb.db*withposix_fadvise(DONTNEED), starts aGET /healthprobe every 100 ms, then requests the latest timeline page while counting the server's/proc/<pid>/io read_bytes. At the end it prints the server's "Slow DB query" lines so any stall at another timestamp can be attributed to a sweep.
Expected: a page of ~1.7 MiB costs on the order of its own size in I/O and does not delay unrelated requests noticeably. Actual (revised script, run 1: 1131-cold-timeline-run1.out; run 2: 1131-cold-timeline-run2.out):
--- server=http://localhost:19384 db=/home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_570fde41-63f-8-cd8a2b804171/bb.db thread=thr_v67duphyr7
--- kill -9 server pid 3754638
--- server back
--- 15:18:28 waiting for startup sweeps to settle (stale destroyed environments left: 0)
15:18:41 still noisy (1 /health samples > 50 ms in a 12 s window); waiting
--- 15:18:54 sweeps quiet (stale destroyed environments: 0, quiet window: 1)
evicted /home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_570fde41-63f-8-cd8a2b804171/bb.db 1565405184
evicted /home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_570fde41-63f-8-cd8a2b804171/bb.db-wal 563521272
evicted /home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_570fde41-63f-8-cd8a2b804171/bb.db-shm 32768
--- 15:18:55.048 GET /api/v1/threads/thr_v67duphyr7/timeline (cold)
timeline: http=200 ttfb=0.283185s size=329482
--- server /proc/3756919/io before: rchar: 50698751 syscr: 18895 read_bytes: 57913344
--- server /proc/3756919/io after: rchar: 50744573 syscr: 18982 read_bytes: 134610944
--- 15:18:55.344 second request (warm, cached)
timeline: http=200 ttfb=0.003377s size=329482
--- /health probe, slowest 5:
15:18:55.098 health ttfb=0.231238s
15:18:55.563 health ttfb=0.064247s
15:18:58.663 health ttfb=0.001408s
15:19:02.418 health ttfb=0.001291s
15:19:02.063 health ttfb=0.001284s
--- /health probe, all samples > 0.05s:
15:18:55.098 health ttfb=0.231238s
15:18:55.563 health ttfb=0.064247s
--- server log lines:
@bb/server:dev: [15:17:52] INFO: [server] Thread timeline build blocked the event loop {"threadId":"thr_v67duphyr7","totalDurationMs":313.1,"thresholdMs":150,"suppressedSinceLastLog":0,"selectionStrategy":"standard-window","pageKind":"latest","segmentLimit":20,"eventRowCount":1599,"eventDataBytes":1 …
@bb/server:dev: [15:18:55] INFO: [server] Thread timeline build blocked the event loop {"threadId":"thr_v67duphyr7","totalDurationMs":276,"thresholdMs":150,"suppressedSinceLastLog":0,"selectionStrategy":"standard-window","pageKind":"latest","segmentLimit":20,"eventRowCount":1599,"eventDataBytes":169 …
--- server log: sweep work (Slow DB query) since the restart, for attribution of any other stall:
@bb/server:dev: [15:14:19] INFO: [server] Slow DB query {"bindingArgumentCount":268,"durationMs":114.2,"operation":"run","sql":"UPDATE events SET data = json_set( data, ?, substr(json_extract(data, ?), 1, ?) || ? || substr(json_extract(da…}
@bb/server:dev: [15:14:24] INFO: [server] Slow DB query {"bindingArgumentCount":1543,"durationMs":4987.6,"operation":"run","sql":"delete from \"environments\" where \"environments\".\"id\" in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,…}
@bb/server:dev: [15:17:52] INFO: [server] Slow DB query {"bindingArgumentCount":4,"durationMs":114.2,"operation":"all","sql":"select \"created_at\", \"data\", \"id\", \"item_id\", \"item_kind\", \"provider_thread_id\", \"scope_kind\", \…}
@bb/server:dev: [15:17:52] INFO: [server] Slow DB query {"bindingArgumentCount":595,"durationMs":104.8,"operation":"all","sql":"select \"created_at\", CASE WHEN length(\"data\") <= ? THEN \"data\" ELSE json_replace(\"data\", CASE WHEN jso…}
@bb/server:dev: [15:18:55] INFO: [server] Slow DB query {"bindingArgumentCount":595,"durationMs":110,"operation":"all","sql":"select \"created_at\", CASE WHEN length(\"data\") <= ? THEN \"data\" ELSE json_replace(\"data\", CASE WHEN jso…}
Read it as: the cold build took 276 ms of loop time (server log line; event-query 213 ms of it), the server read 76,697,600 bytes from disk for a 329 KB response (1.69 MiB of event rows before projection), and the /health request issued 50 ms after the timeline request waited 231 ms — it was queued behind the synchronous build. The second, cached request answered in 3 ms. Run 2 of the same script: 369 ms build (event-query 298 ms), 96,518,144 bytes read, /health stalled 332 ms. The earlier line at 15:17:52 is a run of the same script whose output I overwrote (313 ms build, event-query 249 ms, 97,509,376 bytes read, /health 284 ms); the original report's runs on another instance were 313–459 ms / 99.7 MB / 293 ms, and the verifier's two runs were 322 and 296 ms / 99.3 and 99.7 MB / 320 and 295 ms. The spread in bytes (77–100 MB) comes from pages the restarted server had already faulted in before the request (read_bytes before: 3.9–58 MB), which posix_fadvise cannot evict from a live mapping — the per-statement profiler below, run in a fresh process, gives the clean 99.97 MB figure.
Note the last block of the output: the server's own "Slow DB query" log names the two statements this report blames — at 15:17:52 and 15:18:55 the todo-snapshot select (bindingArgumentCount: 4, 114 ms) and the parent-tool-call select (bindingArgumentCount: 595, 105–110 ms) — while the two lines at 15:14:19/15:14:24 are startup sweep work from the first start (see below), not the timeline.
Startup sweeps on this db (why the script waits). Right after the very first start on the seeded db, before any timeline request, the sweeps blocked the loop on their own: delete from "environments" where id in (1543 ?) took 4,987.6 ms here (1131-startup-sweep-probe.out, tail of the log; the seed leaves 1,543 destroyed environments older than the 7-day TTL and 296,872 event rows referencing them, so the FK ON DELETE SET NULL rewrites all of those rows in one statement — the WAL grew from 0 to 563 MB) and the truncation-sweep UPDATE events … WHERE id IN (250 ?) took 114 ms per tick. On the verifier's more loaded machine the same delete took 26,776 ms and the truncation UPDATE 0.1–4.7 s per tick, and their /health probe recorded 27.98 s and 22.49 s stalls at those timestamps (verifier run 1) while the timeline itself was 322 ms. Those numbers are partly a seed artifact (a real install prunes a few environments per tick), but the mechanism — one synchronous multi-hundred-thousand-row write on the serving loop — is the same one this issue is about.
Where the bytes go: per-statement attribution
1131-profile.sh copies issue-1131-profile.ts into apps/server/ and runs the real buildThreadTimelineWithProfile against the same file with every prepared statement wrapped to record time and read_bytes/major-fault deltas. Run with the dev server stopped (pnpm dev:stop; a running server keeps the file mmapped, which defeats page-cache eviction): BB_REPO=$PWD 1131/repro/1131-profile.sh <data dir>/bb.db <thread id> /tmp/out. Cold (full):
{
"threadId": "thr_v67duphyr7",
"maxSeq": 44004,
"totalMs": 354,
"diskReadBytes": 99966976,
"majorPageFaults": 918,
…
10 statement executions, 10 distinct statements. Top by disk bytes:
73004 KiB 135 ms x 1 select "created_at", "data", "id", "item_id", "item_kind", "provider_thread_id", "scope_kind", "sequence", "thread_id", "turn_id", "type" from "events" where ("events"." …
20256 KiB 110 ms x 1 select "created_at", CASE WHEN length("data") <= ? THEN "data" ELSE json_replace("data", CASE WHEN json_type("events"."data", ?) = 'text' AND length(json_extract("events …
2268 KiB 4 ms x 1 select "thread_id" || ':user-seed:' || "sequence", "sequence" from "events" where ("events"."thread_id" = ? and "events"."type" = ? and ( COALESCE(json_extract("events". …
Warm, same page (full) — the second statement is CPU-bound and stays at ~64 ms with everything in RAM, because it still visits all 44k rows:
Top by time:
64 ms 0 KiB x 1 select "created_at", CASE WHEN length("data") <= ? THEN "data" ELSE json_replace("data", CASE WHEN json_type("events"."data", ?) = 'text' AND length(json_extract("events …
10 ms 0 KiB x 1 select "created_at", CASE WHEN length("data") <= ? THEN "data" ELSE json_replace("data", CASE WHEN json_type("events"."data", ?) = 'text' AND length(json_extract("events …
7 ms 0 KiB x 1 select "created_at", "data", "id", "item_id", "item_kind", "provider_thread_id", "scope_kind", "sequence", "thread_id", "turn_id", "type" from "events" where ("events"." …
Statement 1 is listTodoSnapshotEventRowsForThread; statement 2 is listStoredEventRowsByParentToolCallIds (unbounded). Their identity is confirmed by the SQL text and by the unit test below.
Control: the original thread-list path is fast on base
Truly cold (1131-cold-thread-list-true.sh, run with the dev instance stopped: evict the page cache, start the server, request before the first sweep tick; out):
evicted /home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_570fde41-63f-8-cd8a2b804171/bb.db 1571041280 --- 15:13:57.751 starting dev instance Server: http://localhost:19384 --- 15:14:12.159 server up, pid 3740166; startup so far: read_bytes: 4374528 --- 15:14:12.165 GET /api/v1/threads (first request after a cold start; before the first sweep tick at +10 s) threads: http=200 ttfb=0.052498s size=3267145 --- after request: read_bytes: 4390912 thread rows returned: 3287 --- 15:14:12.270 second GET /api/v1/threads (warm) threads: http=200 ttfb=0.052350s
Server startup itself faulted in 4.4 MB (it touches the threads pages, so a later kill-9-and-evict cannot make this route cold: posix_fadvise(DONTNEED) does not drop pages a live process has mapped). The first request added 16 KB of disk reads and took 52 ms; #1204 measured 10.5 s / 444,010 rows for the pre-fix query on a comparable db. The earlier measurement below (out) restarted the server and evicted afterwards, so it is really "first request after restart, threads pages already faulted in by startup" — 0–8 KB read — and is kept only for the warm CLI timing:
--- kill -9 server pid 2665941, wait for supervisor restart evicted /home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_242c3e11-a10-26-5256c67149d9/bb.db 1565413376 evicted /home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_242c3e11-a10-26-5256c67149d9/bb.db-wal 844632 evicted /home/sawyer/.bb-dev/projects-bb-.claude-worktrees-wf_242c3e11-a10-26-5256c67149d9/bb.db-shm 32768 --- 07:58:49.150 GET /api/v1/threads (cold, first after restart) threads: http=200 ttfb=0.051862s size=3170093 --- server io before: read_bytes: 0 / after: read_bytes: 8192 thread rows returned: 3287 --- 07:58:49.259 second GET /api/v1/threads (warm) threads: http=200 ttfb=0.045422s --- bb thread list --json (warm) via CLI • turbo 2.8.3 • Packages in scope: @bb/cli, @bb/scripts • Running build in 2 packages • Remote caching disabled, using shared worktree cache Tasks: 2 successful, 2 total Cached: 2 cached, 2 total Time: 188ms >>> FULL TURBO real 0m1.846s user 0m1.886s sys 0m0.871s
Unit-level repro (query plans and scaling)
File: issue-1131-timeline-full-thread-scans.test.ts (copy to packages/db/test/; run cd packages/db && pnpm exec vitest run test/issue-1131-timeline-full-thread-scans.test.ts --disableConsoleIntercept). It passes on main: it pins the current plans (thread-wide index walks with json_extract per row) and shows the parent-tool-call scan taking ~28x longer on a 10k-event thread than on a 200-event thread for the same empty result. Output (1131-vitest.out):
RUN v4.1.1 /home/sawyer/projects/bb/.claude/worktrees/wf_242c3e11-a10-26/packages/db
✓ @bb/db test/issue-1131-timeline-full-thread-scans.test.ts > issue #1131: latest-page timeline helpers scan the whole thread > listTodoSnapshotEventRowsForThread visits every tool-call row (and its payload) of the thread 87ms
✓ @bb/db test/issue-1131-timeline-full-thread-scans.test.ts > issue #1131: latest-page timeline helpers scan the whole thread > listStoredEventRowsByParentToolCallIds without sequence bounds is a full-thread scan with json_extract per row 74ms
issue-1131 parent-tool-call scan: 0.49 ms (200 events) vs 13.91 ms (10k events), ratio 28.4x
✓ @bb/db test/issue-1131-timeline-full-thread-scans.test.ts > issue #1131: latest-page timeline helpers scan the whole thread > the unbounded parent-tool-call scan cost grows with thread size, not page size 431ms
Test Files 1 passed (1)
Tests 3 passed (3)
Start at 08:01:00
Duration 1.28s (transform 257ms, setup 0ms, import 610ms, tests 593ms, environment 0ms)
import { describe, expect, it } from "vitest";
import { turnScope } from "@bb/domain";
import { createConnection, type DbConnection } from "../src/connection.js";
import { migrate } from "../src/migrate.js";
import { noopNotifier } from "../src/notifier.js";
import {
insertEvents,
listStoredEventRowsByParentToolCallIds,
listTodoSnapshotEventRowsForThread,
} from "../src/data/events.js";
import { upsertHost } from "../src/data/hosts.js";
import { createProject } from "../src/data/projects.js";
import { createThread } from "../src/data/threads.js";
// Issue #1131 (timeline follow-up, 0.37.0 comment): the *latest page* of a
// large thread blocks the event loop for seconds on a cold cache. Two of the
// helpers the latest-page build always runs are not bounded by the page
// window at all: they walk every event (or every tool-call event) of the
// thread and evaluate json_extract() on the payload of each visited row, so
// their cost is proportional to the whole thread's stored bytes rather than to
// the page that is returned. This test pins the shape of the SQL plans and
// shows the row-visit scaling with an in-memory database.
//
// It PASSES on main: it documents the current plans. Once either helper is
// bounded (partial/expression index, or persisted state), the plan assertions
// here must be updated deliberately.
type SqliteParameter = string | number | bigint | Buffer | null;
interface QueryPlanRow {
detail: string;
}
interface CapturedStatement {
params: SqliteParameter[];
sql: string;
}
function captureStatements(
db: DbConnection,
run: () => void,
): CapturedStatement[] {
const captured: CapturedStatement[] = [];
const raw = db.$client;
const originalPrepare = raw.prepare.bind(raw);
Object.defineProperty(raw, "prepare", {
configurable: true,
writable: true,
value: (source: string) => {
const statement = originalPrepare(source);
const originalAll = statement.all.bind(statement);
statement.all = (...params: unknown[]) => {
captured.push({ params: params as SqliteParameter[], sql: source });
return originalAll(...params);
};
return statement;
},
});
try {
run();
} finally {
Object.defineProperty(raw, "prepare", {
configurable: true,
writable: true,
value: originalPrepare,
});
}
return captured;
}
function queryPlan(db: DbConnection, statement: CapturedStatement): string {
return db.$client
.prepare<SqliteParameter[], QueryPlanRow>(
`EXPLAIN QUERY PLAN ${statement.sql}`,
)
.all(...statement.params)
.map((row) => row.detail)
.join("\n");
}
function setup() {
const db = createConnection(":memory:");
migrate(db);
const host = upsertHost(db, noopNotifier, {
name: "issue-1131-host",
type: "persistent",
});
const { project } = createProject(db, noopNotifier, {
name: "issue-1131",
source: { type: "local_path", hostId: host.id, path: "/tmp/issue-1131" },
});
const thread = createThread(db, noopNotifier, {
projectId: project.id,
providerId: "claude-code",
});
return { db, thread };
}
/**
* A thread made of `toolCallPairs` Read tool calls (item/started +
* item/completed with a `resultText` of `payloadChars`) followed by one
* TodoWrite. This is the shape of a long claude-code session: thousands of
* tool calls, each carrying a multi-KB result, and a handful of todo writes.
*/
function seedToolCallThread(
db: DbConnection,
threadId: string,
toolCallPairs: number,
payloadChars: number,
): number {
const payload = "x".repeat(payloadChars);
let sequence = 0;
const batch: Parameters<typeof insertEvents>[2] = [];
for (let index = 0; index < toolCallPairs; index += 1) {
const itemId = `call_${index}`;
batch.push({
data: JSON.stringify({
item: { id: itemId, type: "toolCall", tool: "Read", status: "inProgress" },
}),
itemId,
itemKind: "toolCall",
scope: turnScope("turn_1131"),
sequence: ++sequence,
threadId,
type: "item/started",
});
batch.push({
data: JSON.stringify({
item: {
id: itemId,
type: "toolCall",
tool: "Read",
status: "completed",
resultText: payload,
},
}),
itemId,
itemKind: "toolCall",
scope: turnScope("turn_1131"),
sequence: ++sequence,
threadId,
type: "item/completed",
});
}
batch.push({
data: JSON.stringify({
item: {
id: "call_todo",
type: "toolCall",
tool: "TodoWrite",
status: "completed",
args: { todos: [{ content: "ship", status: "pending" }] },
},
}),
itemId: "call_todo",
itemKind: "toolCall",
scope: turnScope("turn_1131"),
sequence: ++sequence,
threadId,
type: "item/completed",
});
db.transaction((tx) => {
insertEvents(tx, noopNotifier, batch);
});
return sequence;
}
describe("issue #1131: latest-page timeline helpers scan the whole thread", () => {
it("listTodoSnapshotEventRowsForThread visits every tool-call row (and its payload) of the thread", () => {
const { db, thread } = setup();
seedToolCallThread(db, thread.id, 200, 2_000);
const captured = captureStatements(db, () => {
const rows = listTodoSnapshotEventRowsForThread(db, {
threadId: thread.id,
});
// Only the single TodoWrite row is wanted ...
expect(rows).toHaveLength(1);
});
const statement = captured.find((entry) =>
entry.sql.includes("'TodoWrite'"),
);
if (!statement) {
throw new Error("expected the todo snapshot SQL");
}
// ... but the plan can only narrow to (thread_id, type, item_kind): the
// json_extract($.item.tool) filter is applied per row after fetching the
// event payload, so every tool-call row of the thread is read from disk.
// On the reporter's 44k-event thread that is thousands of multi-KB rows
// scattered across a 1.6 GiB file (73 MiB of reads on the seeded copy).
const plan = queryPlan(db, statement);
expect(plan).toMatch(
/SEARCH events USING INDEX events_thread_type_item_kind_sequence_idx \(thread_id=\? AND type=\? AND item_kind=\?\)/u,
);
expect(plan).not.toContain("COVERING INDEX");
db.$client.close();
});
it("listStoredEventRowsByParentToolCallIds without sequence bounds is a full-thread scan with json_extract per row", () => {
const { db, thread } = setup();
seedToolCallThread(db, thread.id, 200, 2_000);
const captured = captureStatements(db, () => {
// This is how ensureTimelineWindowParentedRows calls it for the latest
// page (sequenceBounds === null): no sequenceStart / beforeSequence.
const rows = listStoredEventRowsByParentToolCallIds(db, {
excludedTypes: ["item/agentMessage/delta"],
maxInlineOutputChars: 4_000,
parentToolCallIds: ["call_7", "call_9"],
threadId: thread.id,
});
expect(rows).toHaveLength(0);
});
const statement = captured.find((entry) =>
entry.sql.includes("'$.parentToolCallId'"),
);
if (!statement) {
throw new Error("expected the parent-tool-call SQL");
}
const plan = queryPlan(db, statement);
// (thread_id=?) only: SQLite walks every event of the thread through the
// thread/sequence index and evaluates json_extract on each payload.
expect(plan).toMatch(
/SEARCH events USING INDEX events_thread_sequence_idx \(thread_id=\?\)/u,
);
db.$client.close();
});
it("the unbounded parent-tool-call scan cost grows with thread size, not page size", () => {
const { db, thread } = setup();
const small = createThread(db, noopNotifier, {
projectId: thread.projectId,
providerId: "claude-code",
});
seedToolCallThread(db, small.id, 100, 4_000);
seedToolCallThread(db, thread.id, 5_000, 4_000);
const time = (threadId: string): number => {
const start = performance.now();
for (let index = 0; index < 5; index += 1) {
listStoredEventRowsByParentToolCallIds(db, {
excludedTypes: ["item/agentMessage/delta"],
maxInlineOutputChars: 4_000,
parentToolCallIds: ["call_1"],
threadId,
});
}
return (performance.now() - start) / 5;
};
const smallMs = time(small.id);
const largeMs = time(thread.id);
// Same page (zero matching rows either way), 50x the thread: the query
// time follows the thread. Printed rather than asserted on an exact ratio
// to keep the test stable on slow CI; the ratio is ~30-50x locally.
console.log(
`issue-1131 parent-tool-call scan: ${smallMs.toFixed(2)} ms (200 events) vs ${largeMs.toFixed(2)} ms (10k events), ratio ${(largeMs / smallMs).toFixed(1)}x`,
);
expect(largeMs).toBeGreaterThan(smallMs * 5);
db.$client.close();
});
});
Root cause
1. Structural: reads are synchronous on the only event loop. GET /threads/:id/timeline calls buildThreadTimelineWithProfile inside runEventLoopWorkSync (timeline.ts#L1809-L1846); every SQLite call underneath is a blocking better-sqlite3 call on the main thread (connection.ts#L164-L191). The server itself documents the consequence: a slow build "directly stalls agent work on every thread on the host" (timeline-build-log.ts#L4-L17) and logs "Thread timeline build blocked the event loop" above 150 ms, and "Event loop stalled" above 500 ms (event-loop-stall-monitor.ts#L13-L15). Nothing has changed here since the issue was filed; #1198 (worker thread) was closed in favour of query-level fixes (#1207).
2. The thread-list stall (the issue's headline) was listLatestGoalEventRowsByThreadIds, fixed by #1204. Not re-derived here; #1204's writeup and the reporter's follow-up confirm it, and my first-request-after-cold-start thread list over 3,287 threads is 52 ms with 16 KB of reads.
3. The timeline stall (0.37.0 comment) comes from two window-independent, whole-thread reads inside the "event-query" stage. selectStandardTimelineEventRows (timeline.ts#L1380-L1500) correctly bounds the window rows by segment anchors and an event budget, but then backfills state with helpers that ignore the window:
ensureLatestTimelineHeadStateRows→listTodoSnapshotEventRowsForThread(timeline.ts#L1011-L1017, events.ts#L1911-L1940). SQL:thread_id = ? AND type IN (?,?) AND item_kind = ? AND json_extract(data,'$.item.tool') IN ('TodoWrite',…). Plan:SEARCH events USING INDEX events_thread_type_item_kind_sequence_idx (thread_id=? AND type=? AND item_kind=?)— the index narrows to all tool-call rows of the thread, and thejson_extractfilter forces a table fetch of each row'sdatapayload. The doc comment assumes "tens of rows per thread"; the row count it actually visits is the thread's tool-call count (2,524 here; a long claude-code session has thousands, each with a multi-KB result). Cold: 73 MB / 135 ms on NVMe.ensureTimelineWindowParentedRows→listStoredEventRowsByParentToolCallIds(timeline.ts#L463-L517, events.ts#L1325-L1370). For the latest pagesequenceBoundsisnull(timeline.ts#L1450-L1458), so the SQL isthread_id = ? AND (json_extract(data,'$.parentToolCallId') IN (…) OR json_extract(data,'$.item.parentToolCallId') IN (…)) AND type NOT IN (…) ORDER BY sequence. Plan:SEARCH events USING INDEX events_thread_sequence_idx (thread_id=?)— every event of the thread is visited and its payload parsed. Cold: 20 MB / 110 ms; warm: 64 ms CPU. Both queries touch overlapping pages, so whichever runs first pays most of the I/O; together they read essentially every page holding this thread's rows (~100 MB with mmap readahead), which is why the total did not drop when I indexed only the todo lookup (see the experiment below).
Why the symptom follows. A 44k-event thread's rows are interleaved with 700k other rows across a 1.6 GB file. Visiting all of them (or all tool-call rows) means thousands of scattered page faults; on a cloud volume each is a synchronous ~ms read plus ~100 MB of throughput, and every one of those milliseconds is loop time. That yields the reporter's profile shape exactly: event-query ≫ decode + projection, 1.2k rows / 1.7 MiB returned. It also explains why warm requests still cost 270–330 ms for them (the full-thread json_extract walk is CPU, not I/O). #1716's index for hasParentedEventCrossingSequence and the background-task aggregation are different queries and do not touch these two.
Deeper issue. Several timeline backfills query "the whole thread" for state that is conceptually per-thread (current todo list, open background tasks, parent/child links) but is stored only as events with the discriminator inside JSON. Any such lookup is O(thread) unless there is a partial/expression index whose predicate the query spells out literally, and the planner needs an INDEXED BY pin because bb.db never runs ANALYZE (#1204 hit both points). Adding a worker thread would stop one client's page from freezing everyone, but the read amplification would remain.
Deeper issue, writes. The same loop also runs the periodic sweeps synchronously (start-server.ts#L254-L257). pruneDestroyedEnvironments (sweeps.ts#L365-L397) deletes every stale destroyed environment in one unbatched statement, and events.environment_id / threads.environment_id are ON DELETE SET NULL with foreign_keys = ON, so the statement rewrites every event row of those environments (296,872 rows → 5.0–26.8 s and a 563 MB WAL here). The truncation sweep's UPDATE … WHERE id IN (250 ?) AND … length(json_extract(data, ?)) > ? (sweeps.ts#L224-L250) reads 250 scattered payloads per output path per tick to change 0 rows on this data (0.1 s here, up to 4.7 s under load). Neither is bounded by time or row count per tick; a fix would batch the prune (e.g. 50 environments per tick) and skip the truncation UPDATE when the scan found no candidate over the threshold.
Proposed fix (first principles)
- Bound the parent/child backfill on the latest page. Children of a tool call are always appended after the parent's
item/started, and every visible tool call is inside the window (rows ≥sequenceStart). PasssequenceStart: window.sequenceStart(no upper bound) instead ofnullat timeline.ts#L1450-L1458, and add a partial index that lets the parented lookup avoid the payload walk, e.g.events (thread_id, sequence) WHERE COALESCE(json_extract(data,'$.item.parentToolCallId'), json_extract(data,'$.parentToolCallId')) IS NOT NULLspelled identically in the query. Risk: a page that opens mid-turn with a parent tool call started beforesequenceStart— that case is already covered by the "missing parent context" path (listStoredToolCallRowsByItemIds) and byensureTimelineWindowTurnStartedRows; add a test for a nested subagent whose parent is on an older page. - Limit the todo-snapshot lookup to the todo/task rows. Add a partial expression index
events (thread_id, sequence) WHERE item_kind='toolCall' AND type IN ('item/started','item/completed') AND json_extract(data,'$.item.tool') IN ('TodoWrite','TaskCreate','TaskUpdate','TaskList','TaskGet')(Drizzle schema + generated migration, like #1204/#1716), rewritelistTodoSnapshotEventRowsForThreadwith literal type/item_kind values andINDEXED BY, and add a query-plan regression topackages/db/test/query-plans.test.ts. I verified on the seeded db that the pinned plan becomesSEARCH events USING INDEX events_todo_snapshot_idx (thread_id=?)visiting 520 rows (and fetching only their payloads: 28 MB instead of 73 MB cold; the index is not covering, the helper still readsdatafor each hit) instead of all 2,524 tool-call rows, and that without the pin the stats-less planner keeps the old plan (experiment, sql, code diff). Alternatively persist the current todo list as thread state at append time so the timeline never re-derives it. - Then re-measure with the profiler script cold; if the event-query stage is still dominated by scattered payload reads, that is the moment for the shared read-isolation seam #1207 discusses (one worker owned by the DB layer, serving thread-list and timeline).
- Retention (separate, smaller): lower
COMPLETED_EVENT_OUTPUT_TRUNCATION_THRESHOLD_CHARStoward 4–8 KB (or make it a settings knob) — the batch size is not the constraint. Note that truncation only shrinks the constant; the fixes above remove the O(thread) factor.
Run Time: real 0.000 user 0.000266 sys 0.000266 --- plan with literals (as the query would have to be written for SQLite to prove the partial-index predicate): QUERY PLAN `--SEARCH events USING INDEX events_thread_type_item_kind_sequence_idx (thread_id=? AND type=? AND item_kind=?) Run Time: real 0.000 user 0.000018 sys 0.000018 --- plan with the current bound parameters for type/item_kind (partial index NOT usable): QUERY PLAN `--SEARCH events USING INDEX events_thread_type_item_kind_sequence_idx (thread_id=? AND type=? AND item_kind=?) Run Time: real 0.000 user 0.000017 sys 0.000017 --- rows in the partial index (whole database): 7656 Run Time: real 0.001 user 0.000341 sys 0.000000 --- plan when pinned with INDEXED BY (what a fix would emit, cf. #1204): QUERY PLAN `--SEARCH events USING INDEX events_todo_snapshot_idx (thread_id=?) Run Time: real 0.000 user 0.000020 sys 0.000000 520 Run Time: real 0.000 user 0.000034 sys 0.000000
Cold profile after applying the todo-index experiment (index created manually, helper pinned): the todo statement drops to 28 MB but the unbounded parent scan absorbs the pages it no longer pre-faulted (65 MB); total stays ~100 MB — evidence that fix 1 is required, not optional (full):
10 statement executions, 10 distinct statements. Top by disk bytes:
64896 KiB 191 ms x 1 select "created_at", CASE WHEN length("data") <= ? THEN "data" ELSE json_replace("data", CASE WHEN json_type("events"."data", ?) = 'text' AND length(json_extract("events …
28356 KiB 45 ms x 1 SELECT "events"."created_at" AS "createdAt", "events"."data" AS "data", "events"."id" AS "id", "events"."item_id" AS "itemId", "events"."item_kind" AS "itemKind", "event …
PR review
No open PRs are linked to this issue. Historical: #1204 (merged) fixed the thread-list half; #1198 (closed) proposed the worker thread; #1716 (merged, in base, not in 0.37/0.38) optimized two other timeline queries.
Related issues
- #1207: thread-list reads still synchronous after #1204 — the "revisit condition" the reporter says is now met by the timeline path.
- #1205 / #1209: SQLite variable-limit failure on the same route.
- #1334: co-located workload starving the bb server (same single-loop sensitivity).
- #882: introduced the event-budgeted window and
listTodoSnapshotEventRowsForThread; #1199: introducedsequenceBoundsfor byte-paged turns (leftnullfor the latest page).
Appendix
Commands run
cd /home/sawyer/projects/bb/.claude/worktrees/wf_242c3e11-a10-26 && git checkout 16ceb3a54
pnpm install --frozen-lockfile --prefer-offline && pnpm exec turbo run build
scripts/bb-dev-app current # app :13609 server :21609 daemon :29609; creates data dir + host-id
pnpm dev:stop
git apply 1131/repro/1131-seed-fixture.diff && pnpm exec turbo run build --filter=@bb/scripts
BB_SEED_GIANT_THREAD_EVENTS=44000 BB_SEED_OUTPUT_LINE_SCALE=6 pnpm seed:perf -- --reset --threads 4000 --events 650000
sqlite3 <data dir>/bb.db "PRAGMA wal_checkpoint(TRUNCATE);"
scripts/bb-dev-app current
export BB_REPO=$PWD
1131/repro/1131-cold-timeline.sh thr_v67duphyr7 # -> 1131-cold-timeline-run1.out
1131/repro/1131-cold-thread-list.sh # -> 1131-cold-thread-list.out
pnpm dev:stop # so page-cache eviction is effective for the profiler
1131/repro/1131-profile.sh <data dir>/bb.db thr_v67duphyr7 1131/repro/1131-profile-base
cp 1131/repro/issue-1131-timeline-full-thread-scans.test.ts packages/db/test/ && cd packages/db && pnpm exec vitest run test/issue-1131-timeline-full-thread-scans.test.ts --disableConsoleIntercept
sqlite3 <data dir>/bb.db < 1131/repro/1131-todo-index-experiment.sql
git apply 1131/repro/1131-todo-index-experiment.diff && 1131/repro/1131-profile.sh <data dir>/bb.db thr_v67duphyr7 1131/repro/1131-profile-todo-index-fix
git checkout packages/db/src/data/events.ts; sqlite3 <data dir>/bb.db "DROP INDEX events_todo_snapshot_idx;"
pnpm dev:stop
# --- revision run (worktree wf_570fde41-63f-8, same commit) ---
git checkout 16ceb3a54 && pnpm install --frozen-lockfile --prefer-offline && pnpm exec turbo run build
scripts/bb-dev-app current && pnpm dev:stop
BB_REPO=$PWD bash /tmp/bb-reports/issues/1131/repro/1131-seed.sh # 34.1 s, thr_v67duphyr7 44004 events / 70,702,989 bytes, 1,571,041,280-byte file
BB_REPO=$PWD /tmp/bb-reports/issues/1131/repro/1131-cold-thread-list-true.sh # evict, start, first request -> 1131-cold-thread-list-true.out
BB_REPO=$PWD /tmp/bb-reports/issues/1131/repro/1131-startup-sweep-probe.sh 150 # -> 1131-startup-sweep-probe.out
sqlite3 <data dir>/bb.db "select count(*) from environments where status='destroyed' and updated_at < (strftime('%s','now')*1000 - 7*86400000);" # 1543 before the first sweep
sqlite3 <data dir>/bb.db "select count(*) from events where environment_id in (select id from environments where status='destroyed' and updated_at < (strftime('%s','now')*1000 - 7*86400000));" # 296872
BB_REPO=$PWD /tmp/bb-reports/issues/1131/repro/1131-cold-timeline.sh thr_v67duphyr7 # x3 -> 1131-cold-timeline-run1.out, -run2.out
pnpm dev:stop
Seed fixture patch
diff --git a/packages/scripts/src/lib/seed-perf-fixture.ts b/packages/scripts/src/lib/seed-perf-fixture.ts
index 3d882a4eb..a2c5e7966 100644
--- a/packages/scripts/src/lib/seed-perf-fixture.ts
+++ b/packages/scripts/src/lib/seed-perf-fixture.ts
@@ -528,7 +528,11 @@ function buildThreadEvents(args: ThreadEventBuildArgs): void {
cwd: "",
status: "completed",
approvalStatus: null,
- aggregatedOutput: makeOutput(rng, rng.int(10, 120)),
+ aggregatedOutput: makeOutput(
+ rng,
+ rng.int(10, 120) *
+ (Number(process.env.BB_SEED_OUTPUT_LINE_SCALE ?? 1) || 1),
+ ),
},
},
});
@@ -872,6 +876,11 @@ export function seedPerfFixture(
options.threadCount,
options.eventCount,
);
+ // Issue #1131 repro: allow one giant thread (reporter: 44,246 events).
+ const giantThreadEvents = Number(process.env.BB_SEED_GIANT_THREAD_EVENTS ?? 0);
+ if (Number.isInteger(giantThreadEvents) && giantThreadEvents > 0) {
+ eventTargets[0] = giantThreadEvents;
+ }
interface SeededThread {
row: ThreadInsert;
Profiler source (issue-1131-profile.ts)
// Issue #1131 profiling harness: run one timeline "latest page" build for a
// thread against a real bb.db, exactly as the route does, and attribute the
// event-loop-blocking time and disk reads to individual SQL statements.
//
// Usage (from apps/server, with the dev server STOPPED or the DB copied):
// node --conditions=source --import tsx issue-1131-profile.ts <bb.db> <thread id> [cold]
//
// "cold" evicts the OS page cache for the db files first (posix_fadvise via
// python3 is not needed: we use fs + a tiny fadvise shim through `dd`-free
// approach: node has no fadvise, so pass "cold" only after running the
// eviction yourself; the script prints /proc/self/io read_bytes deltas so
// you can see whether reads hit disk).
import { readFileSync } from "node:fs";
import { performance } from "node:perf_hooks";
import { createConnection, getThread } from "@bb/db";
import { buildThreadTimelineWithProfile } from "./src/services/threads/timeline.js";
import { DEFAULT_MAX_INLINE_OUTPUT_CHARS } from "./src/services/threads/timeline-output-truncation.js";
const [dbPath, threadId] = process.argv.slice(2);
if (!dbPath || !threadId) {
console.error("usage: issue-1131-profile.ts <bb.db> <thread id>");
process.exit(2);
}
function readBytes(): number {
const io = readFileSync("/proc/self/io", "utf8");
const m = /^read_bytes: (\d+)/mu.exec(io);
return m ? Number(m[1]) : 0;
}
/** Major page faults so far: with SQLite mmap each cold page is one fault. */
function majorFaults(): number {
const stat = readFileSync("/proc/self/stat", "utf8");
// field 12 (1-indexed) after the comm field; comm may contain spaces.
const rest = stat.slice(stat.lastIndexOf(")") + 2).split(" ");
return Number(rest[9]);
}
interface StmtSample {
sql: string;
ms: number;
bytes: number;
op: string;
args: number;
}
const samples: StmtSample[] = [];
const db = createConnection(dbPath, {
slowQueryThresholdMs: 0,
slowQueryLogger: {
info() {
/* replaced by the wrapper below */
},
},
});
// Wrap prepare again so each statement execution records read_bytes deltas.
const sqlite = db.$client;
const originalPrepare = sqlite.prepare.bind(sqlite);
Object.defineProperty(sqlite, "prepare", {
configurable: true,
writable: true,
value: (source: string) => {
const stmt = originalPrepare(source);
for (const op of ["all", "get", "run"] as const) {
const original = stmt[op].bind(stmt);
(stmt as unknown as Record<string, unknown>)[op] = (
...params: unknown[]
) => {
const b0 = readBytes();
const t0 = performance.now();
try {
return original(...params);
} finally {
samples.push({
sql: source.replace(/\s+/gu, " ").trim().slice(0, 1200),
ms: performance.now() - t0,
bytes: readBytes() - b0,
op,
args: params.length,
});
}
};
}
return stmt;
},
});
const thread = getThread(db, threadId);
if (!thread) {
console.error(`thread ${threadId} not found`);
process.exit(1);
}
const maxSeq = (
db.$client
.prepare("select max(sequence) as s from events where thread_id = ?")
.get(threadId) as { s: number }
).s;
samples.length = 0;
const bytesBefore = readBytes();
const faultsBefore = majorFaults();
const t0 = performance.now();
const { profile } = buildThreadTimelineWithProfile(db, thread, {
eventBudget: 1500,
includeProviderUnhandledOperations: false,
includeNestedRows: false,
maxInlineOutputChars: DEFAULT_MAX_INLINE_OUTPUT_CHARS,
maxSeq,
page: { kind: "latest", segmentLimit: 20 },
providerDisplayName: "Codex",
planCommand: null,
summaryOnly: false,
});
const totalMs = performance.now() - t0;
const bytesAfter = readBytes();
const faultsAfter = majorFaults();
console.log(
JSON.stringify(
{
threadId,
maxSeq,
totalMs: Math.round(totalMs),
diskReadBytes: bytesAfter - bytesBefore,
majorPageFaults: faultsAfter - faultsBefore,
profile: {
...profile,
stageTimings: profile.stageTimings.map((s) => ({
stage: s.stage,
ms: Math.round(s.durationMs * 10) / 10,
})),
},
},
null,
2,
),
);
// Aggregate by SQL text.
const agg = new Map<
string,
{ n: number; ms: number; bytes: number; op: string }
>();
for (const s of samples) {
const key = s.sql;
const cur = agg.get(key) ?? { n: 0, ms: 0, bytes: 0, op: s.op };
cur.n += 1;
cur.ms += s.ms;
cur.bytes += s.bytes;
agg.set(key, cur);
}
const rows = [...agg.entries()].sort((a, b) => b[1].bytes - a[1].bytes);
console.log(
`\n${samples.length} statement executions, ${agg.size} distinct statements. Top by disk bytes:`,
);
for (const [sql, v] of rows.slice(0, 12)) {
console.log(
` ${String(Math.round(v.bytes / 1024)).padStart(7)} KiB ${String(Math.round(v.ms)).padStart(5)} ms x${String(v.n).padStart(3)} ${sql}`,
);
}
const byMs = [...agg.entries()].sort((a, b) => b[1].ms - a[1].ms);
console.log(`\nTop by time:`);
for (const [sql, v] of byMs.slice(0, 8)) {
console.log(
` ${String(Math.round(v.ms)).padStart(5)} ms ${String(Math.round(v.bytes / 1024)).padStart(7)} KiB x${String(v.n).padStart(3)} ${sql}`,
);
}
Sweep cursor evidence (15 min after start; fixture rows span ~90 days)
sqlite> select id, datetime(last_created_at/1000,'unixepoch'), datetime(updated_at/1000,'unixepoch') from maintenance_scan_cursors; completed_event_output_truncation:v1:commandExecution:aggregatedOutput|2026-06-04 17:41:18|2026-08-18 08:01:25 completed_event_output_truncation:v1:toolCall:result|2026-07-15 08:14:49|2026-08-18 08:01:25 sqlite> select count(*), sum(length(json_extract(data,'$.item.aggregatedOutput'))>32768), sum(length(json_extract(data,'$.item.aggregatedOutput'))>4096) ...> from events where type='item/completed' and item_kind='commandExecution'; 56166|0|51453 sqlite> select count(*) from events where type='item/completed' and item_kind='commandExecution' and json_type(data,'$.item.truncation.aggregatedOutput') is not null; 0
Query plans on the seeded db (base code)
sqlite> explain query plan select id from events where thread_id='thr_v67duphyr7' and (json_extract(data,'$.parentToolCallId') in ('a','b') or json_extract(data,'$.item.parentToolCallId') in ('a','b')) and type not in ('x','y') order by sequence;
`--SEARCH events USING INDEX events_thread_sequence_idx (thread_id=?)
sqlite> explain query plan select id from events where thread_id='thr_v67duphyr7' and type in ('item/started','item/completed') and item_kind='toolCall' and json_extract(data,'$.item.tool') in ('TodoWrite','TaskCreate','TaskUpdate','TaskList','TaskGet');
`--SEARCH events USING INDEX events_thread_type_item_kind_sequence_idx (thread_id=? AND type=? AND item_kind=?)
sqlite> select type, count(*), sum(length(data)) from events where thread_id='thr_v67duphyr7' and item_kind='toolCall' group by type;
item/completed|1262|1268995
item/started|1262|279417
Verification
An independent verifier re-ran the repro at 16ceb3a54 in a separate worktree (dev instance app :18014 / server :26014). The seed was byte-identical (704,206 events, 1,571,041,280-byte file, same giant thread), the cold timeline build was 322 / 296 ms with 99.3 / 99.7 MB read and a 320 / 295 ms /health stall, the profiler gave the same 99,966,976 bytes / 918 major faults / 73,004 KiB + 20,256 KiB top statements, the unit test passed 3/3 (ratio 29.0x), the truncation stats matched exactly, all 17 permalinks resolved, and origin/main (5 commits ahead) does not touch the two queries. Their findings and what changed in this revision:
- Major — startup sweeps stall the probe too. On the verifier's first run,
/healthrecorded 27.98 s and 22.49 s stalls caused by the destroyed-environment prune (26,776 ms DELETE) and the truncation-sweep UPDATE (up to 4.7 s), which the report did not mention. Fixed by re-running: I reproduced the prune on my instance (4,987.6 ms, 1,543 environments, 296,872 SET-NULL event rows, 563 MB WAL), added a settle-wait and sweep-log attribution to1131-cold-timeline.sh, re-captured1131-cold-timeline-run1.outand a new-run2.outwith the revised script (276 / 369 ms build, 76.7 / 96.5 MB, 231 / 332 ms stall), added1131-startup-sweep-probe.sh/.out, and documented the two synchronous writes in the TL;DR, step 3, the Actual section and "Deeper issue, writes". - Minor — seed script not executable.
chmod +xapplied to1131-seed.sh(and the sweep probe); step 2 now saysbash …/1131-seed.sh, and the repro preamble states where the paths are relative to and which worktree files the scripts touch. - Minor — thread-list control was not cold. Confirmed: kill-9-then-evict cannot evict pages the restarted server already mapped. Added
1131-cold-thread-list-true.sh(evict before start, request before the first sweep tick): startup faulted in 4.4 MB, the request added 16 KB and took 52 ms; relabelled the old measurement in the TL;DR, claims table, control section and root cause. - Minor — "index-only" was wrong. Proposed fix 2 now says the partial index limits the visit to the 520 todo/task rows and still fetches their payloads (28 MB, per the report's own experiment); it is not covering.
Not re-run in this revision: the standalone profiler and the todo-index experiment (verified unchanged by the verifier; artifacts kept). One unexplained detail: on my instance the 5.0 s prune DELETE produced a "Slow DB query" line but no "Event loop stalled" line, whereas the verifier's 26.8 s prune produced both.