#4163 · Async-frame blocking time is omitted from stall attribution

Bug · Priority: Medium · Effort: Medium · host, plugins, perf · 2026-09-23

Issue · Base 94d77da09568d7f0f7cdb23b84686e743acfb0ad

REPRODUCED · Root-cause confidence: high · confirmed-repro

1. TL;DR

The stall monitor detects a blocked event loop but cannot name blocking work executed inside an async tracking frame. Two real-timer runs each detected approximately 650 ms stalls while returning null for slowestWork. The same blocking operation inside the synchronous wrapper was attributed correctly. A wait-only control did not produce a stall. This confirms the attribution gap, without validating the reporter’s private host statistics or SQLite workload.

2. Claims vs findings

3. Environment

Trusted origin/main at the commit above; macOS Darwin arm64; Node v22.22.3; pnpm 9.15.0 through Corepack. A second clean detached worktree used the same commit and its own frozen install. Both Turbo builds completed: 60 successful tasks. No providers, application instance, listening ports, database, or user runtime data were used.

The host’s pnpm launcher initially pointed to a missing module. A temporary command shim invoking corepack pnpm resolved the tooling failure; repository source was unchanged.

4. Minimal reproduction

1. Use a clean checkout of get-bb/bb at 94d77da09568d7f0f7cdb23b84686e743acfb0ad.
2. Run corepack pnpm install --frozen-lockfile --prefer-offline and corepack pnpm exec turbo run build with a working pnpm launcher on PATH.
3. Save attribution.ts as issue-4163-repro.ts in the repository root.
4. Run node --conditions=source --import tsx issue-4163-repro.ts. The script takes about 24 seconds and exits 1 on the trusted base.

Expected: all three blocking cases name their own frame in slowestWork, and the wait-only case logs no stall. Actual: the synchronous control and wait-only control pass; both async blocking assertions fail because slowestWork is null. The test uses real performance.now(), real event-loop delay sampling, and a 650 ms busy loop. It directly calls the same work wrapper used by plugin invocation, without loading a third-party plugin.

{"mode":"sync","records":[{"intervalMs":5000,"maxDelayMs":656.9,"meanDelayMs":24.6,"p99DelayMs":22.6,"resolutionMs":20,"thresholdMs":500,"currentWork":null,"lastWork":"plugin:probe sync","lastWorkMs":650.2,"slowestWork":"plugin:probe sync","slowestWorkMs":650.2}]}
PASS sync
{"mode":"async-initial","records":[{"intervalMs":5000,"maxDelayMs":659.6,"meanDelayMs":24.8,"p99DelayMs":22.1,"resolutionMs":20,"thresholdMs":500,"currentWork":null,"lastWork":"plugin:probe async-initial","lastWorkMs":650.1,"slowestWork":null,"slowestWorkMs":null}]}
FAIL async-initial: Expected values to be strictly equal:
+ actual - expected

+ null
- 'plugin:probe async-initial'

{"mode":"async-continuation","records":[{"intervalMs":5000,"maxDelayMs":654.3,"meanDelayMs":24.7,"p99DelayMs":22.1,"resolutionMs":20,"thresholdMs":500,"currentWork":null,"lastWork":"plugin:probe async-continuation","lastWorkMs":661.8,"slowestWork":null,"slowestWorkMs":null}]}
FAIL async-continuation: Expected values to be strictly equal:
+ actual - expected

+ null
- 'plugin:probe async-continuation'

{"mode":"await-only","records":[]}
PASS await-only
Attribution failures: 2

import assert from "node:assert/strict";
import { performance } from "node:perf_hooks";
import { setTimeout as delay } from "node:timers/promises";
import { runEventLoopWork, runEventLoopWorkSync, resetEventLoopWorkForTests, takeEventLoopWorkWindowSnapshot } from "./apps/server/src/services/system/event-loop-work.ts";
import { startEventLoopStallMonitor } from "./apps/server/src/services/system/event-loop-stall-monitor.ts";

function block() {
  const until = performance.now() + 650;
  while (performance.now() < until) {}
}

