[Feature] Per-request Observability: TTFT Breakdown + HiCache Metrics

[grissomsh]

Problem

Currently, SGLang lacks per-request observability in two key areas:

1. TTFT cannot be decomposed — there's no way to know how much of TTFT is queue wait, schedule delay, or GPU forward time. Operators can only see total TTFT, making prefill performance tuning guesswork. This problem exists regardless of whether HiCache is enabled.
2. HiCache tier performance is invisible — with three-tier KV cache (GPU→CPU→NVMe) enabled, L2 DMA time, L3 prefetch I/O time, and per-tier hit/miss counts are not available per-request. No Prometheus metrics exist for cache hit rates, prefetch latency distributions, or eviction pressure.

Proposed Solution

A lightweight per-request trace + Prometheus metrics system covering both TTFT decomposition and HiCache observability, implemented across 5 files.

Part A: Per-request Trace (JSON log, debug level)

One JSON line per request at logger.debug level. The TTFT fields work universally; HiCache fields are gated by --enable-hierarchical-cache:

{
  "rid": "b3f3e0e1...",
  "prompt_tokens": 136921,
  "input_tokens_cache_hit": 119040,
  "input_tokens_no_cache_hit": 17881,
  "output_tokens": 4096,
  "L1_hit": 0,
  "L1_hit_pct": 0.0,
  "L2_hit": 119040,
  "L2_hit_pct": 86.9,
  "L3_hit": 0,
  "L3_hit_pct": 0.0,
  "L3_pf_alloc_ms": 0,
  "L3_pf_io_ms": 0,
  "L3_pf_tree_ms": 0,
  "queue_ms": 9.9,
  "schedule_ms": 2.4,
  "forward_ms": 1174.6,
  "TTFT_ms": 78907.9
}

TTFT Decomposition (universal — works with or without HiCache)

TTFT ≈ queue_ms + schedule_ms + forward_ms

Field	Source	Meaning
queue_ms	time_stats.scheduler_recv_time → wait_queue_entry_time	Tokenizer → enqueue
schedule_ms	time_stats.wait_queue_entry_time → forward_entry_time	Wait in queue + chunk waits
forward_ms	time_stats.forward_entry_time → prefill_finished_time	GPU prefill compute

HiCache Fields (gated by --enable-hierarchical-cache)

Per-tier hit token counts with percentages, L3 prefetch phase breakdown.

Why no L2 DMA time? cache_controller.load() is asynchronous — it allocates GPU memory and queues the DMA operation, then returns immediately. The actual DMA runs on a CUDA stream in a background thread (start_loading()). CPU-side time.perf_counter() cannot capture the DMA completion time. Since DMA bandwidth is fixed (PCIe 5.0 × 16 ≈ 64 GB/s), the transfer time is a known constant: L2_hit_tokens × 48 KB/token ÷ 64 GB/s. L2 token count alone is sufficient to characterize L2 performance.

L3 prefetch phase breakdown (key finding made possible by this instrumentation):

Phase	P50	Meaning
L3_pf_alloc_ms	0.1ms	Host memory allocation
L3_pf_io_ms	91ms	Pure NVMe→CPU I/O
L3_pf_tree_ms	0.4ms	Radix tree insertion

Without this breakdown, the total L3 prefetch time is often conflated with scheduler queue delays (~2.4s vs actual I/O ~91ms).

Part B: Prometheus Metrics

6 Histograms + 2 Counters exposed at /metrics:

Metric	Type	Description
sglang:hicache_l1_hit_tokens	Histogram	L1 hit tokens per request
sglang:hicache_l2_hit_tokens	Histogram	L2 hit tokens per request
sglang:hicache_l3_hit_tokens	Histogram	L3 hit tokens per request
sglang:hicache_l3_prefetch_seconds	Histogram	L3→L2 prefetch total duration
sglang:hicache_l3_pf_alloc_seconds	Histogram	L3 prefetch: alloc phase
sglang:hicache_l3_pf_io_wait_seconds	Histogram	L3 prefetch: I/O phase
sglang:hicache_l3_pf_tree_insert_seconds	Histogram	L3 prefetch: tree insert phase
sglang:hicache_cached_input_tokens_total	Counter	Cumulative cached tokens
sglang:hicache_uncached_input_tokens_total	Counter	Cumulative uncached tokens

Part C: Eviction Metrics

