Server event loop stalls for up to 11 s every few minutes, and every request in flight stalls with it

Found by the daily slow-request review (#108) on 2026-11-11, covering 2026-11-10 18:00 UTC to 2026-11-11 18:00 UTC.

What the records show

The event loop stalls often. ~/.t3/userdata/logs/event-loop-stalls.ndjson logged 127 stalls over 2 s in the window, 25 of them 9 s or longer. The worst was 11.5 s, at 2026-11-11 01:14:31 UTC. The stalls carry high system CPU time (cpuSystemMs 7–14 s per sample), and the load average was mostly 9–16 on a 32-core machine, so machine load does not explain them.
The slow requests are the stall's victims, not separate causes. 19 of the 28 slow requests (over 10 s) fall into four bursts where several requests started in the same second and all finished 10–13 s later: 22:22:11, 00:44:02, 01:18:04 and 01:34:34 UTC. Inside them, trivial indexed reads took about 10 s with no recorded lock wait, for example SELECT issue_number, thread_id FROM issue_thread_links WHERE host = ? AND repository = ? at 7.8 s and 11.6 s. So did a Forgejo sign-in (ForgejoCli.authenticateFj, 9.7 s). Requests that do show lock wait (sql.transaction lock wait of 10–12.8 s in OrchestratorV2.getThreadRecords and IssueWorkService.repositoryStatus) waited in the same bursts for a connection held by a stalled request.
Durations by request: server.getThreadProcesses 15 records, median 11.7 s, worst 13.4 s; issues.statusBatch 10 records, median 11.6 s, worst 21.6 s (load average 46 at that moment); issues.list 2 and issues.repositoryStatus 1, at 11–13.8 s.
Still present on 2.12.112 (installed 02:01 UTC): stalls of 9.5 s (02:02:44), 9.1 s (03:35:05) and 6.0 s (04:17:36), and two slow requests at 02:14:57 and 02:15:40. Stalls dropped from 15–25 per hour to 0–5 per hour after about 02:00 UTC. That is when the new build started, but also when activity fell off for the night, so the drop is not yet evidence of a fix.

Sample records (trimmed)

2026-11-11T01:18:17Z ws.rpc.server.getThreadProcesses 12.0s  ProjectionStore.readCanonicalProjection 9.7s
  query orchestration_v2_projection_provider_threads WHERE thread_id = ? OR owner_node_id IN (...)  10.1s, lockWait 0
2026-11-11T01:18:19Z ws.rpc.server.getThreadProcesses 13.4s  sql.transaction lockWait 11.9s
2026-11-10T22:22:25Z ws.rpc.issues.list 13.8s  query issue_thread_links WHERE host = ? AND repository = ?  11.6s (lockWait 11.6s)
event-loop-stalls 2026-11-11T01:14:31Z delayMaxMs 11474 utilization 0.71 cpuUserMs 17477 cpuSystemMs 10928

Source

The stall monitor is apps/server/src/observability/EventLoopMonitor.ts. It logs a stall over 2 s (STALL_THRESHOLD_MS) with CPU and page-fault counts, but not what the main thread was doing.
Reads run in a pool of reader workers (packages/shared/src/nodeSqliteClient.ts), but transactions such as getThreadRecords' sql.withTransaction(readCanonicalProjection(...)) (apps/server/src/orchestration-v2/ProjectionStore.ts:5755) and all writes use the main-thread connection.

Suggested direction (unverified)

The blocker is not identified. What blocks the main thread is not confirmed in the source. Candidates are a synchronous SQLite call on the main-thread writer connection (it waits up to busy_timeout = 5000), other synchronous filesystem or process work, or long JSON encoding.

The smallest next step is to name the blocker before fixing anything: when a stall passes about 5 s, record the span that was active when the loop resumed. Alternatively, take a short CPU profile with the inspector after a stall. Then move or split that work.

Daily slow-request review, 2026-11-12. The main-thread freeze happened again, and this one was much longer.

Event-loop stall: at 2026-11-12T02:23:03Z (2026-11-11 19:23 MST), the server on 2.12.114 logged delayMaxMs 778000, so the main thread was blocked for about 13 minutes. During that window it recorded:

utilization 1
56.6 s of user CPU and 161.1 s of system CPU
2.36M minor and 13.3k major page faults
1.6 GB of resident memory (RSS)
a machine load average of about 2, so the rest of the machine was idle

Slow requests that were victims of the freeze: two ws.rpc.server.getThreadProcesses calls both finished at 02:22:35Z.

The first started at 02:07:55 and took 880 s, of which 879.8 s was waiting on the sql.transaction lock.
The second started at 02:09:33 and took 781 s, of which 778.8 s was waiting on that lock.

Both waits were in OrchestratorV2.getThreadRecords ← ThreadManagementService.getThreadRecords ← orchestration.readRunningThreadWork ← BackgroundTasks.processes. The writer connection runs on the frozen main thread, so the lock was held by the stall itself, not by a slow query.

Missing evidence: no trace covers the window. The server.trace.ndjson* files rotate every 6 minutes across 11 files, and the oldest now starts at 2026-11-12T16:47Z. server-child.log was last written on 2026-11-08. So the blocking span is still unknown (unverified). The heavy system CPU and minor faults point to large allocation or copy work on the main thread, but that's inference.

This strengthens the suggested first step here: on a stall over threshold, record the active span or take a short CPU profile, so the next one names its cause.

T3 Code status: Done

Issue: #367 Server event loop stalls for up to 11 s every few minutes, and every request in flight stalls with it

Thread: thread:delegated-task:command%3Amcp%3Af7dbe326-b11b-455a-a927-ca05430dc653%3Adelegate-task%3Aissue-367-build-1

Model: claude-opus-5-5

Branch: issue-367-server-event-loop-stalls-for-up-to-11-s

Updated: 2026-11-13T20:28:34.783Z

T3 Code closeout: done

Issue: #367 Server event loop stalls for up to 11 s every few minutes, and every request in flight stalls with it
Thread: thread:delegated-task:command%3Amcp%3Af7dbe326-b11b-455a-a927-ca05430dc653%3Adelegate-task%3Aissue-367-build-1
Model: claude-opus-5-5
Branch: issue-367-server-event-loop-stalls-for-up-to-11-s
Completed: 2026-11-13T20:28:35.698Z

I couldn't find what blocks the main thread, so this PR doesn't fix the stalls. It adds logging so the next long stall records the operation that was running when it happened. The PR is open against main, references #367, and is not merged.

Cause, still unknown. No trace covers a stall: traces rotate in about 6 minutes, and the current traces contain none. What I could establish from the logs:

The two long stalls line up with heavy disk reads. The machine's activity log (sysstat) shows reads of about 260–340 MB/s from the SSD, lasting about 40 minutes and recurring roughly every 7 hours (Nov 11 18:45–19:30 local, Nov 12 01:45–02:30, 09:25–10:10, 13:00–13:15). The 13-minute stall ended at 19:23 and the 111 s stall at 02:24, each just as one of those read runs finished.
The read runs probably come from the server's history cleanup, but that's unconfirmed. The server prunes old history every 6 hours, and with its run time that matches the ~7-hour rhythm. Its big scans run on a separate reader thread, not the main thread.
I found no statement that would block for minutes. I checked the query plan of every delete the cleanup runs on the main thread when it removes deleted threads, and all of them use an index. The cleanup also hands control back to the event loop between batches, so batching alone can't explain a single 13-minute block.
The shorter 3–11 s stalls look like a separate problem. They come with about 1 million minor page faults per 30 seconds, which suggests heavy memory churn. I didn't pin them down either.
The next cleanup is a good test. 4,744 threads were deleted on Nov 13 between 04:00 and 05:00 UTC. After their one-day grace period, the next cleanup will purge them all, so it's a likely moment to catch a stall with the new logging in place.

What changed:

StallAttribution.ts (new): it wraps the tracer the same way the existing heap tracking does, and remembers open operations plus the last 64 that ran longer than 2 s.
Each stall record now has suspects: up to 5 traced operations or requests that ran through the stall, most recently started first, so the operation that actually blocked should come first. This appears in event-loop-stalls.ndjson, the warning log and the stall's trace entry.
Each stall record also has fileSystemReads: the server's own disk reads during the stall. This will show whether those big read runs come from the server or from another process.
Clients see no change: the stall data sent to them is untouched.

Tests:

The new StallAttribution.test.ts checks the ordering and that operations too short to explain the stall, or that ended before it, are left out. It passes, and so does EventLoopMonitor.test.ts.
vp run check:changed: format, lint, typecheck and tests (3 files, 4 tests) pass. Its second unused-exports check (knip) fails, but only on unused exports already on main; none are in this change. I committed with --no-verify for that reason, as allowed.

PR #397, head 6ba2701, checks and reviews not yet reported.

fix(server): event loop stall records name the spans that lasted thro…

Navigation Menu

Repository navigation

Server event loop stalls for up to 11 s every few minutes, and every request in flight stalls with it #367

What the records show

Sample records (trimmed)

Source

Suggested direction (unverified)

T3 Code closeout: done

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Server event loop stalls for up to 11 s every few minutes, and every request in flight stalls with it #367

Description

What the records show

Sample records (trimmed)

Source

Suggested direction (unverified)

Activity

tannerpolley commented on Nov 12, 2026

tannerpolley commented on Nov 13, 2026

tannerpolley commented on Nov 13, 2026

T3 Code closeout: done

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions