#4161 · Synchronous cleanup of wide event rows

Bug · Priority Medium · Effort Medium · workspaces · perf

GitHub issue · 2026-09-23 · base 94d77da09568d7f0f7cdb23b84686e743acfb0ad

PARTIALLY REPRODUCED · Root-cause confidence: medium · partial-repro

TL;DR

The cleanup path performs synchronous database work before yielding, so a slow statement would delay the server event loop. Both clean-checkout runs confirmed that behavior and the intentional exception allowing one event larger than the 256 KiB budget. Neither run reproduced multi-second statements: measured calls ranged from 0.322 to 6.282 ms. The candidate query uses SQLite's byte-length optimization, so attributing its cost to reading every payload's overflow pages is unsupported and contradicted by the compiled query.

Claims vs findings

ClaimFindingEvidence
Cleanup executes synchronously between yieldsVerifiedSource and pending setImmediate assertion in both runs.
50-row candidate limit, 256 KiB detach budget, up to ten advancesVerifiedConstants and sweep implementation at the recorded commit.
Candidate byte counting loads the full payloadRefuted for tested SQLiteColumn P5=192 (OPFLAG_BYTELENARG), with overflow-content shortcut in bundled SQLite.
1–8 second statements and reported lifetime totalsUnverifiedNo user database or logs accessed; synthetic in-memory timings remained below 7 ms.
Backlog drains faster than inflowUnverified50 is a candidate maximum, not guaranteed detached throughput; wide rows reduce actual batch size.

Environment

Trusted public get-bb/bb main commit above; package version 0.43.4; Darwin arm64; Node 22.22.3; pinned pnpm 9.15.0 through Corepack; better-sqlite3 12.10.0. Two separate detached worktrees A and B, each with a frozen install and successful Turbo build (60 tasks). No live BB instance, ports, provider sessions, or user data were used. Each run creates and migrates a new in-memory database and closes it afterward.

Minimal reproduction

Clone and build the recorded main revision, copy the inline test into the stated path, and run it. Repeat in another clean clone with the same revision. No production source modifications are required.

git clone https://github.com/get-bb/bb.git bb-4161
cd bb-4161
git checkout --detach 94d77da09568d7f0f7cdb23b84686e743acfb0ad
corepack pnpm install --frozen-lockfile --prefer-offline
corepack pnpm exec turbo run build
# Copy the inline issue-4161.test.ts into packages/db/test/data/.
corepack pnpm exec turbo run test --filter=@bb/db --force -- --silent=false test/data/issue-4161.test.ts

The complete test and raw measurements are included below.

Expected latency target for evaluating the report: no multi-second event-loop pause. Actual: pending immediate stays pending until synchronous cleanup returns; one event detached per measured call. The 128 KiB JSON payload exceeds half the budget after JSON framing, so two do not fit. The 512 KiB and 16 MiB rows individually exceed the budget. This is a measurement test that passes on main, not a failing regression test.

RunPayload bytesRows seededCall msDetached rows
A131072500.6181
A524288500.5071
A1677721626.2821
B131072500.4561
B524288500.3221
B1677721624.6651

Test source

import { expect, it } from "vitest";
import { createConnection } from "../../src/connection.js";
import { migrate } from "../../src/migrate.js";
import { noopNotifier } from "../../src/notifier.js";
import { upsertHost } from "../../src/data/hosts.js";
import { createProject } from "../../src/data/projects.js";
import { createEnvironment } from "../../src/data/environments.js";
import { createThread } from "../../src/data/threads.js";
import { pruneDestroyedEnvironments } from "../../src/data/sweeps.js";
import { events } from "../../src/schema.js";

