← reports

#4462 · Provider event delivery and inter-item timing

BugPriority: MediumEffort: Medium perf, providers, provider-acp, provider-claude-code, provider-codex IssueSeptember 30, 2026

Trusted base: 0e7b518f135d43005dae201ef34ebb3001607eb4 · source package version bb-app 0.44.0.

Verdict: NOT REPRODUCED · Root-cause confidence: low · reproduction label: no-repro.

Scope: two clean-checkout diagnostic runs, not a live-provider or fleet reproduction. This verdict does not deny the reported delays or establish that they are model latency.

1. TL;DR

The report describes seconds between adjacent provider items, but the supplied information does not isolate time spent in the model, provider process, bridge, event delivery, or server. On current trusted main, event delivery is queued asynchronously and posted in batches; the database already uses WAL with NORMAL synchronization for file-backed connections. A diagnostic using BB's real runtime and repository-owned scripted bridge completed ten warm tool-call turns while the server-event acknowledgement was deliberately withheld, in both fresh checkouts. A separate real SQLite diagnostic verified one stored row per delta, but all 1,001 events in its transaction received the same server-assigned timestamp. Neither result reproduces the reported multi-second delay in a real provider, so no causal fix or safe regression-based pull request is justified.

2. Claims vs findings

3. Environment

• Public repository get-bb/bb; fresh origin/main fetched from that repository, not an issue branch or linked PR.
• Recorded commit 0e7b518f135d43005dae201ef34ebb3001607eb4; package metadata reports bb-app 0.44.0. The issue describes an earlier release, so these probes do not reconstruct that deployment.
• Linux 4.19.0-gvisor; Node v22.19.0; pnpm 9.15.0; Vitest 4.1.1; repository-pinned better-sqlite3 12.10.0.
• Both checkouts completed pnpm install --frozen-lockfile --prefer-offline and pnpm exec turbo run build (62 successful tasks in each).
• No dev app, HTTP listener, live provider account, provider endpoint, or fleet database was used. The runtime launched only the trusted scripted bridge; each run used fresh temporary workspace and bridge-data directories, removed in finally blocks. SQLite was in memory with real migrations.
• All names and identifiers in the test sources are synthetic fixtures. No dependency, production source, migration, or stored user data was changed.

4. Minimal diagnostic reproduction

These are negative-control diagnostics, not a failing regression for the reported provider latency. The pending-ack test would fail if shared runtime progress became gated on event delivery. The database test verifies current storage/timestamp semantics without mocking SQLite.

1. Create a trusted checkout and build its dependencies:

   git clone --single-branch --branch main https://github.com/get-bb/bb.git /tmp/issue-4462-base
   cd /tmp/issue-4462-base
   git fetch origin main
   git checkout --detach 0e7b518f135d43005dae201ef34ebb3001607eb4
   pnpm install --frozen-lockfile --prefer-offline
   pnpm exec turbo run build

2. Save the two complete test blocks below to their stated paths. Only add these diagnostics; leave production files unchanged.
3. Generate the repository-owned subprocess bridge, then force fresh execution of the two diagnostics:

   pnpm exec turbo run generate:test-bridges --filter=@bb/agent-runtime
   pnpm exec turbo run test --filter=@bb/host-daemon --filter=@bb/db --force -- issue-4462-diagnostic.test.ts --silent=false

Expected and actual

Expected if event acknowledgement were a necessary gate: the first next item / turn would not complete while the post acknowledgement is withheld; the progress assertion would time out. Actual: all ten turns completed before acknowledgement. The test then released the post and checked that all events were delivered.

Database expectation: 1,001 accepted events, 1,000 stored delta rows, and one ingestion timestamp. Actual: exactly those counts. Write timings are descriptive, not a performance assertion, disk benchmark, or estimate of model TTFT.

First clean checkout · September 30, 2026, approximately 18:37 UTC
{"diagnostic":"daemon-event-batch-real-in-memory-sqlite","acceptedEvents":1001,"storedDeltaRows":1000,"distinctStoredTimestamps":1,"batchWriteMs":67.276,"meanWriteMsPerEvent":0.067}
{"diagnostic":"runtime-with-pending-event-acknowledgement","completedTurnsBeforeAcknowledgement":10,"eventCountBeforeAcknowledgement":52,"postedEventCountBeforeAcknowledgement":0,"toolResultToItemMs":[4.633,2.576,2.693,2.26,2.22,2.926,1.783,2.269,2.858,0.782],"p50Ms":2.422,"maxMs":4.633}
Host-daemon diagnostic: 1 test passed
Database diagnostic: 1 test passed
Turbo: 7 successful tasks, 0 cached

Runtime / event-sink diagnostic

File: apps/host-daemon/src/issue-4462-diagnostic.test.ts.