let failures = 0;
for (const mode of ["sync", "async-initial", "async-continuation", "await-only"]) {
  resetEventLoopWorkForTests();
  const records: Record<string, unknown>[] = [];
  const monitor = startEventLoopStallMonitor({ logger: { info: (fields) => { records.push(fields); } } });
  await delay(50);
  const label = `plugin:probe ${mode}`;
  if (mode === "sync") runEventLoopWorkSync(label, block);
  if (mode === "async-initial") await runEventLoopWork(label, async () => { block(); });
  if (mode === "async-continuation") await runEventLoopWork(label, async () => { await delay(10); block(); });
  if (mode === "await-only") await runEventLoopWork(label, () => delay(650));
  await delay(5100);
  monitor.stop();
  const record = records[0];
  console.log(JSON.stringify({ mode, records }));
  try {
    if (mode === "await-only") {
      assert.equal(records.length, 0);
      assert.equal(takeEventLoopWorkWindowSnapshot().slowestWork, null);
    } else {
      assert.ok(record);
      assert.equal(record.slowestWork, label);
    }
    console.log(`PASS ${mode}`);
  } catch (error) {
    failures++;
    console.log(`FAIL ${mode}: ${error instanceof Error ? error.message : String(error)}`);
  }
}
console.log(`Attribution failures: ${failures}`);
process.exitCode = failures ? 1 : 0;

5. Root cause

Async work frames always set blocksEventLoop=false, so their synchronous execution is excluded from slowestWork selection. Async wrapper passes false unconditionally, and selection discards such frames. Completion records measure elapsed duration, without separating callback execution from async waiting. Plugin invocation calls this async wrapper. The monitor attaches its snapshot to actual delay samples.

const id = enterEventLoopWork(label, false);
...
if (!completed.blocksEventLoop) {
  continue;
}

The reproduction’s frames finish before sampling, so currentWork is null and lastWork still identifies the finished operation. This does not imply every real plugin frame remains in flight during logging. The schedule loop awaits each invocation, which explains ordering but is a separate scheduling concern.

6. Proposed fix and simple-fix decision

Record measured synchronous segments while preserving the existing distinction between waiting and blocking. Merely setting async frames to blocking would falsely blame I/O waits; timing only the initial callback would still fail the continuation case. A complete solution needs a decision between explicit instrumentation of synchronous operations and async execution instrumentation, including nesting, concurrency, and overhead. The current wrapper has no hook around arbitrary plugin continuations after awaits.

No production fix or PR was attempted: the instrumentation design decision fails the rule’s simple-fix criteria. No dependencies or production source were changed. Next experiment: prototype segment attribution and benchmark overhead while testing unrelated overlapping waits and nested async callbacks.

7. Related issues and PR check

#3196 concerns synchronous database stalls, a related performance symptom. No open PR was found in the issue’s cross-reference metadata or open-PR search for 4163. No linked PR code was executed.

8. Verification

The same agent repeated the test in a second clean detached checkout at the recorded base, with a separate frozen dependency install and successful Turbo build. Command: node --conditions=source --import tsx issue-4163-repro.ts. Result: exit 1, the same two null-attribution failures, and both controls passing. No report correction was required. A final fetch found no later change to the relevant tracking or invocation files.

{"mode":"sync","records":[{"intervalMs":5000,"maxDelayMs":658.5,"meanDelayMs":24.7,"p99DelayMs":22.1,"resolutionMs":20,"thresholdMs":500,"currentWork":null,"lastWork":"plugin:probe sync","lastWorkMs":650.3,"slowestWork":"plugin:probe sync","slowestWorkMs":650.3}]}
PASS sync
{"mode":"async-initial","records":[{"intervalMs":5000,"maxDelayMs":663.2,"meanDelayMs":24.7,"p99DelayMs":22.1,"resolutionMs":20,"thresholdMs":500,"currentWork":null,"lastWork":"plugin:probe async-initial","lastWorkMs":650.2,"slowestWork":null,"slowestWorkMs":null}]}
FAIL async-initial: Expected values to be strictly equal:
+ actual - expected

+ null
- 'plugin:probe async-initial'

{"mode":"async-continuation","records":[{"intervalMs":5000,"maxDelayMs":652.7,"meanDelayMs":24.6,"p99DelayMs":22.1,"resolutionMs":20,"thresholdMs":500,"currentWork":null,"lastWork":"plugin:probe async-continuation","lastWorkMs":662,"slowestWork":null,"slowestWorkMs":null}]}
FAIL async-continuation: Expected values to be strictly equal:
+ actual - expected

+ null
- 'plugin:probe async-continuation'

{"mode":"await-only","records":[]}
PASS await-only
Attribution failures: 2

9. Appendix

Existing regression suite: pnpm exec turbo run test --filter=@bb/server -- test/system/event-loop-stall-monitor.test.ts passed all 9 tests (1 test file). The reproduction failures therefore expose missing coverage rather than a failing existing test.

Artifacts: first run, second run, reproduction source. Investigation also read the current classification, valid property options, labels, related-issue metadata, source and source history, and PR cross-references. Issue content was treated only as untrusted claims; no supplied external links or code were fetched or executed.

AGENT GENERATED