Sign up
View stargazersSign up

[Bug]: Starting a turn in a long thread freezes the server for 0.3–0.4 s (0.03–0.05 s with one index)#21578

opened15d agobyBbompus

Before submitting

  • I searched existing issues and did not find a duplicate.
  • I included enough detail to reproduce or investigate the problem.

Area

apps/server

Steps to reproduce

  1. Use a thread with a long history, about 14,000 or more turn items (a few weeks of daily agent work in one thread).
  2. Send a message in it so a turn starts.
  3. Meanwhile, watch the server's responsiveness: time any request to it, use the browser preview with control taken, or read the server trace (server.trace.ndjson).

Expected behavior

Starting a turn should not hold the server's main thread for long enough that other clients, other threads or the browser preview notice.

Actual behavior

Every turn start blocks the server's main thread for 314–368 ms. During that time no request is answered: typing, clicks and scrolling in the browser preview wait, and so does every other client connected to the server.

The time goes to four calls of ProjectionStore.getRuntimeRecoveryProjection (ProviderTurnStartService.ts lines 136, 145, 159 and 503). Its queries look up the thread's unfinished turn items (status IN ('pending', 'running', 'waiting')) without a filter on type. The existing partial indexes all filter on type, so the lookups read every turn item the thread has ever had. Since #21122 the server clears planner statistics on purpose and relies on indexes, so this lookup needs an index that fits it.

Impact

Minor bug or occasional failure

Version or commit

v0.1.1-nightly.20261018.3335; the code is unchanged on main @ 1451e7cb23

Environment

Windows desktop app with the WSL server, Node 26.12.0, a 15.8 GB state database

Logs or stack traces

shell
1# Live server, idle browser preview. A request every 50 ms timed the server's
2# event loop; every stall over 300 ms lined up with a turn start, and the trace
3# spans inside each one add up to it.
4stall 363–445 ms: 4x getRuntimeRecoveryProjection (runs, nodes, provider threads, turn items queries)
5
6# The real ProjectionStore.getRuntimeRecoveryProjection called 4 times, as one
7# turn start does, on a copy of that database (no planner statistics, warm cache,
8# median of 5 rounds; longest event-loop gap from perf_hooks.monitorEventLoopDelay)
9thread turn items wall time longest event-loop gap
1017,517 367.5 ms 369.1 ms
1113,885 313.9 ms 315.4 ms
1213,699 330.0 ms 331.4 ms

Screenshots, recordings, or supporting files

No response

Workaround

None applied. A fix exists on a branch: https://github.com/bompus/t3code/pull/14 adds a partial index on unfinished turn items of any type (migration 065), which brings the same four calls to 30–45 ms with the longest gap at 31–46 ms. The index is about 340 KB on this database and builds in under 1 s warm (7.3 s cold). I can open the pull request against pingdotgg/t3code once triage confirms the direction.

JJulius Marminge15d ago

Note

Grok responding on behalf of Julius.

Confirmed on main, so this is accepted as a performance bug.

One turn start calls getRuntimeRecoveryProjection four times (ProviderTurnStartService.ts:136, 145, 159 and 503). Two of its turn item lookups filter only on thread and status, with no type filter (ProjectionStore.ts:4274-4287 and 4324-4326). The partial indexes on turn items are all limited by type (RecoveryIndexes.ts:25-29, ShellIndexes.ts:13-17, 060_ThreadSnapshotWindowIndexes.ts:9-12, 062_ThreadFailureLookupIndex.ts:8-12). These lookups can therefore only use the plain thread indexes, which cover every turn item the thread has ever had. Since #21122 the server clears planner statistics on open (Sqlite.ts:46-49), so the right index matters more.

#20302 proposed the same index and was closed without an in-app measurement. Open #21193 adds long-thread indexes, but none for this lookup.

DDropje975d ago
Synced from GitHub

Two more turn-start scans on long threads, on 0.1.3-nightly.20261027.3754, separate from the unfinished-items index in #23557.

On a thread with 2,223 runs and 19,056 turn items, getTurnStartContext took 4.2-4.8 s.

  1. This run's turn items, 2.2-2.8 s. SELECT payload_json FROM orchestration_v2_projection_turn_items WHERE thread_id = ? AND run_id = ? ORDER BY ordinal ASC, turn_item_id ASC returns 9 rows. To avoid the sort, it uses turn_items_thread_ordinal_idx and walks all 19k items of the thread. With INDEXED BY orchestration_v2_projection_turn_items_run_ordinal_idx it takes 0.1 ms and returns the same rows.

  2. /compact messages, 686 ms. In the messages query, the branch OR (role = 'user' AND lower(trim(json_extract(payload_json, '$.text'), ?)) = '/compact') parses every user message of the thread. We changed it to:

    • a rowid UNION, with the run's prompt message looked up by key;
    • the /compact messages through an expression index on (thread_id, lower(trim(json_extract(payload_json, '$.text'), char(...)))) with WHERE role = 'user', and the same char(...) list in the query instead of the bound trim set.

    The query now takes 0.7 ms. Building the index took 12-17 s on our 22 GB database (21k user messages).

Still slow: the rest of getTurnStartContext reads all runs, attempts and provider turns of the thread, about 1.2 s on this thread.

Equivalence: on a block clone, a harness running the real ProjectionStore code before and after the change returned identical results for 407 getTurnStartContext calls. That covers up to four runs on each of 208 threads, including all 19 threads with /compact messages.

Production: we run these changes in a local build. Compared with the 85 minutes before deploying, the hour after shows:

  • turn-start statements of 250 ms or more: from 98.6 s (117 statements) to 7.9 s (28 statements);
  • the long thread's median time from run request to run start: from 8.1 s to 2.4 s.

Measured and written by Claude (Opus 5.5) in T3 Code, reviewed by Codex (gpt-6.1-sol); posted with the owner's approval.