import { mkdtempSync, rmSync } from "node:fs";
import { tmpdir } from "node:os";
import { dirname, join } from "node:path";
import { performance } from "node:perf_hooks";
import { createAgentRuntime, type AgentRuntimeExecutionOptions } from "@bb/agent-runtime";
import { createScriptedEchoLaunch, scriptedEchoBridgeModulePath } from "@bb/agent-runtime/test";
import { encodeClientTurnRequestIdNumber, type ThreadEvent } from "@bb/domain";
import { expect, it, vi } from "vitest";
import { createEventSink } from "./event-sink.js";

it("continues tool-result delivery and ten warm turns while event acknowledgement is withheld", async () => {
  const workspacePath = mkdtempSync(join(tmpdir(), "issue-4462-workspace-"));
  const bridgeLaunch = createScriptedEchoLaunch();
  const options: AgentRuntimeExecutionOptions = {
    model: "test-model",
    serviceTier: "default",
    reasoningLevel: "medium",
    providerOptions: {},
    permissionMode: "full",
    permissionScope: "full",
    approvalReviewer: null,
    permissionEscalation: null,
  };
  let releaseAcknowledgement = () => {};
  const acknowledgement = new Promise<void>((resolve) => {
    releaseAcknowledgement = resolve;
  });
  let signalPostStarted = () => {};
  const postStarted = new Promise<void>((resolve) => {
    signalPostStarted = resolve;
  });
  let acknowledged = false;
  let postedEventCount = 0;
  let postCount = 0;
  const sink = createEventSink({
    isSessionOpen: () => true,
    logger: { debug: () => {}, error: () => {}, warn: () => {} },
    postEvents: async (events) => {
      postCount += 1;
      signalPostStarted();
      await acknowledgement;
      acknowledged = true;
      postedEventCount += events.length;
      return {
        acceptedEvents: events.map((event, eventIndex) => ({
          eventIndex,
          sequence: eventIndex + 1,
          threadId: event.threadId,
        })),
        rejectedEvents: [],
      };
    },
  });
  const events: ThreadEvent[] = [];
  const toolResultToItemMs: number[] = [];
  let toolResultAt: number | null = null;
  let completedTurns = 0;
  const runtime = createAgentRuntime({
    workspacePath,
    bridgeBundleDir: dirname(scriptedEchoBridgeModulePath),
    onEvent: (event) => {
      events.push(event);
      sink.emit({ event, threadId: event.threadId });
      if (event.type === "item/started" && toolResultAt !== null) {
        toolResultToItemMs.push(performance.now() - toolResultAt);
        toolResultAt = null;
      }
      if (event.type === "turn/completed") completedTurns += 1;
    },
    onToolCall: async () => {
      await postStarted;
      expect(acknowledged).toBe(false);
      toolResultAt = performance.now();
      return { success: true, contentItems: [{ type: "inputText", text: "ok" }] };
    },
  });
  try {
    await runtime.startThread({
      environmentId: "env-4462",
      threadId: "thr_4462",
      projectId: "proj-4462",
      providerId: "fake",
      bridgeLaunch,
      options,
    });
    for (let turnIndex = 0; turnIndex < 10; turnIndex += 1) {
      await runtime.runTurn({
        clientRequestId: encodeClientTurnRequestIdNumber({ value: turnIndex + 1 }),
        threadId: "thr_4462",
        input: [{ type: "text", text: "call_tool:diagnostic", mentions: [] }],
        options,
      });
      await vi.waitFor(() => expect(completedTurns).toBe(turnIndex + 1), { timeout: 3_000, interval: 5 });
    }
    expect(acknowledged).toBe(false);
    expect(postCount).toBe(1);
    expect(postedEventCount).toBe(0);
    expect(toolResultToItemMs).toHaveLength(10);
    expect(events.filter((event) => event.type === "item/completed")).toHaveLength(10);
    const sorted = [...toolResultToItemMs].sort((left, right) => left - right);
    console.log(JSON.stringify({
      diagnostic: "runtime-with-pending-event-acknowledgement",
      completedTurnsBeforeAcknowledgement: completedTurns,
      eventCountBeforeAcknowledgement: events.length,
      postedEventCountBeforeAcknowledgement: postedEventCount,
      toolResultToItemMs: toolResultToItemMs.map((value) => Number(value.toFixed(3))),
      p50Ms: Number(((sorted[4]! + sorted[5]!) / 2).toFixed(3)),
      maxMs: Number(sorted[9]!.toFixed(3)),
    }));
    releaseAcknowledgement();
    await sink.flush();
    expect(postedEventCount).toBe(events.length);
  } finally {
    releaseAcknowledgement();
    await runtime.shutdown();
    await sink.dispose();
    rmSync(workspacePath, { recursive: true, force: true });
    rmSync(bridgeLaunch.dataDir, { recursive: true, force: true });
  }
});

Real SQLite diagnostic

