metric(qwen3): report prefix-cache query/hit

docs/index.md

@@ -141,7 +141,7 @@ Organized by domain (model line / subsystem / playbook / lesson) instead of by l
 | `subsystems/frontend/simulated-inference-engine.md` | CPU-only simulated model crate for vLLM/OpenAI frontend and `vllm bench serve` validation without CUDA, real model weights, or real-model performance claims. |
 | `subsystems/frontend/cpu-profiling-baseline.md` | Frontend CPU profiling baseline using `openinfer-sim` with fixed TTFT=5ms/TPOT=12ms: 200 req / concurrency=16 shows ~150ms TTFT overhead (no dominant hotspot), heap allocation ~10%, stream polling ~7.5%, IPC ~1%; reproducible benchmark command and perf evidence documented. |
 | `subsystems/frontend/startup-time.md` | Qwen3-4B warm startup-to-ready 3.25s → ~1.45s: frontend tokenizer load runs concurrently with the engine load (HTTP still binds only after the engine registers), and the source safetensors mmap is kept alive to dodge ~0.4s of munmap stalling the next cudaMalloc. |
-| `subsystems/frontend/prometheus-metrics.md` | `/metrics` request histograms work for every model; Qwen3, Qwen3.5, and GLM5.2 schedulers also publish running/waiting/KV engine gauges through `LoadSnapshot` watches. |
+| `subsystems/frontend/prometheus-metrics.md` | `/metrics` request histograms come from bridge events/PrefillStats; scheduler stats ride `LoadSnapshot`. Qwen3 now reports real prefix-cache query/hit counters via monotonic totals differenced by the bridge, plus running/waiting/KV gauges. |
 | `subsystems/frontend/dashboards/README.md` | Grafana 10.4-validated dashboard for OpenInfer's live `/metrics` surface: HTTP traffic, request outcomes, scheduler/KV state, token throughput, and request latency. |
 
 ## subsystems / correctness

docs/subsystems/frontend/prometheus-metrics.md

@@ -1,31 +1,23 @@
-# Prometheus /metrics via the vLLM frontend
+# Prometheus `/metrics` via the vLLM frontend
 
-**TL;DR:** `/metrics` exposes request histograms for every model and engine gauges for schedulers that publish `LoadSnapshot`: Qwen3 and Qwen3.5 use one logical engine, while GLM5.2 EP8/DP8 uses eight rank-local engines and GLM5.2 TP8 uses one logical engine. The bridge forwards each partition's stats under the same identity the vLLM frontend uses for least-load routing.
+**TL;DR:** `/metrics` exposes request metrics for every model. Schedulers that publish `LoadSnapshot` also expose load and KV gauges; Qwen3 additionally reports real prefix-cache query and hit token counters.
 
 Last touched: 2026-07
 
-## How the numbers flow
+## Metric sources
 
-Two independent paths feed the upstream Prometheus registry (`vllm-metrics`, served by `vllm-server` at `/metrics` with its HTTP middleware counters):
+- Request metrics come from frontend request events and include latency histograms, prompt/generated token totals, and request outcomes.
+- Scheduler metrics come from `LoadSnapshot`. They are present only for model schedulers that publish a load watch.
+- Each logical scheduler partition has its own `engine` label.
 
-1. **Per-request path (works for every model crate).** The bridge stamps each request's first output with `Queued`/`Scheduled` timestamps and `PrefillStats` (prompt/computed/cached token split). The upstream `RequestMetricsTracker` turns those into `time_to_first_token_seconds`, `inter_token_latency_seconds`, `request_queue_time_seconds`, `prompt_tokens_total`, `generation_tokens_total`, `request_success_total`, `prompt_tokens_by_source_total`, … unconditionally — `disable_log_stats` only gates the periodic *text* logger, not Prometheus.
-2. **Engine-gauge path (needs one `LoadSnapshot` watch per scheduler partition).** The scheduler publishes `LoadSnapshot { kv_used_blocks, kv_total_blocks, num_running_reqs, num_waiting_reqs }` at scheduler boundaries; one bridge identity per partition forwards its snapshot as a stats-only `RequestBatchOutputs`. The enclosing `engine_index` is both the routing identity and the Prometheus `engine` label. Watches coalesce to ≤1 message per scheduler step, and the scheduler's final idle publish settles the gauges back to 0.
+Qwen3 publishes monotonic prefix-cache totals. The frontend converts them to interval deltas before passing them to vLLM's Prometheus collector, so coalesced load-watch updates do not lose or double-count increments.
 