RadixCacheMetricsCollector.increment_eviction_num_tokens() called from cache eviction code paths (previously unused in HiMambaRadixCache):

• L1→L2 eviction counter (tokens evicted from GPU to CPU)
• L2→L3 eviction counter (tokens evicted from CPU to NVMe)

Write-back timing is excluded for the same reason as L2 DMA — cache_controller.write() is also asynchronous.

Implementation Scope

5 files, ~100 lines of instrumentation total:

File	Change
scheduler.py	_hicache_trace_one_request() method: trace JSON + metrics observe
metrics_collector.py	7 HiCache Histograms + 2 Counters
hi_mamba_radix_cache.py	L2/L3 timing in load_back/write_backup/evict/evict_host
hiradix_cache.py	Same for MHA models
cache_controller.py	_page_transfer I/O timing via try/finally

Compatibility

• TTFT decomposition fields work universally (no flag required). HiCache fields gated by --enable-hierarchical-cache
• Trace output at logger.debug level only (no overhead at default info level), tp_rank == 0 only
• HiCache metrics guarded by enable_metrics and --enable-hierarchical-cache
• No breaking changes to existing APIs

Related

• #10916 — Unified Observability Interface proposal (tracing + metrics + TimeStat). This proposal can serve as a concrete implementation of that unified interface for TTFT and HiCache.
• #13511 — Request Tracing Roadmap. This proposal fills the "HiCache tracing" item under "Tracing for uncovered engine components."
• PRs SGLang Tracing: Add trace-level, trace-module, and unify tracing/request-stage-metrics #13152, Refactor: observability code cleanup #17862 — trace-level/module unification (compatible approach)

[ishandhanani]

We have the following in flight

1. split #cached-token into tiered #cached-token-device / #cached-token-host / #cached-token-storage [Observability] Break down prefill #cached-token into device / host / storage tiers #26976
2. fine-grain data transfer statistics for L1<->L2 (both DEBUG logs and /metrics) [HiCache][Observability] Add fine-grained L1<->L2 KV transfer metrics (events / blocks / bytes / duration / bandwidth) #26974

[Cerdore]

@ishandhanani Thanks for the context! It looks like the per-request TTFT breakdown trace (Part A — queue_ms / schedule_ms / forward_ms JSON debug log) isn't covered by either PR yet. I'd like to pick that up.

For the remaining Part B+C items (L2↔L3 transfer metrics, eviction counters, per-request hit histogram), they seem like natural follow-ups to #26976 and #26974 once merged. Happy to help with those as well if needed.

[kpham-sgl]

I think this PR #25933 covers Part A

[grissomsh]

Update (2026-06-13): schedule_ms sub-decomposition + L3 pf_io refinement

@kpham-sgl PR #25933 covers the pre-scheduler stages — that's complementary to what follows. Two refinements we made to the scheduler-side trace based on actual use:

1. schedule_ms → idle_in_queue_ms + budget_wait_ms

schedule_ms (= forward_entry_time - wait_queue_entry_time) bundles too many things. By adding first_prefill_attempt_time (set when PrefillAdder first considers the request), we get:

idle_in_queue_ms = first_prefill_attempt_time - wait_queue_entry_time
budget_wait_ms   = forward_entry_time - first_prefill_attempt_time

• idle_in_queue_ms: pure queue wait. Also absorbs L3 prefetch wait — requests with ongoing prefetch are skipped via continue before first_prefill_attempt_time is set.
• budget_wait_ms: time spent retrying after PrefillAdder returns NO_TOKEN (insufficient rem_total_tokens). Directly reflects L1 eviction pressure.

No semantic change to schedule_ms itself, just one new timestamp in SchedulerReqTimeStats.

2. Trace: only L3_pf_io_ms; alloc/tree → Prometheus-only

The three L3 prefetch phases have different diagnostic value per-request:

• L3_pf_io_ms: pure NVMe→CPU read time. Temporal subset of idle_in_queue_ms. Used to distinguish "I/O is slow" vs "queue wait is the bottleneck".
• L3_pf_alloc_ms / L3_pf_tree_ms: alloc and radix tree insert. Usually <1ms; systemic issues are better captured via aggregated Prometheus histograms.

So trace JSON carries only L3_pf_io_ms; all three phases remain in Prometheus (hicache_l3_pf_*_seconds).