fix: HIGH severity measurement bugs in KV cache benchmark

[FileSystemGuy]

Summary

This PR fixes 6 HIGH severity bugs identified in a broad codebase scan (BROAD_SCAN.md) in the KV cache benchmark subsystem. All bugs directly corrupt reported storage metrics — inflating bandwidth, misattributing latency, or dropping data from reports. Changes are targeted fixes with no refactoring.

---

KVC-1 — Decode path reads full KV block N× per request; inflates bandwidth by N×

File: kv_cache_benchmark/kv_cache/benchmark.py

The batched decode loop called cache.access_cache() num_batched_reads times (= ceil(generate_tokens / decode_batch_size), default batch_size=32). Each call read the entire KV block from storage. In a real LLM decode phase the block is fetched once into GPU SRAM; subsequent steps update it in place — they do not re-read the full block from storage per batch. For 512 generate tokens with the default batch size this read the full block 16 times, inflating total_read_bytes, reported read bandwidth, read IOPS, and storage latency by 16×.

Fix: Replace the loop with a single access_cache() call.

---

KVC-2 — GPU simulation sleep included in end-to-end latency metric

Files: kv_cache_benchmark/kv_cache/benchmark.py, kv_cache_benchmark/kv_cache/models.py

time.sleep(generation_latency) executed between the last I/O call and request.complete_time. As a result, end_to_end_latencies (derived from total_latency_ms = complete_time - submit_time) conflated true storage I/O latency with synthetic GPU simulation time. E2E latency percentiles were meaningless as a storage metric.

Fix:

• Added storage_complete_time: float = 0 field to InferenceRequest, captured immediately before the sleep.
• Added storage_e2e_latency_ms property: (storage_complete_time - submit_time) * 1000.
• end_to_end_latencies now records storage_e2e_latency_ms (I/O only).
• Added system_e2e_latencies to retain the GPU-inclusive view via total_latency_ms.

---

KVC-3 — Cross-clock skew between benchmark window and request timestamps

File: kv_cache_benchmark/kv_cache/benchmark.py

benchmark_start used time.time() (wall clock) while request.complete_time and request.start_time use time.perf_counter() (monotonic). On long runs an NTP step adjustment could shift time.time() relative to perf_counter, causing actual_duration to diverge from the true elapsed window and producing incorrect throughput calculations.

Fix: Switch benchmark_start and actual_duration in run_benchmark() to time.perf_counter(), matching the clock used by all request timestamps.

---

KVC-4 — np.load() includes numpy deserialization in reported disk I/O time

File: kv_cache_benchmark/kv_cache/backends.py

np.load(path, allow_pickle=False) performs both disk I/O and numpy array deserialization in a single inseparable call. The measured device_time therefore included numpy header parsing and array reconstruction in addition to the actual read from disk. The subsequent np.array(data) defensive copy was attributed to host_time but is pure CPU overhead with no storage meaning.

Fix: Switch the NVMe backend from .npy to raw binary:

• Write: tensor.numpy().tofile(str(path)) — raw bytes, no header overhead.
• Read: open(path, 'rb').read() for pure disk I/O (device_time), then np.frombuffer(...).reshape(...) for CPU-only array reconstruction (host_time). Shape and dtype are stored in self.metadata[key].
• File extension changed from .npy to .bin throughout.

---

KVC-5 — storage_tokens_processed undercounts by tensor_parallel factor

File: kv_cache_benchmark/kv_cache/cache.py

num_tokens = entry_size / self.model_config.kv_cache_size_per_token — entry_size is the TP-sharded per-rank size (1/tensor_parallel of the full entry), but kv_cache_size_per_token is the full unsharded value. Dividing a sharded byte count by an unsharded per-token size undercounts storage_tokens_processed by a factor of tensor_parallel for every NVMe read when tensor_parallel > 1.

Fix:

sharded_bytes_per_token = kv_cache_size_per_token / max(1, self.tensor_parallel)
num_tokens = entry_size / sharded_bytes_per_token

---

KVC-6 — start_time captured at dequeue but never used; no service latency reported

Files: kv_cache_benchmark/kv_cache/benchmark.py, kv_cache_benchmark/kv_cache/models.py

request.start_time was set when a worker dequeued a request (after queue wait time) but was never referenced in any latency metric. There was no way to distinguish I/O service time from queue wait time in the output. Tail latency driven by queue buildup versus actual slow storage was indistinguishable.

Fix:

• Added service_latency_ms property to InferenceRequest: (complete_time - start_time) * 1000.
• Added 'service_latencies': [] to the results initialization.
• Records service_latency_ms in the results-recording block so P50/P99 service latency (dequeue-to-complete, excluding queue wait) appears in final stats.

---

Test plan

• Run existing unit tests: pytest tests/unit -v
• Run mlpstorage kvcache run on a small dataset and verify reported bandwidth is not inflated (KVC-1: previously 16× over for 512 token requests with default batch_size)
• Verify end_to_end_latencies in results no longer includes generation sleep time (KVC-2)
• Verify service_latencies section appears in KV cache benchmark output (KVC-6)
• Verify NVMe backend reads/writes .bin files and results match before/after (KVC-4)

[github-actions]

MLCommons CLA bot All contributors have signed the MLCommons CLA ✍️ ✅

[dslik]

I do not think the logic behind KVC-1 is correct.

Metrics from KVC-2, KVC-5, KVC-6 are not used in MLPerf 3.0.

KVC-4 needs more analysis.

These code changes need a more detailed analysis (ideally by the code author) and also requires additional testing.

[hazemawadalla]

hey Curtis, please give me a chance to review these closely