[Bug][Windows]: v2 guidance catalog-state probe still costs ~7.5s per turn (the #1876 async fix removed the event-loop block, not the request latency)

[Vladimir321123]

Client or integration

Codex App, Codex CLI, and any ACP client (observed via @agentclientprotocol/codex-acp inside Obsidian Copilot).

Area

Proxy and routing / Platform (Windows)

Summary

#1852 reported that the Windows catalog-state enumeration blocked the Bun event loop. #1876 fixed that: collectCodexAppServerCatalogStateForRequest() now uses listWindowsSnapshotsAsync() with in-flight dedup and a short cache, and /healthz stays responsive.

The latency half of the same code path is still there, and it is now the dominant cost of every multi-agent v2 turn. On 2.32.0 the enumeration still runs on the request hot path, and on this machine it takes ~7.5s — longer than CATALOG_STATE_TTL_MS, so the cache almost never serves a request.

Measured on this installation, same account, same trivial prompt ("reply with PONG"), 4 runs each, interleaved:

Route	median	runs (ms)
through proxy	11296 ms	10844, 11245, 11296, 12689
direct to ChatGPT (no proxy)	5151 ms	3818, 4654, 5151, 5836
through proxy, multiAgentGuidanceEnabled: false	3424 ms	3118, 3292, 3424, 5698

So the proxy was ~7s slower than no proxy at all; with guidance off it is faster than direct (the WS upstream transport pays off as documented in ws-upstream.ts).

Evidence that the cost is the catalog probe, not the network

1. The proxy's own usage.jsonl already shows it. Representative slow row:

durationMs: 10175, firstOutputMs: 9969
attempts: [{ ordinal: 1, adapter: "openai-responses", status: 200,
             durationMs: 2024, firstOutputMs: 1818, sendCount: 1, recoveryKinds: [] }]

The upstream attempt took 2.0s; the request took 10.2s. ~8s is spent before the attempt starts.

2. CPU time of the proxy process during those 8 seconds is 0–31 ms per 900 ms sample — it is waiting on a child process, not computing.

3. Temporary console.log timestamps in src/server/responses/core.ts localise it exactly:

core: enter                       t0
step: before body read            t0 +8 ms
step: before route normalization  t0 +17 ms
step: before codex auth           t0 +7492 ms     <-- applyFinalRouteRequestNormalization
step: before request build        t0 +7497 ms
step: before fetch                t0 +7501 ms
providerFetch -> WS upstream      t0 +7502 ms
wsUpstream OPEN                   +346 ms
first frame to client             +498 ms

applyFinalRouteRequestNormalization() → multiAgentGuidanceText() → defaultCollectCatalogState() is the whole delay. With multiAgentGuidanceEnabled: false the same steps take 1–2 ms and durationMs equals attempts[0].durationMs within 4–8 ms.

Root cause: GetOwner is per-process, and the TTL is shorter than the probe

Running the exact script from windowsSnapshotPowerShellCommand() standalone:

snapshot #1: 5617 ms, 9 rows
snapshot #2: 5909 ms, 9 rows
snapshot #3: 5893 ms, 10 rows

Split into its two parts (822 processes on this machine):

Step	Cost
Get-CimInstance Win32_Process + CommandLine regex filter	646 ms
Invoke-CimMethod GetOwner, 93 candidate processes	43887 ms (~472 ms per process)

So the snapshot cost scales with the number of running Codex processes, not with machine size. This installation runs 9–10 of them at once — desktop app-server, plugin app-server, codex sandbox, codex-code-mode-host, codex-command-runner — which is an ordinary Codex App session, giving ~5.9s; the batched start-time query brings the total to ~7.5s.

That interacts badly with the cache:

const CATALOG_STATE_TTL_MS = 5_000;          // app-server-processes.ts
const CATALOG_STATE_UNKNOWN_TTL_MS = 250;

A 5s TTL in front of a 7.5s probe cannot help: the entry is stale before the next turn starts. In-flight dedup only merges concurrent turns, and sequential chat turns are not concurrent. The comment above collectCodexAppServerCatalogStateForRequest ("Typical cold cost is tens of milliseconds") does not hold on Windows once more than one or two Codex processes are alive.

Suggestion 5 from #1852 ("optionally narrow the CIM query before owner lookups") was reasonably deferred there, because narrowing does not fix event-loop blocking. Now that the blocking is fixed, that suggestion is the remaining problem.

Suggested safe direction

1. Drop the per-process GetOwner fan-out. One Get-CimInstance Win32_Process already returns everything needed except the owner; owner can come from a single association query, or from a SessionId/token comparison, or by dropping owner filtering to a cheaper heuristic and treating ambiguity as unknown. This alone should turn ~5.9s into <1s.
2. Serve stale while revalidating. The probe result is advisory. Returning the last known state immediately and refreshing in the background would remove it from the hot path entirely, instead of making one unlucky turn per TTL window pay the full cost.
3. Make the TTL exceed the observed probe cost (or adapt it to the measured duration). A TTL below the probe duration guarantees a miss on every sequential turn.
4. Regression test: with the enumeration seam stubbed to take, say, 3s and a TTL of 5s, assert that N sequential guidance builds trigger at most one enumeration and that turns after the first do not wait on it.

Workaround

ocx agent injection set --guidance off

(equivalently "multiAgentGuidanceEnabled": false in ~/.opencodex/config.json). Median turn dropped from 11296 ms to 3424 ms. This only disables OpenCodex's extra guidance injection; syncCodexSubagentDefaults and Codex's own collaboration tools are unaffected.

Note that this is the effective default for every user, since multiAgentGuidanceEnabled(config) returns config.multiAgentGuidanceEnabled !== false.

Version

OpenCodex 2.32.0 (verified byte-identical to the published npm tarball), bundled Bun 1.4.0, Codex CLI 0.149.0.

Operating system

Windows 11 Home, version 10.0.26200 (build 26200). Native Windows, no WSL.

Provider and model

Not provider-specific. Reproduced on openai/gpt-5.6-sol with ChatGPT login (codexAccountMode: pool); the delay happens before any provider work.

Logs or error output

usage.jsonl (slow turn)   durationMs=10175  firstOutputMs=9969
                          attempts[0].durationMs=2024  firstOutputMs=1818
proxy process CPU during the 8s gap: 0-31 ms per 900 ms sample
standalone snapshot script: 5617 / 5909 / 5893 ms
GetOwner alone, 93 processes: 43887 ms

Screenshots and supporting files

Not required; timings and code paths above are text-reproducible.

Redacted configuration

{
  "multiAgentGuidanceEnabled": true,
  "injectionModel": "gpt-5.6-sol",
  "injectionEffort": "xhigh"
}

Related issues

• [Bug][Windows]: synchronous PowerShell app-server enumeration blocks /healthz and proxy traffic on v2 requests #1852 — the event-loop blocking half of this code path (fixed by fix(windows): keep catalog discovery off request event loop #1876)
• fix(windows): fail closed when the top-level process query fails #1925 — the enumeration-failure sentinel and the 250 ms unknown TTL
• [Bug]: transient code-mode-host process makes catalog staleness check return "unknown", emitting a false "catalog changed after Codex started" restart prompt (2.11.1, Windows) #1354 — earlier correctness fix in the same collector

Checks

• I searched existing issues and documentation.
• I removed secrets, tokens, account details, request credentials, and personal data.

[lidge-jun]

리뷰 · 우선순위 74 / 80

설명: 이 이슈는 윈도우에서 브이투 협업 안내를 붙일 때마다 카탈로그 상태 조사가 한 턴에 약 7.5초를 먹는다는 보고다. 1852 가 말한 이벤트 루프 막힘은 1876 이 고쳤다. 지금은 막히지 않는다. 다만 기다리는 시간은 그대로다. 지금 CURRENT dev HEAD 는 faaa78d 이다. 이번 시간에 origin/dev 는 02c302a 에서 faaa78d 로 움직였다. 2500 이 잘못된 namespace 선택자와 스냅샷 권한을 고치고, 2501 이 이미 납작한 와이어 이름을 가진 선택자를 인가 문에서 막았다. 그 두 착지는 이 조사 경로를 건드리지 않는다. 이 이슈의 코드 길은 지금 HEAD 에도 그대로 있다. package.json 은 2.32.0 이다. src/config.ts 는 3238줄이다. src/runtime 폴더는 없다. default-aliases.ts 와 model-presets.ts 도 없다.

호출은 이렇게 이어진다. src/server/responses/core.ts 의 applyFinalRouteRequestNormalization 1665-1674줄이 multiAgentGuidanceText 를 기다린다. 보고자가 찍은 시간표의 before codex auth 간격이 바로 이 자리이다. src/server/responses/collaboration.ts 281-286줄은 브이투 면에서만 카탈로그 상태를 기다린다. 기본 수집기는 같은 파일 228-237줄 defaultCollectCatalogState 이다. 환경 변수 덮어쓰기가 없으면 src/codex/app-server-processes.ts 의 collectCodexAppServerCatalogStateForRequest 를 부른다. 윈도우가 아니면 동기 수집기로 떨어지고, 윈도우면 비동기 파워셸을 탄다. 안내가 꺼져 있으면 collaboration.ts 266줄에서 바로 null 을 돌려 조사를 안 한다. src/config.ts 2953-2956줄 multiAgentGuidanceEnabled 는 값이 false 가 아니면 켠다. 곧 기본이 켜짐이다. 그래서 윈도우 사용자는 설정을 안 건드려도 이 세금을 낸다.

조사 본체는 src/codex/app-server-processes.ts 400-437줄 windowsSnapshotPowerShellCommand 다. Get-CimInstance Win32_Process 로 전체를 읽고, 명령줄이 codex 후보일 때만 GetOwner 를 부른다. 후보는 줄였지만, 살아 있는 코덱스 프로세스가 아홉에서 열이라면 GetOwner 를 아홉에서 열 번 낸다. 보고자는 후보 아흔셋에서 프로세스당 약 472ms, 스냅샷 단독 5.6-5.9초를 쟀다. 그 다음 시작 시각 조회가 더해져 요청 경로에서 약 7.5초가 된다. listWindowsSnapshotsAsync 454-460줄 제한 시간은 8000ms 다. 7.5초면 겨우 들어가고, 조금 느리면 타임아웃이다. 타임아웃은 877줄에서 unknown 이 된다. unknown 의 캐시 수명은 741줄 CATALOG_STATE_UNKNOWN_TTL_MS 250ms 뿐이다. 다음 턴이 바로 다시 조사한다.

캐시도 이 비용을 못 가린다. CATALOG_STATE_TTL_MS 는 733줄의 5000ms 다. 조사가 7500ms 면 항목은 다음 턴이 시작되기 전에 이미 낡는다. 비행 중 합치기는 862-866줄처럼 같은 세대의 동시 요청만 묶는다. 채팅 턴은 보통 하나씩이다. 그래서 순차 턴마다 전체 비용을 다시 낸다. 765-770줄 주석은 아직 차가운 비용이 수십 밀리초이고, 백그라운드 새로고침은 이 조각의 범위 밖이라고 적는다. 그 문장은 윈도우에서 코덱스 프로세스가 둘 이상일 때 거짓이다. 1852 의 다섯 번째 제안, 곧 소유자 조회 앞의 질의 좁히기는 그때 이벤트 루프 막힘을 안 고친다고 미뤄 두었다. 막힘은 고쳤고, 남은 문제는 그 지연이다.

이 경로는 안내 문장을 붙일지 말지 정하는 조언이다. 업스트림 호출 자체는 아니다. 보고자의 usage.jsonl 도 업스트림 시도 2.0초, 전체 10.2초였다. 안내를 끄면 중앙값이 11296ms 에서 3424ms 로 떨어졌고, 프록시가 직접 챗지피티보다 빨라졌다. 임시 우회는 ocx agent injection set --guidance off 또는 config.json 의 multiAgentGuidanceEnabled false 다. 이 우회는 코덱스 자체의 협업 도구를 끄지 않는다. 다만 기본이 켜짐이라, 우회를 모르는 윈도우 사용자는 브이투 턴마다 이 세금을 낸다. 우선순위 74 는 그 때문이다. 502 전송 구멍은 아니다. 2473 이 막아 둔 웹소켓 큰 프레임과도 다르다. 그래도 기본 경로의 체감 지연이라 점수가 높다.

types.ts/config.ts 가르기와는 겹치지 않는다. 이 이슈를 구현하는 풀이 나오기 전에는 닫지 말 것. 1852 는 막힘 반쪽이고 이미 고쳤다. 이 이슈로 1852 를 다시 열지 말 것. 1925 의 unknown 250ms 와 1354 의 수집기 수정도 이 이슈가 대체하지 않는다. 2475 는 여전히 드래프트라 2407 을 닫지 말 것. 2492 는 아직 안 합쳐져 2489 도 닫지 말 것. 2496 도 드래프트라 2495 를 닫지 말 것. 2491 의 네 관계 버그도 그대로다. 2426 과 2460 은 leftover-closed 다. 다시 열지 말 것. 2463/2464/2465 도 기본 별칭 파일이 없어 닫지 말 것. 프리뷰 배포가 아니다.

src/codex/app-server-processes.ts 733줄 CATALOG_STATE_TTL_MS - 5000ms 다. 조사 7500ms 보다 짧아 순차 턴마다 캐시가 빗나간다
src/codex/app-server-processes.ts 427줄 Invoke-CimMethod GetOwner - 후보마다 한 번씩 나간다. 보고자는 프로세스당 약 472ms 를 쟀다
src/codex/app-server-processes.ts 454-460줄 listWindowsSnapshotsAsync - 제한 8000ms. 7.5초면 겨우 들어가고, 넘치면 unknown 250ms 만 캐시한다
src/codex/app-server-processes.ts 765-770줄 주석 - 차가운 비용이 수십 밀리초이고 백그라운드 새로고침은 범위 밖이라고 아직 적는다. 윈도우 실측과 다르다
src/codex/app-server-processes.ts 839-937줄 collectCodexAppServerCatalogStateForRequest - 요청 경로가 조사를 기다린다. 비행 합치기는 동시 요청만 묶는다
src/server/responses/collaboration.ts 281-286줄 - 브이투 면만 이 조사를 기다린다. 브이원은 안 탄다
src/server/responses/core.ts 1665-1674줄 applyFinalRouteRequestNormalization - 보고자의 7.5초 간격이 이 호출이다
src/config.ts 2953-2956줄 multiAgentGuidanceEnabled - false 가 아니면 켠다. 기본이 켜짐이다

메인테이너의 판단이 필요한 지점

• GetOwner 팬아웃을 한 번의 연관 조회로 바꿀지, 소유자 필터를 더 싼 휴리스틱으로 바꿀지. 바꾸는 편이 맞다. 조언 값 하나를 위해 턴마다 7.5초를 내면 안 된다
• 낡은 값을 바로 주고 뒤에서 새로 고칠지. 이 결과는 조언이라 그 편이 요청 경로에서 조사를 빼낸다
• TTL 을 실측 비용보다 길게 할지. 길게만 하면 한 턴은 여전히 전체 비용을 낸다. TTL 만으로 고치지 말 것
• 윈도우에서 안내 기본값을 끌지. 우회는 이미 있다. 기본을 바꾸면 브이투 안내가 조용해진다
• 1852 / 1925 / 1354 를 이 이슈로 닫을지. 닫지 말 것
• v2.32.1 GO 문서 2504 의 알려진 결함에 이 이슈를 넣을지. 넣는 편이 맞다. 동결 뒤에 열렸고 실측이 있다

너의 추천
열어 둔다. 구현 풀이 오기 전에는 닫지 말 것. 우회는 안내를 끄는 것이다. 고침은 GetOwner 비용을 줄이고, 요청 경로에서 조사를 기다리지 않게 하는 쪽이 맞다. TTL 만 올리지 말 것. 라벨은 그대로 둔다. 머지할 대상이 아직 없다. 프리뷰 배포가 아니다.

이 댓글은 grok-bot이 작성했습니다

[lidge-jun]

Fixed on dev by #2580 (342911fec7), which landed during this cycle's backlog sweep — I verified it is an ancestor of the current dev head rather than taking that on report.

Your diagnosis was exactly right, including the part that made it hard: the probe's cost routinely exceeds its own TTL, so the cache almost never served a request and the enumeration became the dominant per-turn cost.

The fix is bounded stale-while-revalidate rather than a bigger TTL. After the first real observation, a request gets the previous reading immediately while a refresh runs behind it:

• expired real observations stay servable for 60s past expiry (CATALOG_STATE_MAX_STALE_MS, src/codex/app-server-processes.ts:743-763)
• the stale window is measured from expiry, not from when the reading was taken, so it stays independent of the TTL — anchoring it to total age would silently disable the path if the TTL were ever raised past it
• unknown is explicitly never served this way: it is a failure to observe, not an observation
• a catalog write advances the generation and drops the entry, so a stale reading can never outlive a real change

Raising the TTL was considered and rejected: it would have made the numbers look better while serving evidence nobody bounded. The refresh is what makes the next reading current; the bound is what stops a persistently failing probe from serving indefinitely old evidence.

Honest limitation: the first cold request on a given machine still waits, because there is no prior observation to serve. So does a request arriving more than 60s past expiry. Your ~7.5s figure is what that first probe costs; what changed is that it is now paid once rather than on nearly every turn.

Platform-independent coverage is at tests/codex-app-server-processes.test.ts:1054-1256 — I could not verify on Windows here, so the tests pin the caching and serving policy rather than the platform call itself. Falsified by removing both stale-serving returns, which reddens the expired-cache case specifically.

Thanks for the interleaved medians — a latency report with a control is what made it obvious this was a cache-effectiveness problem rather than a slow-query problem.