Tracing#

Note

--enable-tracing requires --otlp-endpoint to be set. The server will refuse to start if tracing is enabled without an OTLP endpoint, since there is no local fallback for trace export.

When tracing is enabled (--enable-tracing --otlp-endpoint <URL>), the tracing subscriber creates OTel spans from START/END event pairs:

mp.store — from MP_STORE_START to MP_STORE_END
mp.retrieve — from MP_RETRIEVE_START to MP_RETRIEVE_END
mp.lookup_prefetch — from MP_LOOKUP_PREFETCH_START to MP_LOOKUP_PREFETCH_END

Each span carries event metadata as span attributes (e.g. device, stored_count, found_count).

View traces in any OTel-compatible backend such as Jaeger or Grafana Tempo.

# Start Jaeger all-in-one (OTLP gRPC on 4317)
docker run -d --name jaeger \
    -p 16686:16686 -p 4317:4317 \
    jaegertracing/all-in-one:latest

# Start LMCache with tracing
lmcache server \
    --l1-size-gb 100 --eviction-policy LRU \
    --enable-tracing --otlp-endpoint http://localhost:4317

Per-Request Hit-Rate Attributes#

Each session is wrapped in a per-request root span — request for the standard MP path and cb.request for the CacheBlend path — that nests all child spans (mp.store, mp.retrieve, mp.lookup_prefetch) beneath it. When the lookup phase ends, the root span is annotated with OTel attributes that summarise the request-level cache hit rate. Both root spans carry the first three below; the rest are specific to the request span, and cb.request instead carries its own CacheBlend breakdown of hit_tokens (prefix / segmented-prefix / non-prefix).

Attribute	OTel type	Description
`hit_tokens`	`int`	Tokens served from L1+L2 (numerator).
`requested_tokens`	`int`	Chunk-aligned tokens submitted for lookup (denominator).
`hit_rate`	`float`	`hit_tokens / requested_tokens`; `0.0` when the denominator is zero. Stored as a precomputed float because trace UIs (Tempo, Jaeger) cannot derive it from two integer attributes at query time.
`l1_hit_tokens`	`int`	Tokens in the prefix L1 alone could serve, under each object group’s attention window rule. `request` span only.
`l2_hit_tokens`	`int`	Tokens by which L2 extended that prefix. Together with `l1_hit_tokens` this is an exact integer partition of `hit_tokens`. `request` span only.
`l1_hit_rate`	`float`	`l1_hit_tokens / requested_tokens`; `0.0` when the denominator is zero. `request` span only.
`l2_hit_rate`	`float`	`l2_hit_tokens / requested_tokens`; `0.0` when the denominator is zero. Sums with `l1_hit_rate` to `hit_rate` up to float rounding. `request` span only.
`early_exit_reason`	`str`	Which branch of the lookup returned before a prefetch was submitted: `no_gpu_context` or `no_group_layout_descs` (nothing registered for this model / world size), or `empty_chunk_hashes` (prompt shorter than one chunk). `""` on the normal path, including a genuine cold miss. `request` span only.

The attributes are written when MP_LOOKUP_PREFETCH_END (standard MP path) or CB_LOOKUP_END (CacheBlend path) is processed — while the root span is still open. Store-only requests that never call lookup_prefetch_start() emit no end event for the lookup phase, so their root span will not carry these attributes.

Example TraceQL queries (Grafana Tempo):

# Requests with less than 50% cache hit rate
{ name = "request" && span.hit_rate < 0.5 }

# Full cache hits only
{ name = "request" && span.hit_rate = 1.0 }

# Complete misses (lookup ran but nothing was cached)
{ name = "request" && span.requested_tokens > 0 && span.hit_tokens = 0 }

# Requests that had to go to L2 for most of their hit
{ name = "request" && span.l2_hit_rate > 0.5 }

# Lookups that exited early rather than genuinely missing
{ name = "request" && span.early_exit_reason != "" }

For the full event-to-span mapping and the registry pattern that links child spans back to the root see docs/design/observability/request-event-span.md in the source tree.

Trace Recording#

Note

Trace recording is distinct from --enable-tracing (OTel spans). Trace recording captures every StorageManager public-API call to a binary file so the same workload can be replayed later for testing, regression hunting, and benchmarking — without needing vLLM and (eventually) without a GPU. --enable-tracing exports live OTel spans to an OTLP endpoint for online observability. The two features are independent and can be used together.

When --trace-level storage is set, LMCache records every call to StorageManager.{reserve_write, finish_write, submit_prefetch_task, read_prefetched_results, finish_read_prefetched} to a binary file for later replay.

Recording is off by default and adds near-zero overhead when off (a single boolean check per StorageManager call). When on, recording happens on the EventBus drain thread, off the request path.

Capturing a trace#

With an explicit output path:

lmcache server \
    --l1-size-gb 100 --eviction-policy LRU \
    --trace-level storage --trace-output /tmp/run.lct

With an implicit timestamped output path under $TMPDIR:

lmcache server \
    --l1-size-gb 100 --eviction-policy LRU \
    --trace-level storage
# → INFO log: "trace recording enabled (level=storage); no
#   --trace-output given, writing to
#   /tmp/lmcache-trace-<pid>-<UTC>.lct"

The trace file is closed cleanly on shutdown (SIGTERM is handled by the EventBus stop path).

Capturing the cache-event stream#

--trace-level events records what this server would report to an MP coordinator: every cache-event batch (stores, deletes, accesses, capacity declarations) in the exact form POST /events carries. No coordinator is needed, so a fleet that runs without one can be captured and replayed later against a coordinator or a test double.

lmcache server \
    --l1-size-gb 100 --eviction-policy LRU \
    --trace-level events --trace-output /data/events-$(hostname).lct

One file is written per server; capture every server in the fleet. When --coordinator-url and --coordinator-event-reporting are also set, the same batches go to both the coordinator and the file. lmcache trace info prints instances, restarts, batches by type and tier, and bytes stored. Store entries carry the chunks’ token ids, which are the prompt: treat the file as sensitive.

Replay#

Replaying a recorded trace, plus the full set of CLI flags for driving, monitoring, and exporting replay results, is covered in its own page: Tracing and Debugging.

What is captured (and what is not)#

Captured:

The fully-qualified name of every decorated StorageManager call.
Each call’s input arguments (e.g. keys, layout_desc, mode, extra_count, external_request_id).
Wall-clock and monotonic timestamps of each call.
A header carrying a trace schema version, start times, and a SHA-256 digest of the active StorageManagerConfig so replay can detect mismatched configurations.

Not captured:

KV tensor bytes. Replay exercises bookkeeping and controller logic; payloads at replay time are zeros.
Calls inside the MPCacheServer, the message queue, or any GPU-copy code. These layers are out of scope for the storage trace level.

File format#

A length-prefixed msgpack stream:

[4-byte big-endian length][msgpack Header]
[4-byte big-endian length][msgpack Record]
[4-byte big-endian length][msgpack Record]
...

The Header carries a magic prefix (LMCT), a format version, the trace level (storage today), a trace schema version, start timestamps, and the StorageManagerConfig digest. Each Record carries a relative timestamp, a wall-clock timestamp, the fully-qualified call site (qualname), and an argument dict.

The format is deliberately extensible: future trace levels (mq, gpu) will share this layout and use the level header field to discriminate. Additional captured ops add new qualname strings without bumping the format version.

Transfer phase sub-spans#

With tracing enabled, each mp.store / mp.retrieve gets two child spans, one per GPU transfer phase:

transfer.kernel_interval – gather/scatter kernel sections (paged KV blocks <-> GPU staging buffers). The name says interval because the kernel queues behind the co-resident inference engine’s SM work: most of this bar is that wait, not the copy itself. Do not read it as a rate.
transfer.staging – DMA copies (GPU staging buffers <-> pinned host memory) on the copy engine, which does not contend for SMs.

The two bars are a stacked breakdown, not a timeline: the phases alternate every batch step on one stream, so their real intervals interleave. The phase that ran first starts at the transfer’s real start and lasts its total elapsed; the other follows for its own. Their sum is the transfer’s stream time; the gap to the parent span is idle time.

Attributes: nbytes, elapsed_seconds, num_steps, the real first_start_s / last_end_s, device_index, session_id, and – on transfer.staging only – throughput_GB_per_second (nbytes / elapsed_seconds; see above for why the kernel span carries none). Timings are CUDA-event based, anchored to the same wall clock as the other MP events; the children are exported shortly after their parent.

For the full design rationale see