Cut relay hot-path overhead

[D0n9X1n]

Summary

Cuts the per-request overhead found in the #141 performance review. Each fix is its own commit with a regression test.

1. undici 7.30 (package.json, package-lock.json). undici 7.28 checked an idle keep-alive socket with an unref'd setTimeout(0) before reusing it; on Windows that timer can wait for the next system timer tick. 7.29.1 and later use a ref'd setImmediate. Test: a second request over the same idle connection schedules no zero-delay timer (fails on 7.28.0).
2. Upstream keep-alive 50 s (src/copilot/client.ts). Copilot sends no Keep-Alive hint, so undici's 4 s default closed every idle upstream connection and the next request paid for a new TCP and TLS handshake. In the [Perf]: Cut relay hot-path overhead: log writes, idle-socket timer, request copies, schema rebuilds, upstream keep-alive #141 probe Copilot reused a connection idle for 60 s and had closed one idle for 120 s. Test: a connection idle for 5.5 s is reused (fails before). Internals states the cost: a NAT or proxy that silently drops connections idle for less than 50 s can now leave a request waiting for an operating system timeout or the upstreamTimeoutSeconds deadline.
3. Log writer (src/lib/log.ts). Each entry ran its own directory checks, open, stat, chmod, append and close, and read its timestamp and dated file after those awaits, so a burst could reach the file out of order. Entries are now stamped and assigned their dated file when logged, and appended in call order by one drain. The file stays open while entries keep coming and is closed a second after the last one. The handle is reused only while the path still names the same private file with one link (mode 0600 on POSIX) and the app and logs directories are still the ones checked when it was opened (not links; mode 0700 on POSIX); otherwise the next batch reopens with the full checks. Tests that fail on main: a 50-entry burst keeps call order through one open; an entry logged at 23:59:30 local time and written after midnight keeps its stamp and dated file; batches written within a second share one open. Further tests: a renamed or replaced file, a second hard link, a logs folder replaced by a link, and a loosened file or folder mode (POSIX) are not written through the reused handle; the file is closed a second after the last entry; concurrent flushLogs calls resolve; the idle timer does not use the global setTimeout.
4. Request trace (src/lib/request-trace.ts). Every upstream request body was copied into a Buffer to count its bytes, even with capture off. It is now counted with Buffer.byteLength and encoded only when recorded. Test fails before.
5. Tool schemas (src/copilot/tool-schema.ts). normalizeResponsesToolSchema rebuilt every schema on every Responses request. It is now copy-on-write: a schema that needs no change comes back as the same object, and an omitted pattern copies only its path. Tests: same object and path-only copy (both fail before); a __proto__ property name stays data; a copied array keeps its holes and length.
6. Tokenizer preload (src/start.ts, src/lib/tokenizer.ts). The first count_tokens request loaded the gpt-tokenizer module and built the encoder while Claude Code waited. After preflight, start loads o200k_base and each supported tokenizer the configured models report, logs Tokenizers loaded: ..., then listens. A failure is logged and loading falls back to first use. Tests: the preload unit test fails when the preload loads nothing, and the packed smoke (scripts/package-smoke.mjs) checks that start logs Tokenizers loaded before its server listens; a build that preloads after startServer fails it.

Docs: wiki Internals, Architecture, Logging and troubleshooting, and Development (EN and 中文), and CLAUDE.md.

Closes #141

Scope

Relay internals only. No route, config key, request or response shape changes. One new startup log line: Tokenizers loaded: <names>.

Left unchanged, as listed in #141: per-delta JSON parse and serialize, WebSearch retained chunks, catalog discovery after a base-URL reload, the consola reporter, keep-alive toward Claude Code, and synchronous counting after the preload.

Review follow-ups

Opus and GPT-6 Astra reviewed the first seven commits; Opus also checked efdd1e9. Neither found a blocker. Each finding below has its own commit, test first:

