Skip to content

Commit bc3fbcd

Browse files
Fix bench_long_session metric names + expose scheduler_kv_live_bytes
Triage of the 2026-05-30 Mac M4 4h run (results/platform-tests/ bench_long_session_mac_1780130542.aborted.json) surfaced a bench-side bug that made the entire run produce no KV-memory data. Root cause ---------- scripts/bench_agentic/bench_long_session.py looked for these metric names: inference_engine_scheduler_active_sessions inference_engine_scheduler_pool_in_use inference_engine_scheduler_pool_size inference_engine_scheduler_kv_live_bytes but the server actually exposes: scheduler_active_sessions scheduler_pool_in_use scheduler_pool_total scheduler_pending (no scheduler_kv_live_bytes at all) So all 58 turns recorded an empty 'metrics: {}' dict and the KV-bounded check (the headline ADR 0006 §2.3 claim) was effectively disabled. Fixes in this commit -------------------- 1. inference_engine/memory/pool.py SlabPool.live_kv_bytes property — sums RolloutSlab.live_kv_bytes across the in-use slabs. Free slabs report 0 (logical_size is reset on release). Verifier-side bytes flow in via PooledVerifier's existing live_kv_bytes_override mechanism, so this aggregate matches the verifier's actual footprint. 2. inference_engine/server/metrics.py New 'scheduler_kv_live_bytes' Gauge with descriptive HELP text pointing at ADR 0006 §2.3. snapshot_scheduler() takes an extra kv_live_bytes kwarg (defaults to 0 so existing callers stay valid; calling without it now also explicitly resets the gauge so a stale prior value never bleeds into the next scrape). 3. inference_engine/server/app.py Bootstrap snapshot + the per-/metrics-scrape refresh both now pass pool.live_kv_bytes through. 4. scripts/bench_agentic/bench_long_session.py - Corrected metric names everywhere they appear (5 sites: _METRIC_NAMES, docstring, progress line, bucketize aggregate, global aggregate). - Added a 'note on what this bench measures and what it doesn't' to the module docstring documenting the prefill- grows-linearly-with-history finding from the same triage. That observation is a *protocol-level* limitation of stateless OpenAI chat-completions, NOT a sink+window failure: KV memory is bounded but prefill cost is O(history). The bench reports both metrics independently — KV bounded is a hard claim, latency drift is a measurement. Tests ----- tests/inference_engine/memory/test_pool.py +3 tests for live_kv_bytes aggregation tests/inference_engine/server/test_metrics.py +1 test for default-zero kwarg, +scheduler_kv_live_bytes in expected-name set, +assertions in existing snapshot tests tests/.../test_app_metrics_and_auth.py +1 integration test asserting /metrics exposes the new gauge at idle Verified: pytest tests/inference_engine/ → 389 passed python3 scripts/bench_agentic/bench_long_session.py --dry-run → OK parser smoke test on real metric-name sample → parses all 5 Out of scope ------------ - Server-side fixes for the orphan-session-on-disconnect bug (already applied locally on the Mac per the aborted.json fixes_applied list; will be a separate PR from that work). - Architectural decision on cross-request KV reuse (the actual fix for prefill latency growth) — needs ADR 0006 amendment and likely a v0.4 implementation, separate work line. Co-authored-by: FluffyAIcode <FluffyAIcode@users.noreply.github.com>
1 parent 9b69582 commit bc3fbcd

7 files changed

Lines changed: 139 additions & 13 deletions

File tree

inference_engine/memory/pool.py

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -112,6 +112,27 @@ def total_kv_bytes(self) -> int:
112112
"""Sum of physical KV bytes across all slabs (capacity, not live)."""
113113
return sum(s.kv_bytes for s in self._all_slabs)
114114

