row/BENCH-35B-TTFT: TTFT deficit attributed to serving INTAKE (diag instrument, no lever yet) - #32
Merged
Merged
Conversation
The async serving frontend calls OutputProcessor::process_outputs with
iteration_stats == nullptr (the production /metrics endpoint is deliberately
404, api_server.cpp:762-765), so the per-request queue/prefill/decode split
that stats.py exposes as vllm:request_{queue,prefill,decode}_time_seconds is
invisible on our serving path. This blocks the queue-vs-execution TTFT
attribution the 35B binding grid needs (TTFT is 2-6% worse than throughput at
c>=2 and worsens with concurrency; that split decides whether the lever is
scheduler admission, front-end overhead, or prefill execution).
VT_TTFT_DUMP=1 emits one "TTFTSPLIT rid=... queued=.. prefill=.. decode=..
e2e=.." stderr line per finished request, reconstructed directly from the
event-populated req_state timestamps (identical arithmetic to stats.py:459-476,
which the async path already fills unconditionally since log_stats_ defaults
true). Reads only; generation is byte-identical when the env var is unset
(one function-local static getenv, no behaviour change on the compute path).
FOLLOWING_AGENTS_PROTOCOL
Assisted-by: Claude Code:claude-opus-4-8 [ClaudeCode]
Empirically, the async serving frontend produced all-zero TTFT-split rows (queued=prefill=decode=0, e2e negative): two gaps, both the SERVE-RESPONSE- METRICS residual. (1) EngineCore::step_with_batch_queue never stamps engine_core_outputs.timestamp (the synchronous step() does, core.cpp:85), so engine_core_timestamp is 0 and first_token_ts/last_token_ts/TTFT are wrong. (2) AsyncLLM::RunOutputHandler passes iteration_stats=nullptr to process_outputs, which gates the ENTIRE per-request timing block (event folding that sets queued_ts/scheduled_ts, first_token_ts, last_token_ts, num_generation_tokens — output_processor.cpp:379-426), so req_state timing is never populated on the serving path. Both are fixed only under VT_TTFT_DUMP (function-local static getenv): the async timestamp stamp and a throwaway IterationStats so the timing block runs and the dump reads real intervals. Unset = instruction-identical to production (nullptr path, no stamp); generation is byte-identical either way. This is a diagnostic enabler; the durable fix is to wire the async /metrics stat logger (a separate observability feature row). FOLLOWING_AGENTS_PROTOCOL Assisted-by: Claude Code:claude-opus-4-8 [ClaudeCode]
… dump Localizes the serving-layer frontend cost: intake = queued_ts - arrival_time is the async engine-core intake wait (OutputProcessor registration to the scheduler QUEUED event, same steady clock), isolating the input-queue-drain / step-cadence ingress cost from tokenize (before arrival_time) and egress. Same VT_TTFT_DUMP gate; reads only. FOLLOWING_AGENTS_PROTOCOL Assisted-by: Claude Code:claude-opus-4-8 [ClaudeCode]
Measured same-tool (vllm bench serve + /metrics vs a VT_TTFT_DUMP per-request split) on the 35B online-serve workload. The concurrency-growing TTFT deficit (TTFT ratio c2 0.95 -> c32 0.92) is NOT the prefill kernels or the scheduler queue (both at/near parity) but the async engine-core INTAKE (arrival->QUEUED admission latency), +34..103ms and growing 20x c2->c32, plus a ~flat prefill glue gap (+82..92ms = the task #61 residual). Both engines run async scheduling (async-vs-sync refuted). Appended benchmark-record + anchored state entry; refreshed NOW (in budget). Evidence dgx:~/work/q35-regrid/ttft-attr/. FOLLOWING_AGENTS_PROTOCOL Assisted-by: Claude Code:claude-opus-4-8 [ClaudeCode]
New read-only observability env var introduced by the async TTFT-split instrument. Documented under the Diagnostic section (generation byte-identical when unset). Satisfies check-env-doc. FOLLOWING_AGENTS_PROTOCOL Assisted-by: Claude Code:claude-opus-4-8 [ClaudeCode]
# Conflicts: # .agents/NOW.md # .agents/benchmark-record.md # .agents/state.md
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Finding
The 35B TTFT deficit (0.93-0.98x, worsening with concurrency) decomposes server-side (c32, ms): INTAKE (arrival→QUEUED, engine-core admission) ours 612 vs vLLM 509 = +103ms and growing 20x from c2→c32; PREFILL +92ms flat (the known task-#61 glue residual); QUEUE (queued→scheduled) ours BETTER by 34ms. At c4 we WIN throughput while LOSING TTFT — TTFT is not slaved to drain rate. Kernels and scheduler are at/near parity.
Mechanism:
EngineCoreProc::run_busy_loop(core_proc.cpp:54-63) drains the input queue once perstep_with_batch_queue(core.cpp:115), so a newly-arrived request waits ~step-cadence, which grows with batch size. vLLM drains viaEngineCoreProc._process_input_queue(core.py:1259-1298). Ruled out: TCP_NODELAY, tokenizer locks, egress, async-vs-sync scheduling (both async).Contents (diagnostics + records only)
VT_TTFT_DUMP-gated per-request TTFT-split dump on the async path (byte-identical unset) — also surfaces a SERVE-RESPONSE-METRICS residual: production async serving passesiteration_stats=nullptrand never stampsEngineCoreOutputs.timestamp, so per-request timing is untracked there.VT_TTFT_DUMPdocumented in ENVIRONMENT.Gates
SACRED
test_qwen36_paged_enginePASS on the instrumented binary; agent-preflight exit 0; evidencedgx:~/work/q35-regrid/ttft-attr/.Next (separate work)
Lever A: mirror vLLM's input-drain cadence in the busy loop (needs finer timing first, being pursued on a stacked branch).
🤖 Generated with Claude Code
https://claude.ai/code/session_014fZAcg1WcU8V629k6HWKys