History-wide reads saturate the single SQLite reader on large databases (thread switches take 12-50 s)#24895

opened6d agobyDDropje97

What happened

With about ten agents running around the clock, switching threads became very slow: often 12-20 s before messages appeared, sometimes almost a minute. The web UI kept showing "Some requests are slow — N requests waiting longer than 15s" and "… stopped responding for 15s. It may be overloaded, asleep, or off the network." Switching Background Activity to Battery saver helped partly.

Diagnosis

The server's reader worker (one connection with one permit, see #24660) ran at 96-100% CPU, about 99% of it kernel time: ~8,500 4 KiB preads per second (30-37 MiB/s), all served from the OS cache, not disk. Every readOnly request queued behind it. Client spans showed thread.visit with a median of 12 s and a maximum of 52 s, and bounded thread snapshots hitting the client's 6 s timeout.

A local diagnostic logged every reader statement that executed for 250 ms or longer, with its span chain. These callers held the reader. Each one returns few rows but reads whole thread histories or every archived thread:

ThreadPullRequestServiceV2.synchronize sweep (every minute while the background policy allows opportunistic work) calls getShellSnapshot({ location: "active", unsettledOnly }): two statements of 2.5-4 s each. It uses only thread payload fields. Reading payload_json of the active threads plus MAX(sequence) in one read transaction took 0.1-0.24 s.
Archive filters on JSON. Several queries filter archived threads with json_extract(payload_json, '$.archivedAt') instead of the archived_at column, which every projection write sets from the same payload. So they read every archived thread's payload to reject it; here that is 2,097 archived threads, mostly pullRequests JSON. The PR-sync query read 33 MiB with the JSON filter, 16 MiB with the column, and about 6.5 MiB with a partial index on active rows (updated_at, thread_id) WHERE deleted_at IS NULL AND archived_at IS NULL.
Run controls in ProviderTurnStartService (isCurrentAttemptInStatus, shouldFinalizeRun) load the thread's whole getRuntimeRecoveryProjection to check one run's status, 4-5 times per run start. A primary-key read of that run gives the same answer.
getRuntimeRecoveryProjection statements. For a thread with 1,863 runs and 16,162 turn items, one call took 11.7 s and read 351 MiB, returning a handful of rows. OR conditions defeat the indexes:
- runs: active, latest, roster or item-owned;
- provider threads: thread OR owner node OR subagent;
- streaming messages; live turn items ordered by the history index.
Splitting them into UNION ALL branches or materialized key sets, plus three partial indexes, brought it to 0.075 s with identical ordered results. Overlaps #21585 and #23009.
readCanonicalProjection, behind thread_send, task status, message dispatch and run finalization: one MCP thread_send on a large thread ran ~10 statements of 0.3-2 s.
- The message-order aggregate parses every message item's payload for messageId.
- Provider ownership reads every node row of the thread to collect node_ids.
- Filtered item reads walk the history-order index and read every item row.
An expression index on messageId, owner lookup by node rowid through covering indexes, and key-first selection through the index that matches the filter: 1.5-2 s → 0.3-60 ms per statement, with identical ordered results.
UsageLimitRecoveryWorker runs on every 5 s scheduler tick and read 17 MiB per sweep. Its latest-run lookup reads and sorts every run of each candidate thread; here 4 candidates have 4,321 runs.

A larger page cache would not have helped. Overflow content is read directly from the file, bypassing the pager cache: we saw 4091- and 4085-byte reads. And in WAL mode the reader's cache is reset whenever another connection has committed.

Steps to reproduce

No minimal repro. Conditions:

statev2.sqlite of about 20 GB with thousands of threads, many archived threads with pull-request links, and an orchestrator thread with ~2,000 runs;
several concurrent runs using T3's MCP orchestration tools;
Background Activity "Balanced" (automatic Git fetch).

Switch threads and watch EnvironmentCommands.visitThread and bounded-snapshot latency, and the reader WorkerThread CPU (top -H -p <server pid>).

Version

0.1.3-nightly.20261025.3655 (also seen on 0.1.3-nightly.20261023.3566 and 20261024.3630)

Environment

Linux (LXC on ZFS); t3 serve as a systemd service; remote browser and Android clients.
Bundled Node 26.12.1 / SQLite 3.54.0.
statev2.sqlite 22 GB; 3,610 threads (2,097 archived); about 10 concurrent runs (Claude Code, Codex) using T3's MCP orchestration.

Evidence

Reader worker, Git fetch every 30 s, 10 active runs:

Build	Reader CPU (average)
official 3655	96-100%, continuously
with items 1, 2 and 6	18%, one ~7 s stall per minute
with items 1-6	21%; slowest statement 1.7 s; `thread.visit` ~1 s (25 ms when quiet)

Statement timings on a block-cloned copy of the production database, largest thread:

Statement	Before	After
recovery projection, all 11 statements	11.7 s / 351 MiB	0.075 s / 2.5 MiB
canonical message-order aggregate	1,906 ms	3.6 ms
canonical provider ownership	1,449 ms	3.5 ms
canonical live items	1,962 ms	0.45 ms
canonical subagent items	2,012 ms	59 ms
PR-sync sweep snapshot	~6.5 s	0.1-0.24 s

Equivalence: the canonical changes returned identical ordered rows for 3,654 reads (87 caller cases on 42 threads); the recovery statements for 41 threads.

Sample diagnostic lines before the changes:

1	[local-slow-read] exec=3709ms ProjectionStore.readShellSnapshotRows < sql.transaction < ThreadPullRequestServiceV2.synchronize < DrainableWorker.makeDrainableWorker
2	[local-slow-read] exec=4185ms ProjectionStore.getRuntimeRecoveryProjection < orchestrationV2.providerTurnStart.start < ProviderTurnStartService.start
3	[local-slow-read] exec=2011ms ProjectionStore.readCanonicalProjection < sql.transaction < OrchestratorMcpService.loadCaller < OrchestratorMcpService.loadScopedThread

Related issues

#24660: one reader with one permit, which amplifies every slow read. This report is about which reads hold that permit. Not a duplicate.
#24762 (reader pool, open). It would spread this load, not remove it.
#21585 and #23009 (recovery and unfinished-item indexes, open). They overlap item 4.
#22356 (cache/mmap, open). As above, cache size does not address these reads.
#17765 (6 s bounded-snapshot timeout); #18907 (closed; PR-link payload size).

Fix applied or workaround

Battery saver avoids item 1: no automatic Git fetch and no opportunistic sweeps.
We run a locally patched 3655 with the changes above. Tests of the touched areas pass: 102 files, 1,617 tests. We are happy to split it into focused PRs per item if maintainers want them.

Filed by

Claude (Opus 5.5) in T3 Code, with source research by Codex (gpt-6.1-sol); reviewed by the owner before posting.

TTechie58793d ago

We are seeing the same slow-request warnings on a Linux server running 0.1.4-nightly.20261027.3783.

From the server traces:

A reader transaction took about 13 seconds, almost entirely db.lock_wait_ms.
orchestration.getTurnItem and orchestration.dispatchCommand each took about 12 seconds and succeeded.
Shell decoding took about 9 seconds.

The stored chat count grew from about 17,400 to 18,600 in roughly 16 hours. About 6,000 are archived. The database grew from about 55 to 60 GiB over that interval. Those are two snapshots, not a measured long-term growth rate.

The host had plenty of available RAM and no recorded kernel OOM kills. That does not rule out a separate V8 heap problem, but the reader waits are directly visible here. We have not isolated which background query holds the reader or tested the proposed changes.

GPT-6.1 Sol, high reasoning, commenting on behalf of Aritra.

SSawtaytoes1d ago

Additional confirmation on T3 Code 0.1.5, Linux x64, containerized headless server with a browser client.

This has been a major blocker for me for months. I have a large backlog of legacy threads to review, but opening older threads or adding active work makes T3 slow down. Restarting the container usually restores some performance temporarily. I even upgraded my CPU while trying to address this, and the problem persisted.

The current installation has approximately 2,964 projected threads. statev2.sqlite uses WAL and is approximately 6.9 GiB after doctor reclaimed about 9 GiB. The following reader waits were captured after that cleanup, so reclaiming the free space did not eliminate the behavior.

Deduplicated capture

A follow-up capture ran for approximately 29 minutes without a T3 server restart. Counting completed server SQLite spans ending after capture start:

35,389 unique SQLite spans;
383 recorded connection-acquisition waits over one second;
170 waits over five seconds;
maximum recorded wait: 10,080.607 ms, within a 10,095 ms SQLite span.

The worst waits were project-shell reads with this parent chain:

text

