feat(observability): report real prefix-cache query/hit counters in /metrics - #953
1571859588 wants to merge 4 commits into
Conversation
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: ab0234f87f
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| queries: snapshot.prefix_cache_queries, | ||
| hits: snapshot.prefix_cache_hits, |
There was a problem hiding this comment.
Diff prefix-cache totals before exporting counters
For Qwen3's stepped bridge, SchedulerMetrics carries monotonic totals and dispatch_step sends scheduler_stats_from(&self.scheduler.metrics()) on every output batch; vLLM's Prometheus logger increments prefix_cache_queries/hits by the values in each SchedulerStats. Once any cached request has run, every subsequent token batch re-adds the same cumulative totals, so /metrics overcounts prefix-cache traffic until the process restarts. Please compute per-send deltas here, like the existing spec-decode path does.
Useful? React with 👍 / 👎.
| effects.prefix_queries += 1; | ||
| effects.prefix_hits += result.cached_tokens as u64; |
There was a problem hiding this comment.
Count prefix-cache queries in tokens
For any prompt longer than one token, this makes the query denominator request-granularity (+1) while prefix_hits is token-granularity (cached_tokens). vLLM's prefix-cache counters are meant to be compared as hit tokens / queried tokens, so a repeated ~1900-token prompt would report roughly 1888 hits over 1 query and produce impossible hit rates above 100%. Increment queries by the queried/cacheable prompt token count instead.
Useful? React with 👍 / 👎.
|
Please fix the token-vs-request query-unit mismatch and cumulative-counter double counting, then provide an exact-head, multi-batch scheduler-to-/metrics E2E result showing stable non-zero deltas across scrapes; the PR currently reports that Qwen3 E2E was blocked, so no E2E result has been provided. |
SummaryFixes two issues flagged on the prefix-cache /metrics counters: Token-vs-request query-unit mismatch (pegainfer-qwen3/src/scheduler/resolve.rs): prefix_queries was incremented per-request (+= 1) while prefix_hits was token-granular (+= result.cached_tokens), so repeated prompts reported >100% hit rates. Both are now token-granular: prefix_queries += req.prompt_tokens.len(), prefix_hits += result.cached_tokens (cached_tokens ≤ prompt_tokens ⇒ rate ∈ [0,1]). Verificationcargo test --release -p pegainfer-frontend --lib vllm::bridge → 14/14 passed, including prefix_cache_stats_are_per_interval_deltas_not_running_totals (interval 1 ships (100,37); interval 2 after totals reach (200,74) ships delta (100,37) not (200,74); idle ships (0,0)). Note on E2EThe live A100 /metrics multi-batch scrape requested in review could not be produced in this environment: the qwen3 build chain pulls rdma-mummy-sys, whose bindgen (0.66) generates _address fields under the local toolchain, breaking that third-party crate's compile — unrelated to this change. The overcount behavior is directly covered by the passing bridge delta test. If CI runs on this head, the bridge test goes green; I can supply a real /metrics scrape snapshot once a qwen3-buildable environment is available. |
FeathBow
left a comment
There was a problem hiding this comment.
Thanks! please rebase on main :)
Rebased on main (now 419ba7f, based on 99b68f3). Worth flagging: while rebasing onto 95b02cc (#952 — "stamp spec-decode counters on the stepped bridge"), I found that PR introduced exactly the abstraction this branch needed. It extracted SpecDecodeTracker::interval as the shared cumulative→per-interval converter for the spec-decode counters. The prefix-cache counters had the identical bug (scheduler holds running totals, the wire must carry deltas, or the frontend's *_total counters re-add history every batch), so I mirrored it with PrefixCacheTracker and routed both bridges through it, rather than keeping my earlier free-function prefix_cache_delta plus the AtomicU64 last-state fields on SteppedEngineBridge. Both counters now go through one pattern and cannot drift. Also fixed while rebasing: token-granular units in resolve.rs (prefix_queries was += 1 per request against token-granular prefix_hits), plus rustfmt and a missing DCO sign-off on the first commit. Verified: cargo test --release -p pegainfer-frontend --lib → 68/68 passed, including prefix_cache_stats_are_per_interval_deltas_not_running_totals. |
b988a32 to
419ba7f
Compare
419ba7f to
253ffaf
Compare
|
Fixed. SchedulerMetrics gained prefix_cache_queries/prefix_cache_hits, but several model lines initialize it as a struct literal with no ..Default fallback, so the new fields broke their build. Zero-initialized the fields at every literal site — gemma4, qwen35 (×3, incl. one test), and glm52, which the CI matrix doesn't compile but would have broken identically. Both lines report zeros for now, which is honest for them: qwen35's hybrid Gated DeltaNet state is linear and not prefix-reusable, and gemma4's conversation-tail cache resolves hits through send_scheduled's cached_tokens rather than through counters — wiring it up is a follow-up. Verified locally: cargo check --release -p pegainfer-gemma4 --features gemma4 --lib and -p pegainfer-qwen35 --features qwen35 --lib --tests both pass (Triton AOT included), rustfmt clean, plus the frontend tests at 68/68. |
FeathBow
left a comment
There was a problem hiding this comment.
I would appreciate it if you could rebase onto main first and keep an eye on the CI while working on the fix.
253ffaf to
385ffc3
Compare
|
I've rebased onto the main branch and will keep an eye on CI while working on the fix. Rebased on main (385ffc3, based on 70a600b). Refactor from #968 splits qwen35's scheduler into |
xiaguan
left a comment
There was a problem hiding this comment.
Thank you for rebasing the PR and fixing the new metrics-field initializers. I re-reviewed the current head (385ffc31), and the original metrics issues are still present:
-
resolve_prefill_outputsincrementsprefix_queriesfor every request's first chunk, whileschedule_prefill_chunkonly performsmatch_and_add_prefixwhen the prefix cache is enabled andechois false. Cache-disabled and echo requests therefore report lookups that never happened. Please derive the counters from the executor's actual lookup result instead of inferring them from prompt length. -
CPU-offload and P2P-restored blocks are absorbed by the same
match_and_add_prefixcall and then reported as localprefix_cache_stats.base.hits. Please preserve the source and populate the connector/external counters separately. -
In the stepped bridge's
outputs.is_empty()branch,self.stats(prefix, spec)advances the prefix tracker before the code decides whether to send. When there is a prefix delta but no speculative-decoding delta, the batch is dropped and that prefix delta is lost permanently. Please send a stats-only batch whenever either delta is present, and add a metadata-only cached-step followed by abort regression test. -
The current tests validate synthetic scheduler totals and synthetic bridge deltas separately. Please add one live path through real lookup, the stepped bridge, the vLLM metrics logger, and a
/metricsscrape. It should cover cache disabled/echo, local miss/hit, external restore attribution, and the metadata-only abort case.
The token-granularity and cumulative-to-interval conversions themselves look good, and the current public CI is green. Once the four cases above are covered, this should be ready for another focused review. Thank you.
385ffc3 to
65f1700
Compare
|
Thanks — addressed 1 and 3, and I need your steer on 2 and 4.
if req.prefill_pos == 0 {
effects.cached.push(...); // unchanged
if executor.prefix_cache_enabled() && !req.echo {
effects.prefix_queries += req.prompt_tokens.len() as u64;
effects.prefix_hits += result.cached_tokens as u64;
}
}I deliberately left effects.cached outside the gate — that drives the cached_tokens usage field from #603, which shouldn't change behaviour here. Regression test: prefix_cache_disabled_reports_no_lookups (fake executor with the cache off, drained to terminal, asserts both counters stay 0).
Note qwen3 is unverified locally for the same reason; the two qwen3 changes are small and mechanical but will need CI to confirm. |
…metrics Thread prefix-cache query/hit counters from the qwen3 scheduler through SchedulerMetrics into the vLLM SchedulerStats.prefix_cache_stats surface, so Prometheus /metrics no longer reads zeros for prefix cache hit rate. - pegainfer-qwen3: accumulate per-step prefix_queries/prefix_hits in StepEffects (one query per first-chunk request; hits = cached_tokens), fold into cumulative counters on the scheduler, expose via metrics(). - pegainfer-frontend: add prefix_cache_queries/hits to SchedulerMetrics and map them to PrefixCacheStats in the vLLM bridge. This complements the cached_tokens usage path (TokenEvent::Scheduled) that upstream already landed for pegainfer-project#603; it covers the /metrics consumer only. Verified: pegainfer-frontend --lib tests pass (65); cargo clippy and cargo check --workspace --lib clean. qwen3 A100 e2e blocked locally by a rdma-mummy-sys bindgen environment issue unrelated to this change. Signed-off-by: yuntaonie <1571859588@qq.com>
…r-send deltas Two review bugs on the prefix-cache `/metrics` surface, both fixed: 1. Unit mismatch (queries vs hits). Previously `prefix_queries += 1` (a request) while `prefix_hits += cached_tokens` (a token count), so `hit_rate = hits/queries` could exceed 100%. Now both are TOKEN-granular, matching vLLM's `PrefixCacheStats`: `prefix_queries` counts the prompt tokens looked up in the cache and `prefix_hits` counts the cached tokens. Because cached <= prompt, `hits <= queries` and the rate stays in [0, 1]. Guarded by the existing `prefill_pos == 0` check so each request is counted exactly once (no double counting across chunked prefill). 2. Cumulative overcount in Prometheus. The scheduler holds running totals, but `dispatch_step` / `publish_scheduler_stats` shipped that running total on *every* token batch, and the frontend adds each `SchedulerStats` value into its `prefix_cache_*_total` counters — so a cached request re-added the whole history on every subsequent batch until restart. Now the bridge ships per-send DELTAS (cur - last), mirroring the existing spec-decode path: `prefix_cache_delta()` in bridge.rs, with `last_prefix_*` state in both the legacy `publish_scheduler_stats` loop and the stepped bridge (AtomicU64, since `dispatch_step` takes `&self`). Adds a `FakeExecutor` prefix-hit hook, a multi-batch/multi-scrape qwen3 scheduler test (`prefix_cache_metrics_stable_across_batches_and_scrapes`, token-granular assertions), and a frontend test (`prefix_cache_stats_are_per_interval_deltas_not_running_totals`) that proves the bridge ships the interval delta, not the running total. Signed-off-by: yuntaonie <1571859588@qq.com>
65f1700 to
14fe247
Compare
There was a problem hiding this comment.
Thanks for the tracker refactor and the two fixes; the delta conversion now mirrors #952 and the units are right. On your two questions:
&2: the field exists on the pinned rev. SchedulerStats has connector_prefix_cache_stats (protocol/stats.rs:183) and the metrics crate registers vllm:external_prefix_cache_queries/hits, so nothing in the git dependency needs extending. On the qwen3 side the split is available where the lookup happens: schedule_prefill_chunk runs after the prefetch settles and PrefetchState carries the probe's gpu_hit_blocks(), so local = gpu_hit_blocks x block_size (the whole match when there was no prefetch) and external = matched − local. I recommend a second counter pair on SchedulerMetrics and a second tracker stamping connector_prefix_cache_stats, with match_and_add_prefix left as is.
&4: I recommend adding the lookup plumbing to sim the way its spec-decode counters work: a synthetic prefix_hit (and an external knob) reported as cached_tokens on each request's first chunk, and a frontend_e2e case that scrapes /metrics for the four prefix counters across local hit/miss, disabled/echo, the metadata-only abort, and external attribution. The qwen3 real-lookup leg can be run on a GPU host once that is green.
Two more things before another pass: the &3 fix has no regression test yet (metadata-only cached step, then abort, asserting the prefix delta ships in a stats-only batch); and the &1 fix re-states the executor's gate (prefix_cache_enabled() && !echo) in the resolver behind a trait default of true. Reporting the lookup from the executor (cached_tokens: Option on PrefillRequestResult, None when no lookup ran) removes the duplicated predicate and the permissive default.
Non-blocking: the totals-versus-deltas explanation is written in seven places; one home on PrefixCacheTracker is enough. The adapter test could shrink to the once-per-request rule with a multi-chunk prompt, without the eprintln!s, the triple read, and the stale prefix_cache_delta reference.
…tely An external restore (CPU offload or P2P) was absorbed by the same `match_and_add_prefix` call and then reported as a local prefix-cache hit, so `vllm:prefix_cache_hits_total` counted reuse that never came from local KV. Split the match where the lookup happens: in `schedule_prefill_chunk` the prefetch probe's `gpu_hit_blocks` are the local share and the remainder is external (with no probe for the request the whole match is local). Each side gets its own counter pair on `SchedulerMetrics` and its own interval tracker, the external one stamping `SchedulerStats.connector_prefix_cache_stats`, so `vllm:external_prefix_cache_queries/hits` report the connector's share and the local pair stops overstating it. `match_and_add_prefix` itself still returns a plain `usize`. Reporting the lookup also moves to the executor rather than being re-derived in the resolver: `PrefillRequestResult::cached_tokens` is now `Option`, `None` meaning no lookup ran (prefix caching off, or an echo request) and `Some(0)` meaning a miss. That drops the resolver's duplicate of the executor's `prefix_cache_enabled() && !echo` gate — which would have drifted silently if the executor's condition ever changed — along with `ModelExecutor::prefix_cache_enabled` and its permissive `true` default, which let an executor that forgot to override report the phantom queries this series set out to remove. `pegainfer-sim` gains a scripted lookup knob (local hit plus an external share) modeled on its spec-decode counters, so the counters are now exercised end to end through the stepped bridge and out to a `/metrics` scrape without a GPU: one case asserts the four families carry the scripted split, another asserts a cache-disabled engine reports no lookup at all. Signed-off-by: yuntaonie <1571859588@qq.com>
…elta notes The stepped bridge's stats-only batch had no test: the existing prefix-cache case drives `publish_scheduler_stats`, the legacy loop, so nothing exercised the branch where a step produces no output at all. `aborted_request_still_ships_its_prefix_lookup` covers it end to end. A request is admitted against a slow-prefill simulated engine — so its lookup is counted — and then abandoned by a client that gives up inside the prefill window, leaving a prefix delta with no token to carry it. A second, completed request drives the next step. The four families must then report both lookups exactly once: two prompts' worth, not just the survivor's, and not a delta replayed on top of it. Mutation-checked: dropping the prefix/external terms from the send condition fails this test. Also folds the totals-versus-deltas explanation, previously restated at seven sites, into `PrefixCacheTracker` — the other six now point at it — and trims the scheduler adapter test to what it actually pins: the once-per-request counting rule, without the scratch `eprintln!`s, the triple read, and a reference to `prefix_cache_delta`, which no longer exists. Signed-off-by: yuntaonie <1571859588@qq.com>
|
Both remaining items are done, plus the non-blocking cleanup. &3 regression test — aborted_request_still_ships_its_prefix_lookup: a request is admitted against a slow-prefill simulated engine (so its lookup is counted) and then abandoned by a client that gives up inside the prefill window, leaving a prefix delta with no token to carry it; a second completed request drives the next step. The four families must then report both lookups exactly once — two prompts' worth, not just the survivor's, and not a delta replayed on top of it. Mutation-checked: removing the prefix/external terms from the send condition fails this test (10s timeout), restoring them passes. &1 — PrefillRequestResult::cached_tokens is now Option (None = no lookup, Some(0) = a miss), set where the lookup happens. ModelExecutor::prefix_cache_enabled, its permissive true default, and the resolver's copy of the prefix_cache_enabled() && !echo gate are all gone; the usage effect uses unwrap_or(0). &2 — split at the lookup site: gpu_hit_blocks × block_size is local, the remainder external, and the whole match counts as local when the request has no prefetch probe. Second counter pair on SchedulerMetrics, second PrefixCacheTracker stamping connector_prefix_cache_stats (None on a zero interval, so a line with no connector leaves it unset). match_and_add_prefix still returns usize. &4 — pegainfer-sim gained with_prefix_cache(local, external) modeled on its spec-decode knob, and frontend_e2e now scrapes all four families through the stepped bridge, plus a case asserting a cache-disabled engine reports no lookup. The qwen3 real-lookup leg is still unrun locally — rdma-mummy-sys doesn't build here — so it needs CI or a GPU host. Non-blocking — the totals-versus-deltas note now lives only on PrefixCacheTracker; the other sites point at it. Adapter test trimmed: no scratch eprintln!s, no triple read, no stale prefix_cache_delta reference. Locally: frontend 68/68, sim e2e 16/16, qwen35 + gemma4 build, rustfmt clean. |
Summary
Threads prefix-cache query/hit counters from the qwen3 scheduler through
SchedulerMetricsinto the vLLMSchedulerStats.prefix_cache_statssurface,so Prometheus
/metricsno longer reports zeros for prefix-cache hit rate.pegainfer-qwen3: accumulate per-stepprefix_queries/prefix_hitsinStepEffects(one query per first-chunk request; hits =cached_tokens),fold into cumulative counters on the scheduler, expose via
metrics().pegainfer-frontend: addprefix_cache_queries/prefix_cache_hitstoSchedulerMetricsand map them toPrefixCacheStatsin the vLLM bridge.Relation to #814 / #669 / #603
This supersedes #814 (which was opened from
feat/sim-frontend-prefix-cache-metrics,head
7f24658e, against the pre-rename tree and went CONFLICTING due to#841PegaInfer rename +#824kv-store refactor). Per the maintainer noteon #814, this is the single canonical PR for the prefix-cache reporting surface.
Scope split to avoid two parallel implementations:
cached_tokens→ OpenAI usage): already landed upstreamvia
TokenEvent::Scheduled(issue metrics: report real prefix-cache query/hit counters from the qwen3 scheduler #603 line). Not touched here./metricssurface (prefix_cache_queries/hits→ Prometheus): this PR.Verified
cargo test -p pegainfer-frontend --lib— 65 passed (incl. bridgeprefix_cache_statsmapping).cargo clippy+cargo check --workspace --lib— clean.Note: a full qwen3 A100 e2e was blocked in this local environment by a
rdma-mummy-sysbindgen issue (missing vendoredrdma-core-mummyheaders) thatis unrelated to this change and does not touch rdma code; upstream CI with the
full rdma toolchain will validate the qwen3 build.