V2_DEEP_ANALYSIS §3.1 (execution_mode distribution) and §3.2 (path-level
latency vs DP) had hand-typed tables with approximate latencies (e.g.
"~1.0s") and required readers to mentally compare 5+ rows × 5 columns.
Both sections now reference generated PNG figures derived directly from
the v2 + DP metrics.jsonl files.
§3.1 figure (v2_execution_mode_distribution.png):
Horizontal bar chart, log x-axis. 4076 direct-to-D fast-path requests
(green) dwarf the rest by ~30x; the long tail of slow / fallback /
failure modes is visible at one glance. Counts and percentages
annotated on each bar.
§3.2 figure (v2_path_level_latency.png):
Grouped bar chart, log y-axis. Per-path TTFT p50 / TTFT p99 / Lat p50
with exact numeric labels (no more "~1.0s" approximations). Sample
counts annotated below each path. Quick visual reads:
- KVC fast path TTFT p50 41ms vs DP 92ms (2.2x faster)
- KVC reseed TTFT p99 5.12s vs DP 0.43s (12x slower) -- the cost
- KVC no-d-capacity TTFT p99 7.65s (worst case)
Bundled:
- scripts/analysis/plot_v2_path_breakdown.py -- the script that
generates both figures; rerunable when v2 data changes.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
The old filter `if row.latency_s is not None` accepted SGLang's fast
input-length-aborts (latency_s ~ 0.08s, finish_reason='abort/BadRequest')
as if they were successful zero-cost requests. This deflated mean/p50
of any run where the model rejected oversized inputs.
Impact on existing comparisons (ts=1 4-run validation + v2):
KVC v2 has 40 aborts + 5 ReadTimeouts (was reported as just 5);
DP 4w has 67 aborts (was reported as 5).
Both runs have abort behavior; the asymmetry (40 vs 67) is purely from
SGLang's mem-fraction-derived max-input-len: KVC decode-only worker gets
~10 GB free GPU mem -> max-input=92098, DP fused worker gets ~9 GB ->
max-input=87811, because DP also needs chunked-prefill workspace.
The KVC-vs-DP latency-win direction holds and widens slightly under the
fixed filter (lat mean delta: -0.8% -> -1.4%); see V2_DEEP_ANALYSIS_ZH
§4.3 for the recomputed table.
Changes:
- metrics.py: new _is_failed_request(row) helper; latency/ttft/tpot
stats now exclude both errors and aborts. New summary fields
abort_count and failure_count expose the counts directly.
- scripts/analysis/recompute_summary.py: re-derives summary.json from
existing metrics.jsonl using the fixed code, with optional --diff
against the old buggy summary for inspection.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Hostile audit of the original report flagged three load-bearing errors:
1. held_tokens semantic was inverted. session_held_tokens() at
session_aware_cache.py:278-282 sums (kv_allocated_len - cache_protected_len)
per slot, i.e. slot-private (NOT in radix tree). So "other = cap - held -
avail" actually CONTAINS the radix-tree protected prefix cache (likely the
single biggest component for shared agentic prefixes), not just running
batch + in-flight as the original report claimed.
2. Admission-race causal hypothesis for the 415 EXP2+profile errors is
contradicted by the data: 414/415 errors have kv_transfer_blocks > 0 — they
passed admission and died downstream ("generate stream ended before
producing any token", raised by the client when a 200 response had an empty
stream).
3. Polling deconfound was too quickly dismissed. Mode counts shift ~1:1
(session-cap-fb -356 / kvcache-centric +406), and /server_info is not a
passive read — it dispatches into the scheduler main loop and iterates
every session slot.
Plus: per-D error% confounded by sticky session affinity (only 18 unique
sessions cause 415 errors, decode-3 had 0 errors only because no high-error
session landed there); decile 10 "recovery" was an equal-time binning
artifact (24.5% under equal-count); v5 vs v5+profile time gap was 21h not
6h; p50/p90 latency comparison is N=1.
Rewritten report (docs/V5_PROFILE_INVESTIGATION_ZH.md) marks each correction
with ⚠️ and demotes admission-race to one of four hypotheses (H1-H4).
Action items split into P0 (verify, must do first) and P1 (instrument):
P0 — scripts/sweep_tp1_v5_baseline_rerun_exp2.sh runs 3x v5 baseline EXP2
(no polling, identical config to the original v5 run) to test whether the
9-error baseline result is reproducible. If 3 runs give ~9 errors and
profile gives 415, polling is the leading suspect. Currently running
in background.
P1 — scheduler.py:_compute_pool_breakdown_for_diagnostics adds a read-only
"pool_breakdown" dict to /server_info covering: radix_evictable_tokens,
radix_protected_tokens, slot_private_held_tokens, session_slot_count,
running_batch_{reqs,kv_tokens}, transfer_queue_{reqs,tokens},
prealloc_queue_{reqs,tokens}, retracted_queue_{reqs,tokens}. With these,
"unaccounted = cap - sum(known)" exposes true leakage. replay.py captures
all fields into the per-tick row; analyzer prints the decomposition and
gracefully handles old timeseries (prints "P1 instrument absent").
Mock-tested end-to-end. SGLang patch is read-only and does not affect
admission/scheduling. Old v5+profile data still analyzes correctly.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
v5 dropped errors but pushed session-cap fallback to 46-51%. Before adding
v6 mitigations we need to attribute that capacity loss to one of:
(a) active sessions — real footprint
(b) idle-evictable sessions — LRU not aggressive enough
(c) prefill backup blocks / in-flight / fragmentation — release timing
Without this it's all guessing. Plumb a 1Hz poller into replay that hits
each P/D worker's /server_info, captures session_cache + memory_usage, and
writes a per-worker time-series JSONL to <run_dir>/d-pool-timeseries.jsonl.
Off by default (--pool-poll-interval-s 0); v5+profile sweep enables it at
1.0s. Per-tick HTTP cost is ~8 parallel /server_info calls — negligible
relative to the 50min run.
Analyzer (scripts/analysis/analyze_pool_timeseries.py) decomposes each D's
capacity into active_held / idle_evictable / other (= cap-held-avail, the
backup-blocks bucket) / free, and reports session residency churn across
workers as a starvation/thrashing signal.
Mock-tested poller end-to-end (cancellation clean, file flushed, sessions
captured); analyzer validated against synthetic timeseries.
Next: run scripts/sweep_tp1_v5_optD_profile.sh on hardware (~90min), then
analyze results to pick a v6 direction.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Add v4 sweep results and post-mortem analysis showing:
- direct-to-D path: 54.3% (1P7D) / 58.0% (2P6D) of requests now use
KVC cleanly. P50=0.5s and TTFT P50=0.043s; this path beats baseline
8DP across the board (P50 -24%, TTFT P50 -54%, TTFT P90 -79%).
- Overall vs baseline (errors+truncated excluded):
v4 2P6D P50=0.85s vs baseline 0.66s (28% slower).
Reason is not errors -- 35% of requests still hit
fallback-large-append-session-cap, where capacity-based
cap = usable_tokens / target_tokens evaluates to 1-2 (not 16)
for large agentic inputs.
- 9-10% errors on KVC variants are mooncake TCP transfer timeouts,
not SGLang logic bugs. Prefill log shows
"Failed to send kv chunk ... 32s timeout ... session not alive".
Errors concentrate in turn>=31 (large inputs) after run >44.8%.
Track:
- docs/KVC_DEBUG_JOURNEY_V1_TO_V4.md: append v4 results table,
per-mode breakdown, and error root cause.
- scripts/analysis/{analyze_v3,analyze_v4,analyze_errors,compare_no_error}.py
- outputs/qwen3-30b-tp1-v{3,4}*/exp*_summary.json (force-added,
small JSON; metrics.jsonl excluded due to size).
- outputs/qwen3-30b-tp1-v{3,4}*/sweep_results.txt
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