115+
@property
116+
def live_kv_bytes(self) -> int:
117+
"""Sum of *live* KV bytes across slabs currently in use.
118+
119+
This is what we want to expose as a Prometheus gauge for the
120+
long-session memory-stability claim (ADR 0006 §2.3): it's the
121+
actual KV memory consumed by active sessions right now, not
122+
the pool's pre-allocated capacity. Free slabs contribute 0
123+
(their ``logical_size`` is reset on release).
124+
125+
:class:`~inference_engine.scheduler.pooled_verifier.PooledVerifier`
126+
keeps each slab's ``live_kv_bytes_override`` synced with the
127+
real verifier KV size, so this aggregate matches the verifier
128+
backend's actual memory footprint.
129+
"""
130+
with self._lock:
131+
in_use_set = set(self._in_use)
132+
return sum(
133+
self._all_slabs[i].live_kv_bytes for i in sorted(in_use_set)
134+
)
135+
115136
def acquire_optional(self) -> Optional[KVSlab]:
116137
"""Acquire a slab if available, else return ``None`` instead of raising.
117138

inference_engine/server/app.py

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -152,6 +152,7 @@ def create_app(
152152
metrics = Metrics.build()
153153
metrics.snapshot_scheduler(
154154
active=0, pool_in_use=0, pool_total=pool.total_count, pending=0,
155+
kv_live_bytes=0,
155156
)
156157

157158
@asynccontextmanager
@@ -295,6 +296,7 @@ async def metrics_endpoint() -> Response:
295296
pool_in_use=pool.in_use_count,
296297
pool_total=pool.total_count,
297298
pending=scheduler.pending_count,
299+
kv_live_bytes=pool.live_kv_bytes,
298300
)
299301
return PlainTextResponse(
300302
content=metrics.render(),

inference_engine/server/metrics.py

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -105,6 +105,7 @@ class Metrics:
105105
scheduler_pool_in_use: Gauge
106106
scheduler_pool_total: Gauge
107107
scheduler_pending: Gauge
108+
scheduler_kv_live_bytes: Gauge
108109
scheduler_admission_total: Counter
109110

110111
@classmethod
@@ -169,6 +170,14 @@ def build(cls) -> "Metrics":
169170
"Submissions queued for admission under QUEUE policy.",
170171
registry=registry,
171172
),
173+
scheduler_kv_live_bytes=Gauge(
174+
"scheduler_kv_live_bytes",
175+
"Bytes of KV cache currently live across all active "
176+
"sessions. Bounded by the per-session sink+window "
177+
"configuration; verifies the ADR 0006 §2.3 long-session "
178+
"memory-stability claim.",
179+
registry=registry,
180+
),
172181
scheduler_admission_total=Counter(
173182
"scheduler_admission_total",
174183
"Total admission attempts, by result.",
@@ -207,11 +216,13 @@ def record_completion(self, *, finish_reason: str, n_tokens: int,
207216
)
208217

209218
def snapshot_scheduler(self, *, active: int, pool_in_use: int,
210-
pool_total: int, pending: int) -> None:
219+
pool_total: int, pending: int,
220+
kv_live_bytes: int = 0) -> None:
211221
self.scheduler_active_sessions.set(active)
212222
self.scheduler_pool_in_use.set(pool_in_use)
213223
self.scheduler_pool_total.set(pool_total)
214224
self.scheduler_pending.set(pending)
225+
self.scheduler_kv_live_bytes.set(kv_live_bytes)
215226

216227
# ------------------------------------------------------------------
217228
# Exposition

scripts/bench_agentic/bench_long_session.py

Lines changed: 40 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -15,10 +15,11 @@
1515
* completion tokens (from ``usage.completion_tokens``)
1616
* tokens/s for that turn
1717
* server-side KV pool state, scraped from ``/metrics``::
18-
inference_engine_scheduler_active_sessions
19-
inference_engine_scheduler_pool_in_use
20-
inference_engine_scheduler_pool_size
21-
inference_engine_scheduler_kv_live_bytes
18+
scheduler_active_sessions
19+
scheduler_pool_in_use
20+
scheduler_pool_total
21+
scheduler_pending
22+
scheduler_kv_live_bytes
2223
* client-side RSS (best-effort; uses /proc/self/status on Linux,
2324
psutil if installed, otherwise ``None``)
2425
@@ -35,6 +36,28 @@
3536
session can run for hours without OOM. A single agent driven for
3637
4 hours is therefore the cleanest evidence.
3738
39+
A note on what this bench measures and what it doesn't (per the
40+
analysis of the 2026-05-30 Mac M4 run, ``bench_long_session_mac_
41+
1780130542.aborted.json``):
42+
43+
* **KV memory** stays bounded across hours (the §2.3 claim). The
44+
``scheduler_kv_live_bytes`` gauge is what proves it.
45+
* **Per-turn latency** does NOT stay bounded. The OpenAI
46+
chat-completions protocol is stateless: every turn the client
47+
sends the full history, the server tokenizes it from scratch
48+
and the verifier prefills the entire prompt, so prefill cost
49+
grows linearly with history length. Sink+window only bounds
50+
*generation-phase* memory, not prefill cost. A 30-min run on
51+
Mac M4 showed p50 turn latency growing from ~15 s to ~55 s as
52+
history grew from ~50 to ~3700 tokens. This is a **protocol-
53+
level limitation**, not a memory-stability failure. Cross-
54+
request KV reuse (a v0.4 feature) is the eventual fix; until
55+
then, agent applications should manage prompt length via
56+
summarization or sliding windows.
57+
58+
The bench reports both metrics independently — KV bounded check is
59+
a hard claim, latency drift is a measurement, not a gate.
60+
3861
Usage
3962
-----
4063
@@ -131,11 +154,16 @@ def _client_rss_bytes() -> Optional[int]:
131154
return None
132155

133156

157+
# Names match the ones registered by inference_engine.server.metrics
158+
# (Prometheus-client does NOT add a service prefix). Changing any of
159+
# these breaks the bench's KV-bounded check; if you rename a metric on
160+
# the server, update both ends in the same commit.
134161
_METRIC_NAMES = (
135-
"inference_engine_scheduler_active_sessions",
136-
"inference_engine_scheduler_pool_in_use",
137-
"inference_engine_scheduler_pool_size",
138-
"inference_engine_scheduler_kv_live_bytes",
162+
"scheduler_active_sessions",
163+
"scheduler_pool_in_use",
164+
"scheduler_pool_total",
165+
"scheduler_pending",
166+
"scheduler_kv_live_bytes",
139167
)
140168

141169

@@ -345,7 +373,7 @@ def _print_progress(
345373
) -> None:
346374
last = turns[-1] if turns else None
347375
last_lat = f"{last['latency_s']:.2f}s" if last else "-"
348-
kv = (metrics or {}).get("inference_engine_scheduler_kv_live_bytes")
376+
kv = (metrics or {}).get("scheduler_kv_live_bytes")
349377
kv_str = f"{kv / (1024 * 1024):.1f} MiB" if kv is not None else "?"
350378
print(
351379
f"[bench] t={elapsed/60:6.1f} min | turns={turn_idx:5d} "
@@ -384,7 +412,7 @@ def _bucketize(
384412
bucket_turns = buckets[idx]
385413
latencies = [b["latency_s"] for b in bucket_turns]
386414
kv_vals = [
387-
(b["metrics"] or {}).get("inference_engine_scheduler_kv_live_bytes")
415+
(b["metrics"] or {}).get("scheduler_kv_live_bytes")
388416
for b in bucket_turns
389417
]
390418
kv_vals_clean = [v for v in kv_vals if v is not None]
@@ -416,12 +444,12 @@ def _aggregate(
416444
}
417445
latencies = [t["latency_s"] for t in turns]
418446
kv_series = [
419-
(t["metrics"] or {}).get("inference_engine_scheduler_kv_live_bytes")
447+
(t["metrics"] or {}).get("scheduler_kv_live_bytes")
420448
for t in turns
421449
]
422450
kv_clean = [v for v in kv_series if v is not None]
423451
pool_in_use_series = [
424-
(t["metrics"] or {}).get("inference_engine_scheduler_pool_in_use")
452+
(t["metrics"] or {}).get("scheduler_pool_in_use")
425453
for t in turns
426454
]
427455
pool_in_use_clean = [v for v in pool_in_use_series if v is not None]

tests/inference_engine/memory/test_pool.py

Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -175,3 +175,33 @@ def test_total_kv_bytes_is_sum_across_slabs(pool, cfg):
175175
one = KVSlab(cfg)
176176
expected = 3 * one.kv_bytes
177177
assert pool.total_kv_bytes == expected
178+
179+
180+
# ---------------------------------------------------------------------------
181+
# live_kv_bytes
182+
# ---------------------------------------------------------------------------
183+
184+
185+
def test_live_kv_bytes_zero_when_empty(pool):
186+
"""Idle pool reports 0 live KV bytes (every free slab has
187+
logical_size==0)."""
188+
assert pool.live_kv_bytes == 0
189+
190+
191+
def test_live_kv_bytes_counts_only_in_use_slabs(pool):
192+
"""Only acquired slabs contribute to live_kv_bytes; free slabs
193+
contribute 0 because their logical_size is reset on release."""
194+
s = pool.acquire()
195+
# Simulate the verifier reporting 1024 KV bytes for this session.
196+
s.live_kv_bytes_override = 1024
197+
assert pool.live_kv_bytes == 1024
198+
pool.release(s)
199+
assert pool.live_kv_bytes == 0
200+
201+
202+
def test_live_kv_bytes_aggregates_across_multiple_in_use(pool):
203+
a = pool.acquire()
204+
b = pool.acquire()
205+
a.live_kv_bytes_override = 100
206+
b.live_kv_bytes_override = 250
207+
assert pool.live_kv_bytes == 350

tests/inference_engine/server/test_app_metrics_and_auth.py

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -88,6 +88,23 @@ async def test_metrics_pool_total_gauge_reflects_config(short_engine):
8888
assert "scheduler_pool_total 4.0" in r.text
8989

9090

91+
async def test_metrics_kv_live_bytes_gauge_present_and_zero_at_idle(
92+
short_engine,
93+
):
94+
"""The KV-live-bytes gauge must be exposed and read 0 on an idle
95+
pool (every slab has logical_size == 0). This is the gauge that
96+
bench_long_session.py scrapes to verify the ADR 0006 §2.3
97+
KV-bounded claim, so its presence is part of the public contract.
98+
"""
99+
app = create_app(short_engine, ServerConfig(max_concurrent=2))
100+
async with AsyncClient(transport=ASGITransport(app=app),
101+
base_url="http://t") as c:
102+
r = await c.get("/metrics")
103+
text = r.text
104+
assert "# HELP scheduler_kv_live_bytes" in text
105+
assert "scheduler_kv_live_bytes 0.0" in text
106+
107+
91108
# ---------------------------------------------------------------------------
92109
# OpenAI error envelope
93110
# ---------------------------------------------------------------------------

tests/inference_engine/server/test_metrics.py

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@ def test_build_registers_all_documented_metrics(metrics):
3939
"scheduler_pool_in_use",
4040
"scheduler_pool_total",
4141
"scheduler_pending",
42+
"scheduler_kv_live_bytes",
4243
"scheduler_admission_total",
4344
}
4445
found = set()
@@ -170,22 +171,38 @@ def test_record_completion_clamps_acceptance(metrics):
170171
def test_snapshot_scheduler_sets_gauges(metrics):
171172
metrics.snapshot_scheduler(
172173
active=2, pool_in_use=2, pool_total=4, pending=3,
174+
kv_live_bytes=12345,
173175
)
174176
assert _get_metric_value(metrics, "scheduler_active_sessions") == 2.0
175177
assert _get_metric_value(metrics, "scheduler_pool_in_use") == 2.0
176178
assert _get_metric_value(metrics, "scheduler_pool_total") == 4.0
177179
assert _get_metric_value(metrics, "scheduler_pending") == 3.0
180+
assert _get_metric_value(metrics, "scheduler_kv_live_bytes") == 12345.0
178181

179182

180183
def test_snapshot_scheduler_overwrites_previous(metrics):
181184
metrics.snapshot_scheduler(
182185
active=5, pool_in_use=5, pool_total=8, pending=10,
186+
kv_live_bytes=99999,
183187
)
184188
metrics.snapshot_scheduler(
185189
active=0, pool_in_use=0, pool_total=8, pending=0,
190+
kv_live_bytes=0,
186191
)
187192
assert _get_metric_value(metrics, "scheduler_active_sessions") == 0.0
188193
assert _get_metric_value(metrics, "scheduler_pending") == 0.0
194+
assert _get_metric_value(metrics, "scheduler_kv_live_bytes") == 0.0
195+
196+
197+
def test_snapshot_scheduler_kv_live_bytes_default_zero(metrics):
198+
"""Calling snapshot_scheduler without kv_live_bytes still sets the
199+
gauge — to 0 — so a /metrics scrape never sees a stale prior
200+
value."""
201+
metrics.scheduler_kv_live_bytes.set(123456)
202+
metrics.snapshot_scheduler(
203+
active=1, pool_in_use=1, pool_total=2, pending=0,
204+
)
205+
assert _get_metric_value(metrics, "scheduler_kv_live_bytes") == 0.0
189206

190207

191208
# ---------------------------------------------------------------------------

0 commit comments

Comments
 (0)