[HiCache][Observability] Add fine-grained L1<->L2 KV transfer metrics (events / blocks / bytes / duration / bandwidth)

[hxieustc]

Motivation / Problem statement

HiCache constantly moves KV between L1 (GPU) and L2 (CPU host) via write-back (offload, L1→L2) and load-back (onboard, L2→L1), but there is no per-operation accounting of data volume, transfer time, or bandwidth. This makes it hard to understand transfer cost, diagnose load-back stalls, or validate device↔host DMA performance.

Modifications

Instrument the device↔host path in HiCacheController, exposed in logs and Prometheus:

• HiCacheAck extended with token_count, block_count, byte_count, host-side start_time_ns fallback timer; _make_hicache_ack() computes block/byte estimates (incl. draft KV pool).
• record_l1_l2_transfer_complete(direction=...) called at each ack-completion point; logs per-transfer and cumulative stats and feeds the collector. Duration prefers CUDA event elapsed_time, falling back to host wall-clock.
• New HiCacheL1L2TransferMetricsCollector exposes counters + a duration histogram, labeled by direction/src/dst plus TP/DP/PP/attn-CP rank and io_backend.
• Wired into hiradix_cache, unified_radix_cache, hi_mamba_radix_cache, hybrid_cache_controller; ack-queue consumers refactored from tuple-unpacking to attribute access.
• Gated by enable_metrics; the in-process cumulative totals dict is always kept for logging.

Benefits

• End-to-end visibility into HiCache device↔host transfer volume, latency, and bandwidth — per operation and cumulative — in logs and Prometheus/Grafana.
• Diagnose load-back stalls / offload pressure; validate DMA bandwidth across TP/DP/PP and backends.

How to enable

The transfer log lines are emitted whenever HiCache is active (DEBUG level).

The Prometheus metrics are additionally gated by --enable-metrics:

# Logs only (per-transfer + cumulative offload/onboard lines):
python -m sglang.launch_server --model-path <model> --enable-hierarchical-cache

# Logs + Prometheus metrics:
python -m sglang.launch_server --model-path <model> \
  --enable-hierarchical-cache \
  --enable-metrics
# then scrape http://<host>:<port>/metrics for sglang:hicache_l1_l2_transfer_*
--enable-hierarchical-cache is required (this is the L1↔L2 path being measured).

--enable-metrics constructs the HiCacheL1L2TransferMetricsCollector and exposes the sglang:hicache_l1_l2_transfer_* series; without it, no Prometheus objects are created but the cumulative log lines still appear.

Expected output

Logs.

• Before — write-back / load-back are silent (only storage metrics, if any, are logged).
• After — each completed transfer emits a per-op line plus a cumulative line:

# load-back (L2 -> L1):
INFO cache_controller.py: Onboard transfer complete ts_us=1748901234567890 blocks=16 bytes=8388608 xfer_us=742 bandwidth=11.31GB/s src="sglang_hicache::L2" dst="sglang_hicache::L1"
INFO cache_controller.py: Onboard transfer cumulative direction="onboard" total_events=128 total_blocks=2048 total_bytes=1073741824 total_xfer_us=95000 bandwidth=11.30GB/s cumulative src="sglang_hicache::L2" dst="sglang_hicache::L1"

# write-back (L1 -> L2):
INFO cache_controller.py: Offload transfer complete ts_us=1748901234600000 blocks=8 bytes=4194304 xfer_us=410 bandwidth=10.23GB/s src="sglang_hicache::L1" dst="sglang_hicache::L2"
INFO cache_controller.py: Offload transfer cumulative direction="offload" total_events=64 total_blocks=512 total_bytes=268435456 total_xfer_us=26000 bandwidth=10.32GB/s cumulative src="sglang_hicache::L1" dst="sglang_hicache::L2"

Prometheus /metrics.

• Before — no such series.
• After (with --enable-metrics):

