Subagent first token stalls 1-2min: withSessionLock covers full forward + slow flash upstream first byte

Summary

Concurrent requests on the same Claude Code session (main turn + background subagents) serialize into a single queue and can stall for 1-2+ minutes before the first token. Two independent causes stack:

withSessionLock covers the entire forward, including the upstream response stream (src/server.ts:1506-1509). The lock exists to protect session.state from interleaved processTurn / stream-rewriter mutations, but it is held from prepare() through the whole streamed response. Claude Code subagent requests do not carry a distinct session id, so main session + every subagent land on the same lock chain — they are not concurrent at all, they queue.
Upstream first-byte for glm-5.3-flash via bili is pathologically slow, and the lock turns each slow upstream response into head-of-line blocking for every queued request behind it.

Evidence (2026-09-19, session c9ec4843)

Two subagents launched simultaneously (INPUT at 00:12:27Z both):

00:12:27.739  request A (2 msgs, 56.4KiB, local=234ms)  → forward     [subagent 1]
00:14:23.606  acp-usage A: input=17383 cached=64 (cache hit 0%)        ← A first byte after 115.9s
00:14:23.607  processTurn B                                               ← B unblocks 1ms after A's response
00:14:23.608  request B (2 msgs, local=115853ms) → forward              [subagent 2 waited 116s]
00:14:50.193  request C (118 msgs, local=142422ms) → forward            [main session waited 142s]
00:14:50.190  acp-usage B: input=17406 cached=17344 (cache hit 100%)    ← B first byte after 26.6s

B's processTurn log fires 1ms after A's response arrives — B did zero work while A's stream was in flight. That is the lock chain, not upstream scheduling.
Upstream first-byte by model, same time window: glm-5.3 (main) 3-6s; glm-5.3-flash via bili 26.6s (cache hit 100%) and 115.9s (cache hit 0%); bare curl to the same endpoint with a 171KB prompt, flash, cache-miss, streaming: 1-3s.
Earlier same-day run of the same scenario: subagent totals 129s / 188s with local= values 10-68s — same mechanism, softer upstream latency.
bili's body injection (56.4KiB → 69.7KiB outbound) breaks the upstream prompt cache on subagent first requests (hit 0% vs 98-99% steady-state), which pushes flash first-token into its worst path.

Repro

Start a Claude Code session through bili (bili claude).
Launch 2+ background agents (Agent tool) with model: sonnet (maps to glm-5.3-flash[1m]).
Watch the agents' first action timestamps vs launch time, and request: ... local= lines in bili.log.

Fix directions (ranked)

Shrink the lock: hold withSessionLock only around state-mutating sections (prepare, and per-message commits in the stream rewriter), not across the whole upstream stream. This is the main fix — even a slow upstream then only delays its own request.
Separate subagent sessions: derive a distinct session id per subagent conversation (prompt_cache_key / system fingerprint) so they don't join the main session's lock chain.
Preserve upstream cache prefix: keep injections out of the stable prefix so subagent first requests don't fall to cache hit 0%.

Open question: how much of the flash 115.9s first byte is upstream queueing vs bili's connection layer (the blind TCP tunnel re-establishes every 4-10s in the logs, worth a look separately).

🤖 Powered by ework · qwen3.8-27b

[bot] 🏷 Confirmed both mechanisms in code; working on it now. Status + plan:

Cause 1 verified. src/server.ts:1509-1644: withSessionLock(session, …) wraps runPrepare() + preflightCompressIfNeeded() + forward(), and forward() only resolves once the entire upstream response has been piped to the client (streaming branch ends at res.end() after the compress-loop; non-streaming after arrayBuffer()). So yes — every request on the same session id queues behind the previous request's full upstream stream, exactly as your B/C timestamps show (processTurn B firing 1ms after A's response = pure lock hand-off).