it("measures synchronous detach work with wide event payloads", async () => {
  const measurements: { operation: string; durationMs: number; sql: string }[] = [];
  const db = createConnection(":memory:", {
    slowQueryThresholdMs: 0,
    slowQueryLogger: { info(fields) { measurements.push(fields); } },
  });
  try {
    migrate(db);
    const host = upsertHost(db, noopNotifier, { name: "repro" });
    const { project } = createProject(db, noopNotifier, {
      name: "repro", source: { type: "local_path", hostId: host.id, path: "/tmp/issue-4161" },
    });
    for (const payloadBytes of [128 * 1024, 512 * 1024, 16 * 1024 * 1024]) {
      const environment = createEnvironment(db, noopNotifier, {
        providerOwnsPath: false, projectId: project.id, hostId: host.id, status: "destroyed",
      });
      const thread = createThread(db, noopNotifier, {
        projectId: project.id, environmentId: environment.id, providerId: "codex",
      });
      const rowCount = payloadBytes > 1024 * 1024 ? 2 : 50;
      const data = JSON.stringify({ payload: "x".repeat(payloadBytes) });
      db.transaction((tx) => {
        for (let sequence = 1; sequence <= rowCount; sequence++) {
          tx.insert(events).values({
            id: `${payloadBytes}-${sequence}`, threadId: thread.id,
            environmentId: environment.id, scopeKind: "thread", sequence,
            type: "thread/started", data, createdAt: 1,
          }).run();
        }
      });
      measurements.length = 0;
      let immediateRan = false;
      const immediate = new Promise<void>((resolve) => setImmediate(() => { immediateRan = true; resolve(); }));
      const started = performance.now();
      const result = pruneDestroyedEnvironments(db, noopNotifier, {
        updatedBefore: Date.now() + 1000, eventBatchSize: 50, limit: 1,
      });
      const elapsedMs = performance.now() - started;
      expect(immediateRan).toBe(false);
      expect(result).toEqual({ deleted: 0, detachedEvents: 1 });
      await immediate;
      const statements = measurements.filter((m) => m.sql.includes("octet_length") || m.sql.startsWith("UPDATE events"));
      console.log(JSON.stringify({ payloadBytes, rowCount, elapsedMs, immediateDelayed: true, result, statements }));
      const opcodes = db.$client.prepare("EXPLAIN SELECT rowid, octet_length(data) FROM events INDEXED BY events_environment_idx WHERE environment_id = ? ORDER BY rowid LIMIT 50").all(environment.id);
      if (payloadBytes === 128 * 1024) console.log(JSON.stringify({ opcodes }));
      for (let i = 0; i <= rowCount; i++) {
        const progress = pruneDestroyedEnvironments(db, noopNotifier, {
          updatedBefore: Date.now() + 1000, eventBatchSize: 50, limit: 1,
        });
        if (progress.deleted) break;
      }
    }
  } finally {
    db.$client.close();
  }
});

Root cause and limits

The server sweep invokes the database function through runEventLoopWorkSync and yields only after it returns. The transaction selects candidates and updates environment_id within the same synchronous operation. The constants limit candidate count and selected payload bytes, not statement duration. The first row bypasses the byte limit to ensure progress; making the limit smaller cannot bound that row's statement latency. This establishes a mechanism for event-loop delays, but does not identify why the reported installation spends seconds per statement.

The candidate SELECT's EXPLAIN output has Column P5=192. In the lockfile-installed better-sqlite3 dependency, deps/sqlite3/sqlite3.c defines OPFLAG_BYTELENARG as 0xc0 and uses it to avoid loading overflow content for octet_length. It still seeks table records for their headers; cold-page or storage latency remains possible. No claim about the reporter's bundled SQLite version is made. UPDATE still operates on the wide events record (schema); these runs show increasing update time with the oversized stress payload, without proving the reported storage mechanism.

Proposed fix / next experiment

No safe automatic patch. First repeat with a synthetic file-backed multi-GB database, cold-cache conditions, and statement plus checkpoint/lock-wait measurements; compare header reads and row rewrites separately. A JavaScript wall-clock check cannot interrupt an already-running synchronous statement. A worker connection or a different persisted association design requires broader concurrency or data-model decisions and exceeds the simple-fix gate. Do not remove the existing byte bound or replace chunking with a single cascading deletion.

Verification

The same agent repeated the test in second clean checkout B at the same full commit, with a fresh migrated database. Turbo --force ensured the test executed instead of replaying a cached result. Both runs passed one measurement test. Run B measured 0.456, 0.322, and 4.665 ms. The report retains the partial verdict and explicitly corrects the full-payload-scan explanation. This is a second direct run, not independent review.

Related issues and PR check

Issue metadata had no cross-referenced pull request; open-PR search for 4161 returned none. The nearby retention issue #4160 concerns storage cleanup and does not establish this latency mechanism. No linked PR code was executed.

Appendix

The probe uses 50 modest wide rows and two oversized stress rows, not the reported 1.9 million events or 5.2 GB disk database. In-memory timing excludes filesystem, WAL, cold-cache, contention, and long-running production effects; it cannot disprove the reported stalls. Installed-version numbers were treated as untrusted claims, and no external issue links or commands were followed. Initial default-pnpm launcher and first temporary shim attempts failed; Corepack with a corrected shell shim completed both installs, builds, and test runs. Raw measured SQL, durations, and EXPLAIN output are included below; raw local artifacts are not published separately.

Run A raw measurements

{"payloadBytes":131072,"rowCount":50,"elapsedMs":0.6175410000005286,"immediateDelayed":true,"result":{"deleted":0,"detachedEvents":1},"statements":[{"bindingArgumentCount":2,"durationMs":0,"operation":"all","sql":"SELECT rowid, octet_length(data) AS dataBytes FROM events INDEXED BY events_environment_idx WHERE environment_id = ? ORDER BY rowid LIMIT ?","thresholdMs":0},{"bindingArgumentCount":1,"durationMs":0,"operation":"run","sql":"UPDATE events SET environment_id = NULL WHERE rowid IN (?)","thresholdMs":0}]}
{"opcodes":[{"addr":0,"opcode":"Init","p1":0,"p2":18,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":1,"opcode":"Noop","p1":1,"p2":4,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":2,"opcode":"Integer","p1":50,"p2":1,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":3,"opcode":"OpenRead","p1":0,"p2":36,"p3":0,"p4":"11","p5":0,"comment":null},{"addr":4,"opcode":"OpenRead","p1":2,"p2":20,"p3":0,"p4":"k(2,,)","p5":2,"comment":null},{"addr":5,"opcode":"Variable","p1":1,"p2":2,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":6,"opcode":"IsNull","p1":2,"p2":17,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":7,"opcode":"Affinity","p1":2,"p2":1,"p3":0,"p4":"B","p5":0,"comment":null},{"addr":8,"opcode":"SeekGE","p1":2,"p2":17,"p3":2,"p4":"1","p5":0,"comment":null},{"addr":9,"opcode":"IdxGT","p1":2,"p2":17,"p3":2,"p4":"1","p5":0,"comment":null},{"addr":10,"opcode":"DeferredSeek","p1":2,"p2":0,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":11,"opcode":"IdxRowid","p1":2,"p2":3,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":12,"opcode":"Column","p1":0,"p2":10,"p3":5,"p4":"{}","p5":192,"comment":null},{"addr":13,"opcode":"Function","p1":0,"p2":5,"p3":4,"p4":"octet_length(1)","p5":0,"comment":null},{"addr":14,"opcode":"ResultRow","p1":3,"p2":2,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":15,"opcode":"DecrJumpZero","p1":1,"p2":17,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":16,"opcode":"Next","p1":2,"p2":9,"p3":1,"p4":null,"p5":0,"comment":null},{"addr":17,"opcode":"Halt","p1":0,"p2":0,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":18,"opcode":"Transaction","p1":0,"p2":0,"p3":527,"p4":"177","p5":1,"comment":null},{"addr":19,"opcode":"Goto","p1":0,"p2":1,"p3":0,"p4":null,"p5":0,"comment":null}]}
{"payloadBytes":524288,"rowCount":50,"elapsedMs":0.5072500000005675,"immediateDelayed":true,"result":{"deleted":0,"detachedEvents":1},"statements":[{"bindingArgumentCount":2,"durationMs":0,"operation":"all","sql":"SELECT rowid, octet_length(data) AS dataBytes FROM events INDEXED BY events_environment_idx WHERE environment_id = ? ORDER BY rowid LIMIT ?","thresholdMs":0},{"bindingArgumentCount":1,"durationMs":0.2,"operation":"run","sql":"UPDATE events SET environment_id = NULL WHERE rowid IN (?)","thresholdMs":0}]}
{"payloadBytes":16777216,"rowCount":2,"elapsedMs":6.282290999999532,"immediateDelayed":true,"result":{"deleted":0,"detachedEvents":1},"statements":[{"bindingArgumentCount":2,"durationMs":0,"operation":"all","sql":"SELECT rowid, octet_length(data) AS dataBytes FROM events INDEXED BY events_environment_idx WHERE environment_id = ? ORDER BY rowid LIMIT ?","thresholdMs":0},{"bindingArgumentCount":1,"durationMs":5.5,"operation":"run","sql":"UPDATE events SET environment_id = NULL WHERE rowid IN (?)","thresholdMs":0}]}

Run B raw measurements

{"payloadBytes":131072,"rowCount":50,"elapsedMs":0.4562919999999622,"immediateDelayed":true,"result":{"deleted":0,"detachedEvents":1},"statements":[{"bindingArgumentCount":2,"durationMs":0,"operation":"all","sql":"SELECT rowid, octet_length(data) AS dataBytes FROM events INDEXED BY events_environment_idx WHERE environment_id = ? ORDER BY rowid LIMIT ?","thresholdMs":0},{"bindingArgumentCount":1,"durationMs":0,"operation":"run","sql":"UPDATE events SET environment_id = NULL WHERE rowid IN (?)","thresholdMs":0}]}
{"opcodes":[{"addr":0,"opcode":"Init","p1":0,"p2":18,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":1,"opcode":"Noop","p1":1,"p2":4,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":2,"opcode":"Integer","p1":50,"p2":1,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":3,"opcode":"OpenRead","p1":0,"p2":36,"p3":0,"p4":"11","p5":0,"comment":null},{"addr":4,"opcode":"OpenRead","p1":2,"p2":20,"p3":0,"p4":"k(2,,)","p5":2,"comment":null},{"addr":5,"opcode":"Variable","p1":1,"p2":2,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":6,"opcode":"IsNull","p1":2,"p2":17,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":7,"opcode":"Affinity","p1":2,"p2":1,"p3":0,"p4":"B","p5":0,"comment":null},{"addr":8,"opcode":"SeekGE","p1":2,"p2":17,"p3":2,"p4":"1","p5":0,"comment":null},{"addr":9,"opcode":"IdxGT","p1":2,"p2":17,"p3":2,"p4":"1","p5":0,"comment":null},{"addr":10,"opcode":"DeferredSeek","p1":2,"p2":0,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":11,"opcode":"IdxRowid","p1":2,"p2":3,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":12,"opcode":"Column","p1":0,"p2":10,"p3":5,"p4":"{}","p5":192,"comment":null},{"addr":13,"opcode":"Function","p1":0,"p2":5,"p3":4,"p4":"octet_length(1)","p5":0,"comment":null},{"addr":14,"opcode":"ResultRow","p1":3,"p2":2,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":15,"opcode":"DecrJumpZero","p1":1,"p2":17,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":16,"opcode":"Next","p1":2,"p2":9,"p3":1,"p4":null,"p5":0,"comment":null},{"addr":17,"opcode":"Halt","p1":0,"p2":0,"p3":0,"p4":null,"p5":0,"comment":null},{"addr":18,"opcode":"Transaction","p1":0,"p2":0,"p3":527,"p4":"177","p5":1,"comment":null},{"addr":19,"opcode":"Goto","p1":0,"p2":1,"p3":0,"p4":null,"p5":0,"comment":null}]}
{"payloadBytes":524288,"rowCount":50,"elapsedMs":0.3224999999999909,"immediateDelayed":true,"result":{"deleted":0,"detachedEvents":1},"statements":[{"bindingArgumentCount":2,"durationMs":0,"operation":"all","sql":"SELECT rowid, octet_length(data) AS dataBytes FROM events INDEXED BY events_environment_idx WHERE environment_id = ? ORDER BY rowid LIMIT ?","thresholdMs":0},{"bindingArgumentCount":1,"durationMs":0.1,"operation":"run","sql":"UPDATE events SET environment_id = NULL WHERE rowid IN (?)","thresholdMs":0}]}
{"payloadBytes":16777216,"rowCount":2,"elapsedMs":4.664916000000062,"immediateDelayed":true,"result":{"deleted":0,"detachedEvents":1},"statements":[{"bindingArgumentCount":2,"durationMs":0,"operation":"all","sql":"SELECT rowid, octet_length(data) AS dataBytes FROM events INDEXED BY events_environment_idx WHERE environment_id = ? ORDER BY rowid LIMIT ?","thresholdMs":0},{"bindingArgumentCount":1,"durationMs":4,"operation":"run","sql":"UPDATE events SET environment_id = NULL WHERE rowid IN (?)","thresholdMs":0}]}

AGENT GENERATED