[Perf]: Cut relay hot-path overhead: log writes, idle-socket timer, request copies, schema rebuilds, upstream keep-alive #141

Context

The maintainer asked for a final performance review, with GPT-6 and Opus both reviewing. Two independent reviews measured the request hot path against a mock upstream (Windows 11, Node v24.19.0), pairing relay and direct requests. A separate live trace against Copilot checked upstream connection reuse. Numbers below are quoted from those runs.

Findings to fix

1. Default info logging does most of the relay's CPU work. Each entry runs its own chain in writeLogFile (src/lib/log.ts): mkdir and lstat of both directories, then lstat, open, stat, lstat, appendFile and close of the file.
   • Opus: a streamed request logs 8 lines and made 16 mkdir, 32 lstat, 8 open, 8 stat and 8 appendFile calls. Relay CPU per small streamed request: 15.88 ms at info, 4.04 ms at error. A profile of 400 requests (2401 ms busy) spent 794 ms under log.ts, 365 ms in consola and 507 ms in node:internal/fs.
   • GPT-6: relay CPU per 200 KB Responses SSE request was 21.9–22.7 ms with logging and 9.7–10.2 ms with logging suppressed. A file-only benchmark of eight entries per request used 15.9–17.0 ms CPU.
   • Each entry's timestamp is taken after those awaits. With 4 concurrent clients sending 160 requests, file order differed from call order for 141 requests (Opus).
2. undici 7.28.0 delays each request on a reused upstream connection. scheduleIdleSocketValidation waits on an unref'd setTimeout(0); on Windows that lasts until the system timer tick unless other I/O wakes the loop. Opus, 120 requests per level: first delta p50/p95 15.02/18.46 ms at logLevel: error, 5.34/8.06 ms at info, where log I/O wakes the loop early by accident. undici 7.29.1 replaced the timer with a ref'd setImmediate ("drop idle-socket timer floor", perf(h1): drop idle-socket timer floor with a ref'd setImmediate nodejs/undici#5707). This must ship together with fix 1, or cheaper logging exposes the timer.
3. Capture-off tracing copies every upstream request body. RequestTrace.fetch (src/lib/request-trace.ts) runs Buffer.from(input.body) before checking whether it records, and the copy stays alive while the request awaits upstream. GPT-6: 12 concurrent 4,194,304-byte requests retained 50,331,648 extra bytes; the copy took 2.21 ms p50, Buffer.byteLength 1.53 ms.
4. Responses tool schemas are rebuilt on every request. normalizeResponsesToolSchema (src/copilot/tool-schema.ts) copies every schema object even when nothing changes. GPT-6: 0.44 ms p50 and approximately 711,664 heap bytes per normalization of a 36-tool fixture. Opus: 57 ms of a 318 ms profile of 15 requests at 1 MB with 220 tools.
5. Upstream connections close after 4 s idle. Copilot's responses carry no Keep-Alive header, so undici applies its default keepAliveTimeout of 4 s. Live trace through fetchCopilot: requests sent immediately and 1 s after the previous one reused its connection; a request after 6 s idle opened a new one. Any Claude Code turn after a pause longer than 4 s (a tool run, reading, typing) pays a new TCP and TLS handshake. Copilot's idle limit is being measured before a longer timeout is chosen.
6. The first count_tokens call loads the tokenizer synchronously. Opus: the first call took 569.7 ms; warm calls p50 13.8, 34.5 and 163.1 ms for 227 KB, 797 KB and 3.6 MB bodies, with event-loop delay up to 162.5 ms. The maintainer's relay log for 2026-10-02 has 108 lines mentioning count_tokens, so that first call lands on a normal request.

Measured and deliberately unchanged

• JSON parsed and serialized several times per streamed delta, including WebSearch wrapping an already normalized stream. Opus: relay CPU per delta 43.9 µs (gpt), 37.1 µs (chat), 39.1 µs (native). GPT-6: an 8,192-delta Chat pipeline p50 was 38.05 ms without WebSearch and 58.99 ms with it. CPU only; Opus found it not noticeable at Copilot's token rates, and removing it touches every stream translator and the terminal checks.
• WebSearch keeps forwarded chunk objects until the terminal: 14,163,048 extra heap bytes at 32,768 deltas (GPT-6), released at the terminal. They back preamble, sibling-tool and refusal handling.
• Catalog discovery after a base-URL reload: 12 concurrent requests made 12 /models calls; warm batches made none (GPT-6). Cold path only. One shared discovery across request snapshots would tie every waiter to the first request's cancellation and capture.
• consola's fancy reporter on non-TTY stdout: 365 ms of the 2401 ms profile (Opus). Changing it changes the console and proxy.out.log format, a separate decision.
• Relay keep-alive toward Claude Code stays at Node's 5 s default: clients that honour the Keep-Alive hint close first, and a loopback reconnect is cheap.
• count_tokens counting stays synchronous after the tokenizer preload; moving it to a worker is a larger change.

Already fine

• Streaming pace at 5 ms between deltas: chunk forwarding p50/p95 0.54/0.90 ms (gpt), 0.43/0.70 ms (chat), 0.41/0.61 ms (native); no buffering or flush delay (Opus).
• Back-to-back requests reuse the upstream connection; no per-request disk reads of the token or config; config snapshots, catalog lookup and endpoint selection do not show in profiles; about 12 KB retained per request, released within upstreamTimeoutSeconds.

Plan

1. Serialize log writes through one queue: timestamp at the call, keep one handle per dated file, check the directories and file when opening, lstat the file once per batch, and write each batch in bounded chunks. Keep: one entry per physical line, rotation at local midnight, retention by filename date, 0700/0600, refusal of symlinks and hard links, identical redacted text in both sinks, a failed write never failing a request, and flushLogs waiting for queued writes.
2. Bump undici to ^7.30.0.
3. Count capture-off request bytes without copying the body.
4. Normalize tool schemas copy-on-write; never mutate the client's schema.
5. Keep idle upstream connections open longer, within Copilot's measured idle limit.
6. Load the configured models' tokenizers at startup.

Acceptance

• Regression tests for each change.
• Before/after benchmark with the reviewers' scripts.
• GPT-6 and Opus review the change.
• Wiki EN and ZH updated.