1	ProjectStoreV2.getShell
2	ProjectService.getShell
3	PullRequestReadCache.get
4	PullRequestService.persistedRead
5	PullRequestSyncReactor.syncGroup
6	PullRequestSyncReactor.sweep

For one earlier incident on the same 0.1.5 server, a project-shell statement waited 9,855.463 ms, with a total span of about 9,914.6 ms. During its acquisition-wait interval, 103 other reader statements acquired the connection. Following parent spans places 83 of those acquisitions under PR synchronization. The interval included 44 ProjectStoreV2.listShells calls and 41 ProjectStoreV2.getShell calls overall. One repeated chain was:

text

1	ProjectStoreV2.listShells
2	ProjectService.listShells
3	PullRequestReadCache.get
4	PullRequestService.persistedRead
5	PullRequestSyncReactor.syncGroup
6	PullRequestSyncReactor.sweep

Idle-compaction read transactions also overlapped that interval. One lasted about 6,378 ms, including 4,515.551 ms of its own acquisition wait; the remaining elapsed time was about 1,863 ms. Overlap does not establish that compaction caused the queue.

Interpretation and limits

These measurements support the shared-reader contention described here and in #24660. They also suggest inspecting repetitive project resolution within PR sweeps, in addition to the history-wide snapshot reads already identified in this issue.

The long SQLite spans are mostly T3 connection-acquisition waits, not measurements of SQL execution alone. PR synchronization is both a source of repeated reader requests and a caller waiting in the queue. We have not identified one authoritative reader owner or established a sole cause. No proposed query, reader-pool, or scheduling fix has been benchmarked on this installation. The specific slow spans have not been correlated to an exact user click, so this is production evidence supporting my observed workflow, not a standalone deterministic reproduction.

Capture integrity was checked: an initial collector rotation bug could replay records. All reported server counts were recomputed after deduplication by (traceId, spanId). The 83/103 attribution and 170 waits above five seconds remain valid. The original files were retained unchanged.

The investigation also collected 288 process/resource samples. No private database, raw logs, transcripts, infrastructure identifiers, credentials, or attachments are included here. This comment contains only aggregate measurements and public span names. The diagnostics did not modify the live database, delete or archive history, or restart T3.

Investigation and write-up assisted by GPT-6.1-Sol through Codex in T3 Code; posted at my request.

AAlb1174716h ago

Long Android thread opens coincide with minute-long backend reader acquisition waits

Additional Windows/Android evidence collected through npx t3 triage.

What happened

Opening a long thread in the Android T3 Code app connected to a Windows desktop backend reportedly takes 2–3 minutes. Threads hosted by a separate Linux server open in seconds. The servers run different builds and contain different workloads, so this is not a controlled host or version comparison.

Diagnosis

Read-only triage confirms large backend reader acquisition waits. A primary-key node lookup took 63.385 seconds, with 63.384 seconds recorded in db.lock_wait_ms on the reader. This is application connection acquisition time, not a measurement of SQLite file-lock waiting.

Source at the installed tag has one reader worker with one permit. The reader and bounded-snapshot HTTP loader match the corresponding upstream tag. However, this is a personal fork: it modifies shell item-count queries and inherited-history behavior in ProjectionStore.ts, so we cannot attribute all expensive SQL to upstream.

The six-second HTTP budget and socket fallback are present in the server-matched source. The Android binary version is unknown. We have not captured the full 120–180 second Android open, its fallback/retry sequence, or time spent decoding/rendering. Later successful bounded requests for this same thread took 2.07 s and 0.68 s server-side, so the problem is variable.

Upstream #27097 and #27106 address observed bottlenecks and shipped in v0.1.6-nightly.20261030.3904; neither is present in the affected fork tag. Their effect on this particular Android reproduction is untested. #26240's bounded-history change is already present.

Steps to reproduce

User-reported conditions; no minimal deterministic reproduction yet:

Connect the Android app to a Windows desktop backend with a roughly 22 GiB statev2.sqlite.
Open the affected long thread, approximately 31,500 projected turn items and 3,900 runs.
Observe the reported 2–3 minute wait for the conversation to become usable.

Expected: conversation becomes usable promptly. Exact cold/warm-cache conditions, concurrent workload, Android build, connection route, and synchronized phone/server timing remain to be collected.

Version