• 7fa8a0d (GPT-6 Astra). Two concurrent flushLogs calls never resolved: each waited for the close the other had just queued. Each call now waits for its own close and closes again only while entries are queued. Test: two concurrent calls in a child process with a timeout; it hung before.
• 410d0c3 (GPT-6 Astra). The reused handle kept appending after the logs folder was replaced by a link to where the open file had been moved; main refused that write. The writer now records the app and logs directories when it opens the file and reuses the handle only while both are unchanged. Tests: a logs folder replaced by a link (failed before), and on POSIX a loosened logs folder mode is restored before the next append.
• 1645930 (Opus). On Windows the kept-open handle blocked renaming or moving the logs folder for as long as the relay ran. The file is now closed a second after the last entry. Test: one entry, then the handle is closed 1.5 s later (failed before). Logging and troubleshooting (EN and 中文) describe the remaining window.
• 78eec3d (both). The tests pinned neither handle reuse nor the file identity check, and the stamp test crossed midnight only when run in the last minute of a local day. New tests: batches within a second share one open, and an entry logged after the file is replaced by a new private file goes to the new file; the stamp test now starts at 23:59:30. The tokenizer test checks membership instead of the exact cache contents.
• 9f91c80 (GPT-6 Astra; also noted by Opus). A copied schema array turned holes after the first changed element into own undefined elements. JSON request bodies have no holes, so requests were unaffected. The copy now keeps holes and the length. Test failed before.
• a0ffef2 (Opus). Internals (EN and 中文) states the cost of the 50 s keep-alive.
• 25d3ccf (local gate and CI, not review). The idle close from 1645930 used the global setTimeout, which auth-recovery.test.ts replaces to capture the token refresh timer. The test captured two timers and failed on all six legs of CI run 37094710202. The idle timer now comes from node:timers. Test: the global setTimeout records nothing across a logged entry and a flush; it recorded [1000] before.

Both reviewers then re-checked 25d3ccf. GPT-6 Astra found its four findings resolved and no new merge-blocking defect in f53b1c1..25d3ccf, and recommended merging. Opus found its four findings and the schema holes resolved and no new defects in efdd1e9..25d3ccf, and gave a merge verdict with three optional nits: Logging and troubleshooting names only the logs folder, though renaming ~/.copilot-relay also fails while the file is open; the idle-close test sleeps a fixed 1500 ms, where polling for the closed handle would leave more margin; and node:test MockTimers enabled for setTimeout also replaces node:timers' setTimeout, which no test enables today. The PR was merged after GPT-6 Astra's verdict and before Opus's report arrived.

Validation

Local, Windows, Node v24.19.0, on the tree of 25d3ccf:

• npm run typecheck
• npm run test:unit (872 pass, 0 fail, 30 skipped)
• npm run test:integration (389 pass, 0 fail)
• npm run build

The gate ran on 8cb8a91, which has the same tree as 25d3ccf; only two commit messages differ (see Notes).

Every test marked above as failing before its fix was run against the code before that fix and failed. The tests in 78eec3d were also checked by breaking src/lib/log.ts: a reuse check that never passes fails the shared-open test (3 opens, expected 1), and removing the file identity check fails the replacement test. Removing the hole check or the length assignment from mapArray fails the array test.

Measurements

main (78eb4f2, undici 7.28.0) against this branch at 25d3ccf, run back to back on one Windows laptop (Node v24.19.0) against a mocked Copilot upstream. Each figure is from one run unless the row says otherwise; timings vary between runs. The bench scripts are the ones from the #141 review and are not part of this PR.

Relay in a child process, quick mode:

	main	branch
File system calls per request at log level info (gpt / chat / native routes)	72.0 / 72.0 / 72.0	12.1 / 11.2 / 11.3
Relay CPU per request, ms (gpt / chat / native)	22.40 / 21.37 / 19.80	9.93 / 6.77 / 6.23
Time to the first streamed marker, p50 ms (gpt / chat / native)	7.8 / 6.0 / 5.3	6.0 / 4.9 / 4.5
setTimeout(0) from undici's idle-socket check, per request	1.00	0.00
Time to the first streamed marker, p50 ms, at log level error / info	14.85 / 7.24	5.22 / 5.40
Of 32 concurrent requests, file log order differs from call order	28	0
New upstream connections after 6 s idle, no Keep-Alive hint	1	0
New upstream connections with Keep-Alive: timeout=5, after 3.5 s / 6 s idle	1 / 1	1 / 1