-For a single-partition model, `EngineHandle::with_load_watch` keeps the original one-engine contract. Qwen3.5 uses that contract for both its single-GPU backend and its TP backend because both execute one logical request stream through one scheduler. A partitioned scheduler uses `with_load_watches`, and the frontend launch declares the same engine count; a mismatch fails startup. GLM5.2 EP8 therefore registers engines 0–7, each bound to its own pending queue and KV pool. TP8 registers only engine 0 because its eight workers mirror one logical request stream.
+`vllm:prefix_cache_queries_total` counts prompt tokens submitted to an actual first-prefix lookup. `vllm:prefix_cache_hits_total` counts tokens restored from matching full cache blocks. Echo requests, cache-disabled requests, and later chunks of the same prefill do not add queries. Qwen3 cache blocks contain 16 tokens.
 
-Measured cost is noise in both covered configurations:
+## Check prefix-cache counters
 
-- Qwen3 TPOT: 10.6387 ms (main) vs 10.6395 ms (metrics branch) over 828 tokens.
-- GLM5.2 EP8, three-run median at concurrency 64: 1268.58 vs 1264.82 output tok/s (-0.30%); TPOT p50 41.76 vs 41.35 ms.
+Send the same prompt of at least 16 tokens twice, then scrape `/metrics` and inspect `vllm:prefix_cache_queries_total` and `vllm:prefix_cache_hits_total`. Both counters are cumulative. Queries should increase for each request; hits should increase when the repeated prompt reuses cached blocks.
 
-## What deliberately reads zero (state at capture time)
+## Coverage limits
 
-- `prefix_cache_queries/hits` and the by-reason waiting split (`reason="deferred"` is driven by a skipped-request counter we don't report; all waiting shows as `reason="capacity"`).
-- Spec-decode counters, per-GPU FLOPs/bytes estimates, KV-block residency histograms, cudagraph stats — the bridge sends `SchedulerStats::default()` for these fields.
-- Every model crate whose scheduler doesn't publish a `LoadSnapshot` watch (currently deepseek and kimi) gets path 1 only; its engine gauges are absent, not lying-zero — the bridge skips the stats task for that partition when no watch exists.
-
-## Validated coverage and next step
-
-Qwen3.5 single-GPU live RTX 5090 validation confirmed that running and KV gauges rise during generation, waiting rises under batch-slot pressure, and all three return to zero after drain and recovery. The commands and metric samples are recorded in [Qwen3.5 Scheduler LoadSnapshot](../../models/qwen35/load-snapshot.md#validation-boundary). TP uses the same scheduler publication path but was not part of that live run.
-
-Next, wire the DeepSeek-V2-Lite and Kimi-K2 schedulers using the same recipe, and report real prefix-cache query/hit counters instead of zeros. A future partitioned model must expose its logical scheduler partitions instead of averaging them behind engine 0.
+Unsupported scheduler fields remain at their upstream defaults, including speculative-decoding counters, GPU FLOP/byte estimates, KV-residency histograms, and CUDA Graph statistics. Models without a `LoadSnapshot` watch expose request metrics but no scheduler gauges.

openinfer-engine/src/engine.rs

@@ -352,6 +352,16 @@ pub struct LoadSnapshot {
     pub num_running_reqs: u64,
     /// Requests admitted but not yet running (KV pressure, prefetch wait).
     pub num_waiting_reqs: u64,
+    /// Prompt tokens queried against the local prefix cache since engine start.
+    ///
+    /// This is a monotonic total because the snapshot rides a coalescing watch
+    /// channel. Consumers that feed delta counters must difference consecutive
+    /// snapshots rather than forwarding this value directly.
+    pub prefix_cache_queries_total: u64,
+    /// Prompt tokens served from the local prefix cache since engine start.
+    /// Monotonic for the same coalescing-safe reason as
+    /// [`Self::prefix_cache_queries_total`].
+    pub prefix_cache_hits_total: u64,
 }
 
 /// One full KV block that just became reusable from this engine's prefix cache.

openinfer-glm52/src/scheduler/load.rs

@@ -36,6 +36,7 @@ pub(super) fn publish_load(
             kv_total_blocks: kv_total_blocks as u64,
             num_running_reqs: slots[rank].iter().flatten().count() as u64,
             num_waiting_reqs: pending[rank].len() as u64,
+            ..LoadSnapshot::default()
         });
     }
 }

openinfer-qwen3/src/executor.rs