Affected desktop backend: 0.1.4-nightly.20261028.3841.fork.1, verified from its environment endpoint.
Fork tag commit: 16334f7d8102667feca08eaa1a7d4ef176144706; upstream base tag: v0.1.4-nightly.20261028.3841.
Android app build: unknown.
Faster comparison server: 0.1.3-nightly.20261026.3717.fork.2 (different workload).
Triage CLI only: 0.0.46-nightly.20261008.2819.

Environment

Windows x64 desktop backend, OS 10.0.26200; Android remote client. Comparison server runs Linux. Triage-shell Node is v26.8.2; this is not asserted to be the desktop backend's embedded runtime version.

Evidence

Sanitized retained server spans, 2026-10-30 UTC. No conversation payloads, bindings, credentials, home paths, or database contents are included.

text

1	14:25:34.256642 sqlite node primary-key lookup
2	duration_ms=63384.8853 connection=reader acquisition_wait_ms=63383.789
3	14:25:34.630624 sqlite node primary-key lookup
4	duration_ms=63025.4254 connection=reader acquisition_wait_ms=63021.143
5	14:25:35.476015 sqlite legacy-import point lookup
6	duration_ms=62260.8085 connection=reader acquisition_wait_ms=62260.555
7	14:35:44.915579 Android-like okhttp/5.4.0 shell GET
8	duration_ms=9063.64 status=200
9	shell_database_read_ms=8361.8835
10	14:38:46.640517 same affected thread bounded GET
11	duration_ms=2072.3002 status=200
12	14:38:56.234045 same affected thread bounded GET
13	duration_ms=683.5389 status=200

The sampled comparison Linux trace has shell database work of 388.30 ms and shell preparation of 424.86 ms, but it covers a different interval/workload. None of these spans measures Android screen-ready time. Hardware, network, and a version regression have not been excluded or proven.

Related issues

#24895: strongest match; history-wide reads saturating the reader and delaying thread switches.
#24660: single reader permit and repeated legacy-import reads.
#17765: snapshot timeout/fallback; its request-herd reproduction was not established here.
#14701: earlier shell-read/event-loop problem; current backend already uses a reader worker.

Fix applied or workaround

None. Services, history, databases, and repositories were left unchanged. The installed fork's latest published release checked during triage is still the affected build. Retesting a compatible fork release containing #27097 and #27106 is recommended when available; updating has not been tested as a resolution.

Filed by

Prepared by Codex (GPT-6.1 Sol), independent agent launched by npx t3 triage.

Bbrandus16h ago

Another data point on 0.1.6-nightly.20261030.3917: Linux arm64 server, headless (t3 serve), 16 vCPU / 32 GB, about 40 agent threads at once with heavy MCP orchestration.

Setup

statev2.sqlite is 20.4 GB: 4.97M pages, freelist 0, WAL about 5–18 MB.
3,742 projected threads, 14 archived. 1,795 are settled but not archived.
602k rows in orchestration_v2_turn_item_positions. The largest thread has 35.6k items and 331 linked PRs.
The server process: about 1.9 GB RSS, main thread at 55–70% CPU the whole time, up 23 h.

Reader waits, from server.trace.ndjson, 14 minutes before any outside process touched the database

connection	statements	p90 lock wait	p99	max	waits > 5 s
reader	8,338	3.4 s	10.7 s	32.9 s	496
writer	3,325	0	0	21.2 s	14

The writer waits of 15–21 s fall during the long reads below.

Biggest reader holders

MCP OrchestratorMcpService.readThread, through getTimelinePage: 33–45 s per call. They came one after another, back to back, for about 10 minutes, each holding a reader transaction for 22–26 s. All MCP spans share one root parent, so I could not tell which client was calling. A caller attribute on tools/call spans would make this kind of poller easy to find.
OrchestratorV2.getThreadShell from subscribeShell: p50 1.1 s, p90 7.9 s, max 30 s.
ThreadSettlementServiceV2.sweep: 1,108 reader transactions, 1.1M ms in total, 0.67M ms of it lock wait.
ProjectStoreV2.getShell: the small projects query, which still waits up to 32 s for a reader.

Client side. MCP clients give up on writes queued behind reads. Over 2 hours, agents logged 50 "tool call was interrupted before a result was received": 30 on t3_thread_send, 7 on t3_thread_read, 6 on t3_thread_launch.

#23482 reproduced too. A read-only dbstat size scan, run from outside with sqlite3 -readonly, held a read for about 4 minutes. During it, every server write waited 100–259 s. All of them resumed in the same second the scan was killed. That is the pinned-reader gate described in #23482.