feat(timing): split TTFT into api-server and client portions - #1228
Conversation
Time-to-first-token previously lumped in-process request building (message serialization, param assembly) together with network + server latency, making it impossible to tell whether a slow turn was the client or the API server. Add an `onRequestSent` hook to kosong's GenerateOptions, fired by every provider immediately before it dispatches the network call. The window from request start to dispatch is attributed to the client; the window from dispatch to the first streamed token is attributed to the API server. The split flows through the step.end / turn.step.completed events (and therefore wire.jsonl) and is surfaced in three places: - KIMI_CODE_DEBUG=1: `TTFT: 2.5s (api 2.4s + client 100ms)` - session log: new `llm response` line with the timing breakdown - vis: firstToken/api + firstToken/client rows and timeline label The split is omitted (total only) when a provider does not report the boundary, preserving backward compatibility.
🦋 Changeset detectedLatest commit: fea78a5 The changes in this PR will be included in the next version bump. This PR includes changesets to release 1 package
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
commit: |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 70b5469b85
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| const timing = response.streamTiming; | ||
| if (timing === undefined) return; | ||
| log.info('llm response', { | ||
| turnStep: `${turnId}/${String(step)}`, |
There was a problem hiding this comment.
For session log consumers that correlate the new llm response record with existing llm config/llm request records, this emits turnStep as turnId/step while the existing request logger uses turnId.step (paramsForAttempt produces values like 0.1). That makes the new timing line fail exact-key joins/filtering with the rest of the LLM log entries; emit the same dot-formatted value here.
Useful? React with 👍 / 👎.
| ...(timing.requestBuildMs !== undefined ? { requestBuildMs: timing.requestBuildMs } : {}), | ||
| ...(timing.serverFirstTokenMs !== undefined | ||
| ? { serverFirstTokenMs: timing.serverFirstTokenMs } | ||
| : {}), |
There was a problem hiding this comment.
The repository-level /workspace/kimi-code/AGENTS.md says optional object properties should be passed as undefined directly instead of using conditional spreads. These newly added log fields use conditional spreads for optional values, so this patch violates the local rule; make them direct properties such as requestBuildMs: timing.requestBuildMs to keep the object shape consistent.
Useful? React with 👍 / 👎.
Time-to-first-token now reports a client/server split, but the slow part of a long turn is the decode window (inter-token streaming), which was still a single opaque number. Profiling long sessions showed decode throughput halving over a session's lifetime independent of context size, which the synchronous per-chunk stream pipeline can cause: kosong awaits the host callback for every streamed part, so a loaded main thread throttles how fast tokens are pulled off the wire. Account for this directly in the stream loop: the time awaiting the next part (server + network) versus the time spent processing each part in-process (deep copy, host callback, part merge). The split is reported through onStreamEnd and flows through the step.end / turn.step.completed events (and wire.jsonl) into the same three surfaces as the TTFT split: - KIMI_CODE_DEBUG=1: `TPS: 40.0 tok/s (200 tokens in 5.0s; server 4.6s + client 400ms)` - session log: serverDecodeMs / clientConsumeMs on the `llm response` line - vis: streamDuration/server + streamDuration/client rows and timeline label A large, growing client share confirms host-side throttling; a dominant server share points at the server/connection. The per-chunk accounting is wrapped in try/finally so it stays correct across `continue` and aborts, and is omitted when the stream reports nothing.
1 participant
Why
Time-to-first-token (TTFT) previously lumped together two very different things: the in-process work kimi-code does to build a request (serializing the message history, assembling params) and the network + API-server latency until the first token. When a turn felt slow, there was no way to tell whether the client or the server was responsible — exactly the question that came up while investigating slow sessions.
What
Add an
onRequestSenthook to kosong'sGenerateOptions, fired by every provider (kimi,openai-legacy,openai-responses,anthropic,google-genai) immediately before it dispatches the network call. TTFT is then split across that boundary:The split flows through
step.end/turn.step.completed(and thereforewire.jsonl) and shows up in three places:KIMI_CODE_DEBUG=1:TTFT: 2.5s (api 2.4s + client 100ms)llm responseline withttftMs/requestBuildMs/serverFirstTokenMs/streamDurationMs/outputTokensfirstToken/api+firstToken/clientdetail rows and a timeline labelWhen a provider does not report the boundary, the split is omitted and only the total TTFT is shown — fully backward compatible.
Boundary note
The provider SDKs' own JSON serialization happens inside
create(), so it is counted in theapiportion (typically tens of ms). This is the known trade-off of placing the marker just before the SDK call rather than wrappingfetch.Test
typecheckpasses across all packageslint: 0 errorsdebug-timing), split computation + graceful degradation when no boundary is reported (kosong-llm), snapshot normalizer, protocol type assertions, vis analysiscli/update/preflight.test.ts— confirmed failing on the base via stash;packages/server/test/fileLaunch.test.ts— a Windows-path assertion in an untouched package)