In process, per call, at request sizes of 204800 / 1048576 / 4194304 bytes:

	main	branch
Tool schema normalization, wall p50 ms	0.473 / 0.463 / 0.463	0.119 / 0.12 / 0.118
Responses payload build, wall p50 ms	0.485 / 0.596 / 0.928	0.136 / 0.226 / 0.577
Responses payload build, heap rise p50 bytes	764296 / 1170280 / 2789664	253536 / 659584 / 2279056

Instrumented relay, 50 requests with 204800-byte bodies at log level info. The instrumentation wraps JSON, Buffer.from and three fs methods to count calls, so its CPU figures include that wrapping. Each mode ran twice; the call and byte counts are from the first run:

	main	branch
mkdir / lstat / open calls, non-streaming	700 / 1400 / 350	2 / 571 / 1
mkdir / lstat / open calls, streaming	800 / 1600 / 400	2 / 559 / 1
Bytes passed to Buffer.from, non-streaming / streaming	10040586 / 10049930	147934 / 157206
Relay CPU per request, non-streaming, two runs, ms	19.06, 21.26	10.28, 7.8
Relay CPU per request, streaming, two runs, ms	33.44, 25	13.74, 10.3

Token counting in a fresh process, three runs each: on main the first count took 602.5, 605.7 and 607.8 ms. On the branch the startup preload took 579.5, 575.4 and 584.3 ms before the server listens, and the first count took 5.6, 5.9 and 5.7 ms.

Notes

• Log file handle. The relay keeps the active log file open while it writes and closes it a second after the last entry. Moving or deleting the file while the relay runs makes the next entry create a new file at the dated path. On Windows, renaming or moving the logs folder fails with access denied while the file is open; Logging and troubleshooting says to wait a second after the last entry or stop the relay first. On POSIX the app and logs directory modes are checked before each reuse; a loosened mode reopens the file, which re-tightens it, as does each retention pass. A failed retention pass no longer drops the queued entries.
• Keep-alive is not a config key. 50 s follows Copilot's measured idle behavior; Internals states the cost. A server that sends a Keep-Alive: timeout=N hint still gets undici's hint-based timeout.
• Lockfile. This machine installs through a mirror; the resolved URL for undici was set back to registry.npmjs.org with the same integrity hash. npm ci passed on every CI leg against that hash.
• Commit messages. After pushing, the messages of the last two commits were reworded and the branch force-pushed with a lease. The keep-alive docs commit, now a0ffef2, had attributed the request to both reviews instead of Opus, and the timer fix, now 25d3ccf, named the docs commit's previous hash. The trees are unchanged.
• CI. Run 37094710202 failed on all six legs in tests/unit/auth-recovery.test.ts (2 !== 1); 25d3ccf fixes the timer collision behind it, and run 37095824238 on 25d3ccf passed on all six legs. On an earlier push, Windows Node 26 failed once in tests/unit/release-pipeline.test.ts, where a Git Bash utility probe hit its 10 s timeout with no output; a rerun of that job passed, and the test does not touch the code changed here.
• No token values are logged; the new startup line names tokenizers only.

Checklist

• Public API remains Claude Code-only unless intentionally changed.
• Config changes are reflected in config.default.yaml, README, and wiki/ (EN and ZH). No config changes.
• Logs do not expose tokens.
• Integration tests mock upstream Copilot; they do not call real Copilot services.

After merge

• Remove inactive local/remote feature branches and temporary worktrees, prune stale refs, and report preserved work; follow the Development Wiki cleanup rules.

perf/hot-path was deleted on origin and locally, and stale refs were pruned. The only worktree is the main checkout; nothing was preserved. The wiki publish run on 5e16372 succeeded, scripts/publish-wiki.py verify passed on a fresh clone of the wiki (19 pages), and each of the 18 English and 中文 links on the live Home page opened its page, including the new Internals and Logging and troubleshooting text.

🤖 Generated with Claude Code