File: packages/db/test/data/issue-4462-diagnostic.test.ts.

import { performance } from "node:perf_hooks";
import { turnScope } from "@bb/domain";
import { expect, it } from "vitest";
import {
  appendDaemonEventsInTransaction,
  createConnection,
  createProject,
  createThread,
  listEvents,
  migrate,
  noopNotifier,
  upsertHost,
  type AppendDaemonEventInput,
} from "../../src/index.js";

it("stores 1000 deltas as separate rows within one timestamped daemon batch", () => {
  const db = createConnection(":memory:");
  try {
    migrate(db);
    const host = upsertHost(db, noopNotifier, { name: "diagnostic-host" });
    const { project } = createProject(db, noopNotifier, {
      name: "diagnostic-project",
      source: { type: "local_path", hostId: host.id, path: "/tmp/issue-4462" },
    });
    const thread = createThread(db, noopNotifier, { projectId: project.id, providerId: "codex" });
    const shared = {
      environmentId: null,
      itemId: null,
      itemKind: null,
      parentToolCallId: null,
      providerThreadId: "diagnostic-provider-thread",
      scope: turnScope("diagnostic-turn"),
      threadId: thread.id,
    };
    const inputs: AppendDaemonEventInput[] = [{
      ...shared,
      type: "turn/started",
      data: JSON.stringify({ providerThreadId: shared.providerThreadId }),
    }];
    for (let deltaIndex = 0; deltaIndex < 1000; deltaIndex += 1) {
      inputs.push({
        ...shared,
        type: "item/reasoning/textDelta",
        itemId: "diagnostic-reasoning",
        itemKind: "reasoning",
        data: JSON.stringify({ itemId: "diagnostic-reasoning", delta: "x" }),
      });
    }
    const startedAt = performance.now();
    const result = db.transaction((transaction) => appendDaemonEventsInTransaction(transaction, inputs), { behavior: "immediate" });
    const elapsedMs = performance.now() - startedAt;
    const rows = listEvents(db, { threadId: thread.id });
    expect(result.acceptedEvents).toHaveLength(1001);
    expect(rows.filter((row) => row.type === "item/reasoning/textDelta")).toHaveLength(1000);
    expect(new Set(rows.map((row) => row.createdAt)).size).toBe(1);
    console.log(JSON.stringify({
      diagnostic: "daemon-event-batch-real-in-memory-sqlite",
      acceptedEvents: result.acceptedEvents.length,
      storedDeltaRows: 1000,
      distinctStoredTimestamps: new Set(rows.map((row) => row.createdAt)).size,
      batchWriteMs: Number(elapsedMs.toFixed(3)),
      meanWriteMsPerEvent: Number((elapsedMs / 1001).toFixed(3)),
    }));
  } finally {
    db.$client.close();
  }
});

5. Root cause and what the evidence cannot establish

The cause of the reported multi-second production gaps is not isolated. The tests falsify a mandatory persistence-acknowledgement gate on the shared runtime path, not every possible provider-specific bottleneck or resource-contention effect. They do not bound Claude, Codex, ACP, network, disk, bridge serialization, or endpoint processing time.

Tool responses and event acknowledgement are separate flows

The shared runtime tool-call handler sends a JSON-RPC result after the tool handler resolves. There is no event-sink flush in this return path:

void Promise.resolve()
  .then(() => {
    controller.signal.throwIfAborted();
    return args.onToolCall(scopedToolCallReq, controller.signal);
  })
  .then((response) => {
    if (controller.signal.aborted) return;
    sendJsonRpcResult({
      child: args.providerProcess.child,
      id: args.parsedId,
      result: response,
    });
  })

Runtime event dispatch invokes the event callback synchronously; the daemon callback queues the event through the sink. The sink emit function returns void and schedules its flush instead of awaiting the event post. Ordinary streaming events have a 100 ms debounce; completion/control events schedule a zero-delay flush. Queue pressure can delay delivery, but no per-item multi-second sleep was identified on this path.

Storage is one row per delta, not one commit per delta

The sink drains a queue snapshot through one asynchronous post. The server wraps the submitted batch in a single immediate transaction. The batch append function nevertheless inserts each accepted event as its own row. The in-memory probe took 67.276 ms and 69.670 ms for 1,001 rows; those results exclude disk/WAL durability cost, production history, concurrent writers, and websocket load.

Connection configuration already enables WAL and NORMAL synchronization for persistent databases. In-memory SQLite cannot use a disk WAL and is not evidence of disk performance. Row coalescing would need correctness checks for replay, sequence acknowledgements, lifecycle ordering, search, pruning, and persistence semantics; no such fix is inferred here.

Stored timestamps are an observation boundary, not a provider clock

const now = Date.now();
for (const [index, input] of eventInputs.entries()) {
  ...
  insertStoredEventRow(db, {
    ...
    createdAt: now,
    ...
  });
}