@@ -95,6 +95,9 @@ pub struct PrefillStepItem {
     /// Set by the executor after matching; the forward pass only computes
     /// the remaining suffix.
     pub(crate) cached_tokens: usize,
+    /// Whether this step performed the request's one local prefix-cache lookup.
+    /// False for later chunks, echo requests, and cache-disabled execution.
+    pub(crate) prefix_cache_queried: bool,
     /// Scheduler-set cap on prompt tokens forwarded this step (chunked
     /// prefill). The executor clamps it to the tokens actually remaining.
     pub(crate) chunk_budget: usize,
@@ -125,6 +128,7 @@ impl PrefillStepItem {
             echo,
             lora_adapter: None,
             cached_tokens: 0,
+            prefix_cache_queried: false,
             chunk_budget: usize::MAX,
             chunk_start: 0,
             chunk_tokens,
@@ -307,6 +311,7 @@ fn build_prefill_request_results(
             first_token_logprob: first_token_logprobs[i].take(),
             prompt_logprobs,
             cached_tokens: req.cached_tokens,
+            prefix_cache_queried: req.prefix_cache_queried,
             completed,
             prefill_pos: req.chunk_start + req.chunk_tokens,
         });
@@ -805,6 +810,10 @@ pub struct PrefillRequestResult {
     pub prompt_logprobs: Option<Vec<Option<TokenLogprob>>>,
     /// Prompt tokens served from the prefix cache (KV reused, not recomputed).
     pub cached_tokens: usize,
+    /// Whether the executor actually queried the local prefix cache for this
+    /// request. The scheduler uses this to exclude echo and cache-disabled
+    /// prefills from the aggregate query denominator.
+    pub prefix_cache_queried: bool,
     /// Whether the prompt is fully prefilled. When false this step ran a
     /// non-final chunk and `first_token` is meaningless.
     pub completed: bool,
@@ -1841,6 +1850,7 @@ impl Qwen3Executor {
             // Echo needs logits for every prompt position; cached positions
             // are never forwarded, so echo requests prefill from scratch.
             if self.prefix_cache_enabled && !req.echo {
+                req.prefix_cache_queried = true;
                 req.cached_tokens = rkv.match_and_add_prefix(self.kv_mgr.pool())?;
             }
             self.request_kvs.insert(req.request_id, rkv);

openinfer-qwen3/src/scheduler.rs

@@ -93,6 +93,23 @@ pub(super) struct PendingRequest {
     pub(super) cached_tokens: usize,
 }
 
+/// Lifetime prefix-cache token totals published through `LoadSnapshot`.
+/// Keeping totals here makes the coalescing watch lossless; the frontend bridge
+/// differences observed snapshots into the interval deltas vLLM expects.
+#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)]
+pub(super) struct PrefixCacheTotals {
+    queries: u64,
+    hits: u64,
+}
+
+impl PrefixCacheTotals {
+    fn record(&mut self, prompt_tokens: usize, cached_tokens: usize) {
+        debug_assert!(cached_tokens <= prompt_tokens);
+        self.queries = self.queries.saturating_add(prompt_tokens as u64);
+        self.hits = self.hits.saturating_add(cached_tokens as u64);
+    }
+}
+
 impl PendingRequest {
     fn from_scheduler_request(request_id: RequestId, req: GenerateRequest) -> Self {
         Self {
@@ -498,12 +515,15 @@ fn publish_load<E: ModelExecutor>(
     executor: &E,
     num_running_reqs: u64,
     num_waiting_reqs: u64,
+    prefix_cache_totals: PrefixCacheTotals,
 ) {
     load_tx.send_replace(LoadSnapshot {
         kv_used_blocks: kv_total.saturating_sub(executor.available_blocks() as u64),
         kv_total_blocks: kv_total,
         num_running_reqs,
         num_waiting_reqs,
+        prefix_cache_queries_total: prefix_cache_totals.queries,
+        prefix_cache_hits_total: prefix_cache_totals.hits,
     });
 }
 
@@ -532,6 +552,7 @@ fn scheduler_loop<E>(
     // Decode-overlap async prefill: pending requests whose prefill is in-flight
     // on the prefill overlap stream. `None` when no async prefill is running.
     let mut inflight_prefill_pending: Option<Vec<PendingRequest>> = None;
+    let mut prefix_cache_totals = PrefixCacheTotals::default();
 
     info!("Scheduler ready");
 
@@ -544,6 +565,7 @@ fn scheduler_loop<E>(
                 + prefilling.len()
                 + inflight_prefill_pending.as_ref().map_or(0, Vec::len)) as u64,
             (deferred.len() + loading.len()) as u64,
+            prefix_cache_totals,
         );
         // Flush the prior step's cache changes to a router (no-op unless the
         // event feed is on). Top-of-loop, like `publish_load`: one pass per
@@ -570,7 +592,13 @@ fn scheduler_loop<E>(
                     scheduled_at_unix_s,
                 };
                 let effects = resolve_step(&executor, &active, artifacts);
-                apply_effects(&mut executor, &mut active, &mut prefilling, effects);
+                apply_effects(
+                    &mut executor,
+                    &mut active,
+                    &mut prefilling,
+                    &mut prefix_cache_totals,
+                    effects,
+                );
             }
         }
 
@@ -703,7 +731,13 @@ fn scheduler_loop<E>(
 
                 // Only apply decode effects from the unified result.
                 let effects = resolve_step(&executor, &active, artifacts);
-                apply_effects(&mut executor, &mut active, &mut prefilling, effects);
+                apply_effects(
+                    &mut executor,
+                    &mut active,
+                    &mut prefilling,
+                    &mut prefix_cache_totals,
+                    effects,
+                );
 
                 // Track the pending prefill for next-iteration polling.
                 inflight_prefill_pending = Some(pending_for_poll);
@@ -721,7 +755,13 @@ fn scheduler_loop<E>(
             }
         };
         let effects = resolve_step(&executor, &active, artifacts);
-        apply_effects(&mut executor, &mut active, &mut prefilling, effects);
+        apply_effects(
+            &mut executor,
+            &mut active,
+            &mut prefilling,
+            &mut prefix_cache_totals,
+            effects,
+        );
     }
 }
 
@@ -743,6 +783,7 @@ fn scheduler_loop_with_lora_control<E>(
     let mut prefilling: Vec<PendingRequest> = Vec::new();
     let mut pending_control: VecDeque<EngineControlRequest> = VecDeque::new();
     let mut post_control_deferred: Vec<PendingRequest> = Vec::new();
+    let mut prefix_cache_totals = PrefixCacheTotals::default();
 
     info!("Scheduler ready with LoRA control");
 
@@ -753,6 +794,7 @@ fn scheduler_loop_with_lora_control<E>(
             &executor,
             (active.len() + prefilling.len()) as u64,
             (deferred.len() + loading.len() + post_control_deferred.len()) as u64,
+            prefix_cache_totals,
         );
 
         // 1. Drain incoming commands. Generation submitted after a pending
@@ -873,7 +915,13 @@ fn scheduler_loop_with_lora_control<E>(
             }
         };
         let effects = resolve_step(&executor, &active, artifacts);
-        apply_effects(&mut executor, &mut active, &mut prefilling, effects);
+        apply_effects(
+            &mut executor,
+            &mut active,
+            &mut prefilling,
+            &mut prefix_cache_totals,
+            effects,
+        );
     }
 }
 

openinfer-qwen3/src/scheduler/effects.rs

@@ -5,6 +5,7 @@ use openinfer_core::engine::TokenSink;
 
 use super::ActiveRequestState;
 use super::PendingRequest;
+use super::PrefixCacheTotals;
 use super::TokenEvent;
 use crate::executor::RequestId;
 
@@ -24,6 +25,7 @@ pub(super) struct ScheduledEffect {
     pub(super) scheduled_at_unix_s: f64,
     pub(super) prompt_tokens: usize,
     pub(super) cached_tokens: usize,
+    pub(super) prefix_cache_queried: bool,
 }
 
 pub(super) enum PendingEffect {
@@ -110,6 +112,7 @@ pub(super) fn apply_effects(
     executor: &mut impl crate::executor::ModelExecutor,
     active: &mut Vec<ActiveRequestState>,
     prefilling: &mut Vec<PendingRequest>,
+    prefix_cache_totals: &mut PrefixCacheTotals,
     effects: StepEffects,
 ) {
     // `Finished` events are not sent inline: they are collected here and
@@ -121,6 +124,9 @@ pub(super) fn apply_effects(
     let mut finishes: Vec<(TokenSink, TokenEvent)> = Vec::new();
 
     for scheduled in effects.scheduled {
+        if scheduled.prefix_cache_queried {
+            prefix_cache_totals.record(scheduled.prompt_tokens, scheduled.cached_tokens);
+        }
         let _ = scheduled.token_tx.send(TokenEvent::Scheduled {
             queued_at_unix_s: scheduled
                 .queued_at_unix_s

openinfer-qwen3/src/scheduler/plan.rs

@@ -225,6 +225,7 @@ fn build_prefill_items(pending: &[PendingRequest], indices: &[usize]) -> Vec<Pre
                 echo: r.echo,
                 lora_adapter: r.lora_adapter.clone(),
                 cached_tokens: r.cached_tokens,
+                prefix_cache_queried: false,
                 chunk_budget: r.step_chunk,
                 chunk_start: 0,
                 chunk_tokens: 0,

openinfer-qwen3/src/scheduler/resolve.rs

@@ -125,6 +125,7 @@ fn resolve_prefill_outputs(
                 scheduled_at_unix_s,
                 prompt_tokens: prompt_len,
                 cached_tokens: result.cached_tokens,
+                prefix_cache_queried: result.prefix_cache_queried,
             });
         }