# HELP sglang:hicache_l1_l2_transfer_events_total Total number of completed HiCache L1<->L2 KV block transfer events.
sglang:hicache_l1_l2_transfer_events_total{direction="onboard",src="sglang_hicache::L2",dst="sglang_hicache::L1",tp_rank="0",tp_size="1",dp_rank="0",pp_rank="0",pp_size="1",attn_cp_rank="0",attn_cp_size="1",io_backend="kernel"} 128.0
sglang:hicache_l1_l2_transfer_blocks_total{direction="onboard",...} 2048.0
sglang:hicache_l1_l2_transfer_bytes_total{direction="onboard",...} 1.073741824e+09
sglang:hicache_l1_l2_transfer_time_us_total{direction="onboard",...} 95000.0
sglang:hicache_l1_l2_transfer_duration_us_bucket{le="1000",direction="onboard",...} 96.0
sglang:hicache_l1_l2_transfer_duration_us_bucket{le="2500",direction="onboard",...} 124.0
sglang:hicache_l1_l2_transfer_duration_us_count{direction="onboard",...} 128.0
sglang:hicache_l1_l2_transfer_duration_us_sum{direction="onboard",...} 95000.0
# ... and the matching direction="offload" series (src=L1, dst=L2)

Derived bandwidth in Grafana:

rate(...bytes_total[1m]) / rate(...time_us_total[1m])

Correctness

• Ack-queue refactor (tuple → NamedTuple attributes) is mechanical and applied consistently; all construction goes through the keyword _make_hicache_ack() helper.
• Metrics opt-in (enable_metrics); no Prometheus objects created when disabled.
• Byte estimation handles plain HostKVCache, HostPoolGroup wrappers, and the draft pool. Duration degrades to host wall-clock when event.elapsed_time() is unavailable.

Caveats

• byte_count is an estimate (token_count × bytes_per_token); bandwidth is derived from it, not from measured DMA bytes.
• Adds a finish_event.synchronize() in loading_check before recording onboard completion — small sync cost on the load-back path.

Speed Tests and Profiling

Instrumentation is lightweight (counter increments + one log line per completed merged op). The only added synchronization is the load-back synchronize(), on acks that already complete before tree-state updates — no measurable serving impact.

Checklist

• Format your code according to the Format code with pre-commit.
• Add unit tests according to the Run and add unit tests.
• Update documentation according to Write documentations.
• Provide accuracy and speed benchmark results according to Test the accuracy and Benchmark the speed.
• Follow the SGLang code style guidance.

---

CI States

Latest PR Test (Base): ❌ Run #28265436149
Latest PR Test (Extra): ❌ Run #28265435914

[gemini-code-assist]

Warning

You have reached your daily quota limit. Please wait up to 24 hours and I will start processing your requests again!

[ishandhanani]

Tested with HiCache + write_through, forcing offload (write-back) and onboard (load-back) by evicting a 1408-token prefix to host and re-requesting it. Both the Prometheus series and the DEBUG logs work and line up with each other:

# /metrics
sglang:hicache_l1_l2_transfer_events_total{direction="offload",...} 9
sglang:hicache_l1_l2_transfer_blocks_total{direction="offload",...} 198
sglang:hicache_l1_l2_transfer_bytes_total{direction="offload",...}  1.453e9
sglang:hicache_l1_l2_transfer_events_total{direction="onboard",...} 1
sglang:hicache_l1_l2_transfer_blocks_total{direction="onboard",...} 22   # 1408 tokens // page_size 64 = 22

# DEBUG log
Onboard transfer complete blocks=22 bytes=161480704 xfer_us=24254 bandwidth=6.66GB/s src="sglang_hicache::L2" dst="sglang_hicache::L1"
Onboard transfer cumulative direction="onboard" total_events=1 total_blocks=22 total_bytes=161480704 ...

block_count matches token_count // page_size exactly and the cumulative log totals match the counters. Nice addition. A few things inline — the first is a hard break for a config this PR doesn't cover.

[ishandhanani]

Adding these 4 non-default fields to HiCacheAck means every consumer that unpacks it positionally has to be updated. The radix-cache controllers here are all converted, but two sites that still do the old 3-tuple unpack were missed:

• python/sglang/srt/disaggregation/decode_kvcache_offload_manager.py:205 — _, finish_event, ack_list = self.cache_controller.ack_write_queue.pop(0) will raise ValueError: too many values to unpack (expected 3) once these acks have 7 fields (decode-side KV offload path).
• test/registered/unit/mem_cache/test_unified_radix_cache_unittest.py:1350 — same 3-tuple unpack of ack_load_queue.

(Defaults wouldn't help — unpacking a 7-tuple into 3 names fails regardless — so those two consumers need the ack.finish_event / ack.node_ids treatment too.)

[hxieustc]

Good catch, thanks. The main branch evolves, so I did a rebase. After the rebase there are a few more stale consumers too, not just the two originally listed. I have updated all ack_write_queue / ack_load_queue consumers to use ack.finish_event and ack.node_ids, and update the tests that still mock the old 3-tuple shape.

[ishandhanani]

record_l1_l2_transfer_complete runs on every transfer regardless of --enable-metrics: _transfer_elapsed_us calls start_event.elapsed_time(finish_event) (a CUDA call) and the hicache_l1_l2_transfer_totals dict is updated each time; only the Prometheus .inc() is gated on the collector. So it's not quite 'zero overhead otherwise' as the description says — there's a per-transfer elapsed_time() even with metrics and debug logging both off. Could early-return / skip the elapsed_time when not self.enable_l1_l2_transfer_metrics and not logger.isEnabledFor(logging.DEBUG).

[hxieustc]

Agreed. I added an early return in record_l1_l2_transfer_complete when both metrics are disabled and DEBUG logging is off, before calling _transfer_elapsed_us. I also gated the cumulative debug totals behind the same debug check so the normal path stays effectively no-op.

[vuuihc]

Related to this elapsed_time() path, I think there may also be a timing-semantics issue: these ACK events appear to be created via device_module.Event() without enable_timing=True.

In PyTorch, torch.cuda.Event defaults to enable_timing=False, so the event is usable for readiness/query/sync but is not a timing event. If elapsed_time() fails and falls back to host perf_counter_ns(), this metric can mix device-side DMA timing with host wall-clock timing, including scheduling/polling/ACK-processing delay.

This is related to the issue addressed in #26411. It may be worth separating readiness events from timing events here too, especially since bandwidth is derived from the duration.

[ishandhanani]

This write_back=True (blocking drain) branch doesn't call record_l1_l2_transfer_complete, while the non-blocking branch just below does — and hiradix_cache.py does record in its equivalent blocking branch (hi_mamba_radix_cache.py also omits it). So flush-path offloads are undercounted inconsistently across the three caches. Minor, but worth making uniform.

[hxieustc]

Makes sense. I made the blocking drain paths consistent by calling record_l1_l2_transfer_complete(direction="offload", ack=ack) after synchronizing each ack in both unified_radix_cache.py and hi_mamba_radix_cache.py, matching hiradix_cache.py.

[ishandhanani]

transfer_time_us_total (and transfer_events_total above) duplicate the histogram's _sum / _count — I confirmed they match exactly in my run (events 9 == duration_us_count 9; time_us 94853 == duration_us_sum 94853). Could drop the two counters and read _sum/_count off transfer_duration_us. The blocks/bytes counters are the useful cumulative additions. Minor.

[hxieustc]

Agreed, the histogram already gives _count and _sum, so keeping separate event/time counters is redundant. I dropped hicache_l1_l2_transfer_events_total and hicache_l1_l2_transfer_time_us_total, while keeping the blocks/bytes counters and duration histogram.

[ishandhanani]

Re-tested the updated branch (23c4982f5, Qwen3-0.6B on 1x L40S, HiCache + write_through + --enable-metrics --log-level debug). Everything flagged in the previous review checks out now:

• Decode-side ack consumers fixed (test_specv2_kvcache_offloading.py: 13/13 pass), write-back flush paths record, redundant counters removed, and the gating works — without --enable-metrics at INFO level there are zero DEBUG lines and zero series while serving load-back traffic.
• Counters are exact: bytes/token = 114688 (= 2 x 28 layers x 8 KV heads x 128 dim x 2B), onboard 24 blocks for a 1536-token load-back, and the DEBUG cumulative totals match Prometheus _count/_sum to the digit under a 256-request load.

Two remaining issues:

1. The duration/bandwidth numbers are host wall-clock, not device time. No event is created with enable_timing=True, so elapsed_time() always raises on CUDA and the except fallback silently measures enqueue -> ack-poll latency. An idle 161 MB onboard logged xfer_us=5751205 (5.75 s, 0.03 GB/s) for a ~7 ms DMA because the ack sat until the next request polled loading_check.
2. enable_metrics is only threaded into HiRadixCache's controller — the disagg-decode manager and all five HybridCacheController sites in hybrid_pool_assembler.py default it to False, so hybrid/unified/disagg stacks never emit the new Prometheus series.

Fix + before/after evidence: hxieustc#2. With it applied, the same idle-gap onboard reports xfer_us=6781 (25.98 GB/s), and the unified stack (SGLANG_ENABLE_UNIFIED_RADIX_TREE=1) emits the full series with exact counts.

[nvpohanh]

/tag-and-rerun-ci