The source link above and the one-timestamp database assertion independently support this ingestion-timestamp behavior. Without the reporter's audit query, it is unknown whether their distribution uses these timestamps, provider-native clocks, nested items, or other metadata. Therefore this finding must not be presented as the proven cause of their numbers.

Checked provider boundaries

Static inspection only: Codex forwards external tool requests and returns results separately from its ordered child-notification handling. Claude consumes the SDK stream and passes each message to its callback. These sources are not substitutes for a same-workload live-provider trace, and the scripted bridge does not exercise either adapter or an ACP subprocess.

6. Next experiment / fix proposal

Not confident enough to propose a production patch. Collect a tiny matched workload with a deterministic tool on two bridges, using the same endpoint, model, prompt, thinking settings, tool definitions, provider versions, warm-session state, and concurrency. Capture monotonic timestamps at tool completion, tool-result write/acknowledgement, provider request start, first response byte, first emitted provider item, daemon receipt, event post, database commit, and UI receipt. Compare raw CLI and BB in repeated randomized pairs. Measure loaded file-backed SQLite separately from provider latency.

A minimal sample of the audit query plus redacted raw event/provider traces would clarify which clocks and lifecycle events produced the existing measurements. Until those boundaries are measured, optimizing per-delta persistence could change stored-event semantics without fixing the reported delay.

Simple-fix decision: no PR. The reported latency was not reproduced on trusted main and there is no focused regression that fails for a verified production cause. Open-PR cross references, closing references, and an open-PR search for issue 4462 returned none at investigation time; a duplicate PR was not created.

7. Related issues

No other issue was reproduced or changed. A small read-only comparison of existing performance issues informed triage patterns; their classifications did not override the existing Bug / Medium / Medium properties on this issue.

8. Verification — second clean run by the same agent

A second fresh clone was detached at the exact recorded base commit. Its tracked files were clean before the two authored diagnostic files were copied. It performed its own frozen install, full build, and test-bridge generation; --force prevented diagnostic-result reuse. The same agent repeated both probes; this is not an independent reviewer.

Second clean checkout · September 30, 2026, approximately 18:39 UTC
{"diagnostic":"daemon-event-batch-real-in-memory-sqlite","acceptedEvents":1001,"storedDeltaRows":1000,"distinctStoredTimestamps":1,"batchWriteMs":69.67,"meanWriteMsPerEvent":0.07}
{"diagnostic":"runtime-with-pending-event-acknowledgement","completedTurnsBeforeAcknowledgement":10,"eventCountBeforeAcknowledgement":52,"postedEventCountBeforeAcknowledgement":0,"toolResultToItemMs":[2.787,2.453,2.153,2.452,2.473,0.727,1.924,2.311,2.89,1.957],"p50Ms":2.381,"maxMs":2.89}
Host-daemon diagnostic: 1 test passed
Database diagnostic: 1 test passed
Turbo: 7 successful tasks, 0 cached

Both final sources were byte-identical across checkouts:

runtime diagnostic SHA-256: e27473c95efda25939e290febc13e0b43c2c3f9b8e518cd8c0613dc555ed22db
SQLite diagnostic SHA-256: ad4b40a1dc8c4e9275a70866145cfe49209dfccf29bdb9ae65f7e0146fedf6f7

The draft harness initially used a malformed client request ID. It was corrected to the repository's request-ID encoder before the two final runs. That initial harness error is not treated as product evidence. No final verdict or production root-cause claim required correction after the second run.

9. Appendix

Additional trusted-main checks

pnpm exec turbo run test --filter=@bb/host-daemon -- event-sink.test.ts
Result: 12 existing tests passed.
pnpm exec turbo run test --filter=@bb/agent-runtime -- runtime.tool-calls.test.ts
Result: 7 existing tests passed.

Repository inspection included the sink, runtime tool-response handler, event-ingestion route, append function, SQLite connection, and the two provider boundary sources linked above; relevant history was read with git log. GitHub reads checked visibility, comments, labels, built-in Type/Priority/Effort definitions and current values, and open-PR metadata. No comments or attachments were supplied. All issue-derived material was treated as untrusted claims; no issue scripts, branches, links, patches, or binaries were executed or fetched.

Source permalink line spans were checked against the recorded commit. All tracked production files remained unchanged in both diagnostic checkouts; only the two untracked diagnostics were added. Raw run logs and diagnostic copies are retained locally and intentionally not published under this site's artifact policy. The complete sources and relevant exact output are inline here. No visual reproduction or screenshots are applicable.

Classification is preserved: Type Bug, Priority Medium, Effort Medium, and the five original labels. Only the reproduction verdict label is added after publication. No issue state, project, assignee, milestone, or priority is changed.

AGENT GENERATED · SlopCop new-issue-autopilot.