Why the lock exists (the constraint any fix must respect): it serializes mutations of the shared session.state — prepare()/processTurn (ref assignment, block ingestion) and the streaming compress-loop (applyRanges block creation + refreshFolded's re-run of processTurn, which replaces session.state). The kernel contract this repo relies on: a ref number / raw id denotes exactly one message forever, never re-issued. Two concurrent requests on one Session object interleaving those mutations is how corruption happens — and in your scenario all three conversations (main + 2 subagents) share one Session object, so today's coarse lock is also the only thing keeping cross-conversation state from interleaving.

Plan:

Shrink the lock (main fix) — hold it only around the discrete state-mutating sections: prepare+preflight, and each mutation point inside the stream path (compress execution, refreshFolded, final usage/markDirty commit). Pure I/O (waiting for upstream bytes, piping chunks) runs unlocked. A slow upstream then only delays its own request. This is wire-behavior-neutral when there's no contention (single-request sessions see identical ordering), and I'll prove it with typecheck + full test suite + a concurrency regression test.
Subagent session separation — for codex this already exists (REQ: codex subagent isolation via turn-metadata partition + anonymous tail-window reattach (PR #249 follow-up) #316, x-codex-turn-metadata thread partitioning). Claude Code sends no equivalent subagent marker (subagent calls reuse x-claude-code-session-id), so I'm evaluating what stable per-subagent-conversation signal exists on the Anthropic wire before touching identity logic — identity changes are high-risk (Codex 长会话在 macOS 休眠唤醒后 Bili 未触发压缩，导致上下文窗口超限 #280/会话身份不稳定：credential/upstream 维度导致长会话状态孤儿化（sessions 缺失） #286 history), so if the only candidate is a system-prompt fingerprint I'll bring you the trade-offs before shipping it.
Cache-prefix injection (Use kernel renderTags:"text-only" + forbid tag echoing in prompt #3) and the raw flash-TTFT question — separate follow-ups. Note on your open question: subagent A sat at the head of the queue, so its 115.9s first byte is bili-path/upstream-specific, not lock-induced — consistent with the cache-hit-0% payload hitting the worst upstream path. Worth instrumenting separately (I'll report what I find on the connection layer in-thread rather than opening new issues).

I'll post progress + PR link here as they land.

🤖 Powered by ework · qwen3.8-27b

[bot] 🏷 Triage: bug confirmed, root cause verified, fix direction #1 implemented → PR #972

What I verified (not just taking the report at face value):

Code path check: src/server.ts held withSessionLock(session, ...) from prepare() through the entire forward() call — i.e. across the whole upstream response stream. Your log evidence (B's processTurn firing 1ms after A's response) is exactly what that structure produces: on Node's single-threaded runtime a queued request does zero work until the holder releases, which only happens after A's stream closes.
Your layer analysis holds: cause fix: keep system prompt byte-stable for prefix cache #1 (lock scope) is the mechanism turning slow first bytes into session-wide head-of-line blocking; cause fix: address all code review findings (condense, routing, session-id, dead code) #2 (flash first-byte latency) is an independent upstream problem this fix does not touch — after the fix, a 115s upstream response delays only its own request, not B and C behind it.

The fix (PR #972): the lock now covers only state-mutating sections. Outer lock wraps prepare+preflight only and returns {body, prepared}; forward() runs unlocked, and each discrete mutation re-acquires it just long enough — markNativeCompactionBoundary, refreshFolded (post-compress processTurn + state write), the three JSON response rewrites, executeProxyTool in the streaming loop and Responses JSON path, and post-forward rememberPluginMessages. Read-only proxy tools stay unlocked (they skip mutating tools and run synchronously ⇒ atomically). Wire shape is unchanged in both compression modes.

Evidence:

New regression test tests/session-lock-concurrency.test.ts: two concurrent requests on one session against a mock upstream holding its first byte 400ms; asserts the second arrival lands within half that window + message-ref integrity under concurrent prepares. It fails on pre-fix code (verified by stash) and passes with the fix.
Rebased onto current master: typecheck clean, full suite 1900 pass / 0 fail / 2 skipped, build green.
Real-client E2E through the built dist (e2e-codex-fake.test.ts, deterministic fake Responses upstream): overflow scenario (compression really fires inside real codex, sentinels retained) + under-window control — both pass.

Not included — remaining items from your list, flagged for owner decision:

Direction fix: address all code review findings (condense, routing, session-id, dead code) #2 (separate subagent sessions): identity/session-binding logic, and it changes which session each conversation belongs to — bigger product decision than a lock fix.
Direction Use kernel renderTags:"text-only" + forbid tag echoing in prompt #3 (keep injections out of the stable prefix to stop the cache-hit-0% on subagent first requests): real win for the flash worst path, but it's a wire-injection-placement change that needs design discussion.
The open question (upstream queueing vs bili's connection layer / blind TCP tunnel churn): needs upstream-side logs I can't see from here; worth a separate look once fix: address all code review findings (condense, routing, session-id, dead code) #2/Use kernel renderTags:"text-only" + forbid tag echoing in prompt #3 are decided.

PR: #972

中文摘要：确认了 bug 根因（会话锁从 prepare 一直持有到整个上游响应流结束，导致同 session 的并发请求排队成头阻塞），已按方向 #1 把锁缩小到仅覆盖状态变更段并加了回归测试（旧代码上验证会失败），全量测试与真实客户端 E2E 均通过，PR #972 待合并；方向 #2（子代理独立 session）和 #3（缓存前缀保护）涉及身份绑定与注入位置设计，留给你拍板。

fix: split Claude Code subagent sessions so they stop queueing on the…

Merge pull request #975 from elevenfund/2026-09-19_subagent-split

fix: shrink withSessionLock to state-mutating sections so concurrent …

Merge pull request #972 from ranxianglei/2026-09-19_shrink-session-lock

fix: invert the Responses instructions fingerprint into a codex/claud…

fix(ranxianglei#1729): refuse dsh native compaction calls at the prox…

feat: dsh persona fingerprint — session id + system hash split for id…

fix(#2170): review findings A+B — split canary excludes design person…

fix: follow the live persona fork when a host-stamped dsh id hits a f…

fix: dsh persona fingerprint parity for the Responses wire (#2203)

fix: rebase ACP state when codex's local auto-compaction replaces the…

fix: rebase ACP state in one turn when dsh native compaction lands wi…

fix: follow the live persona fork when a host-stamped dsh id hits a f…

fix: key dsh personas on the google lane like the other wires (#2730)

Navigation Menu

Repository navigation

Subagent first token stalls 1-2min: withSessionLock covers full forward + slow flash upstream first byte #970

Summary

Evidence (2026-09-19, session c9ec4843)

Repro

Fix directions (ranked)

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Subagent first token stalls 1-2min: withSessionLock covers full forward + slow flash upstream first byte #970

Description

Summary

Evidence (2026-09-19, session c9ec4843)

Repro

Fix directions (ranked)

Activity

ranxianglei commented on Sep 19, 2026

ranxianglei commented on Sep 19, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions