mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
fix(savings): surface request growth the tok_saved clamp swallows (#2708)
## Description `tokens_saved` is clamped at zero, so a request the proxy forwards **larger** than it arrived is indistinguishable in the PERF line from one it simply could not compress. Both read `tok_saved=0`. That ambiguity hides real regressions. Anything that appends to the body after compression — proactive context expansion, memory injection — can outweigh the compression it sits on top of and still look like a neutral turn. On the session that prompted this, a request went from 55,161 tokens in to 57,845 out and reported `tok_saved=0`, for 19 consecutive turns, with nothing in the logs distinguishing it from a turn with nothing left to compress. This reports the swallowed amount as `tok_inflated`. ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) - [ ] New feature (non-breaking change that adds functionality) - [ ] Breaking change (fix or feature that would cause existing functionality to change) - [ ] Documentation update - [ ] Performance improvement - [ ] Code refactoring (no functional changes) ## Changes Made - `RequestOutcome.tokens_inflated`: `max(0, optimized_tokens - original_tokens)`, derived from two counts the outcome already carries — **no new plumbing at any of the emit sites**. - Added `tok_inflated=` to the PERF log line, next to `tok_saved=`. Diagnostic only, deliberately. It does **not** feed `tokens_saved` or `attempted_input_tokens`, for two reasons: 1. `attempted_input_tokens = optimized_tokens + tokens_saved` is a *size*, not a signed delta. Letting the second term go negative makes it smaller than the bytes actually forwarded, corrupting the active-savings denominator. 2. Injection paths already book their own cost through the retrieval-drawback channel. A negative landing in `tokens_saved` as well would count the same loss twice. So the clamp stays and the hidden number surfaces beside it. Worth noting there is already a revert-on-inflation guard *before* compression's own inflation can escape (`anthropic.py`, "Optimization inflated tokens … reverting to original messages") — it is only growth added *after* that point which the clamp was silently absorbing. ## Testing - [x] Unit tests pass (`pytest`) - [x] Linting passes (`ruff check .`) - [x] Type checking passes (`mypy headroom`) - [x] New tests added for new functionality - [x] Manual testing performed ### Test Output ```text $ pytest tests/test_request_outcome.py tests/test_cli_perf_format.py -q ============================== 54 passed in 1.56s ============================== $ pytest tests/ -q -k "outcome or perf or savings or stats" ======= 510 passed, 33 skipped, 9674 deselected, 542 warnings in 40.37s ======== $ ruff check headroom/proxy/outcome.py tests/test_request_outcome.py All checks passed! $ ruff format --check headroom/proxy/outcome.py tests/test_request_outcome.py 2 files already formatted $ mypy headroom/proxy/outcome.py --ignore-missing-imports Success: no issues found in 1 source file ``` Four new tests pin the distinction that was missing: shrank (0), no-op compression (0, and `tok_saved` also 0 — the two cases that used to look identical), grew (reports 2684 while `tok_saved` stays 0), and that `attempted_input_tokens` / `savings_pct` keep their unsigned semantics. `tests/test_cli_perf_format.py` parses hand-written PERF fixtures by field name, so adding a field does not disturb it — verified green above. ## Real Behavior Proof ### The field catching a real inflating request - Environment: macOS 15 (arm64), Python 3.13.14. A proxy booted from this branch: `headroom proxy --mode token --backend anthropic --anthropic-api-url http://127.0.0.1:<stub>`, isolated `HOME` so the run could not touch a developer's live logs/store, `HF_HOME` pointed at cached kompress weights so the lossy+CCR-marker path is exercised and proactive expansion can actually arm. - Exact command / steps: three requests over one conversation through the real HTTP path (`x-headroom-cwd: /tmp/proof`, `user-agent: claude-code/1.4.2`): a user turn carrying the real `~/.claude/rules/*.md` text (~8.2k tokens); then `assistant` + a short user turn so that block becomes compressible and gets tracked as a CCR entry; then a follow-up whose leading text block shares vocabulary with it, so proactive expansion fires and appends the original — which is how a request ends up leaving larger than it arrived. PERF lines read from the isolated `~/.headroom/logs/proxy.log`. - Observed result: real PERF output from that run — ```text msgs=1 tok_before=8170 tok_after=9553 tok_saved=0 tok_inflated=1383 ... transforms=router:text_block:mixed msgs=3 tok_before=8184 tok_after=9567 tok_saved=0 tok_inflated=1383 ... transforms=router:text_block:mixed msgs=5 tok_before=8245 tok_after=11880 tok_saved=0 tok_inflated=3635 ... transforms=router:text_block:mixed ``` Correlated from the same run: `CCR Tracker: Proactively expanded f0cf4efb42373ec225f57725 (1417 items)`, and the stub upstream confirms the block reached the wire (`has_expansion_block: true`, forwarded body 54,130 B on the third request). Every one of those turns reports `tok_saved=0`. Before this change that is all the log said, and it is the same thing it says when there was simply nothing left to compress. `tok_inflated=3635` is the number that was missing. For contrast, the same scenario run against a build where the request genuinely shrinks reported `tok_before=8245 tok_after=7359 tok_saved=886` — that build predates this field, so it does not print `tok_inflated`; the point is only that the inflating and shrinking cases are the two states the field has to separate, and on `main` today both render as `tok_saved=0` whenever the growth path is taken. The `tok_inflated=0` case on a shrinking request is covered by unit test. ### Scale of what was hidden From a live `--mode token` proxy on Claude Code traffic across four rotated logs: **305 of 3,743 requests (8%)** had `tok_after > tok_before` while every one reported `tok_saved=0` — 192,829 tokens of growth rendered as "nothing to compress". The worst single session held +2,643/turn for 19 consecutive turns. - Not tested: the `headroom perf` CLI was not run against a real log file containing the new field — it parses by field name and `tests/test_cli_perf_format.py` is green, but that is test-level rather than end-to-end evidence. Streaming responses were not exercised (the stub replies non-streaming), so the streaming emit path carries the new field on the strength of sharing `emit_request_outcome` rather than by observation. No dashboard or Prometheus consumer was re-run. ## Review Readiness - [x] I have performed a self-review - [x] This PR is ready for human review ## Checklist - [x] My code follows the project's style guidelines - [x] I have performed a self-review of my code - [x] I have commented my code, particularly in hard-to-understand areas - [ ] I have made corresponding changes to the documentation - [x] My changes generate no new warnings - [x] I have added tests that prove my fix is effective or that my feature works - [x] New and existing unit tests pass locally with my changes - [x] I did **not** edit `CHANGELOG.md` — it is generated by release-please from my Conventional Commit PR title (a CI guard enforces this) ## Screenshots (if applicable) N/A — one added field on an existing log line; no user-facing surface. ## Additional Notes - Independent of #2706 and #2707 — verified `conflicts=0` via `git merge-tree`; mergeable in any order. - Related but deliberately out of scope: `main` has no producer for retrieval-cost accounting (`record_savings_event` takes no `kind`/`tokens_retrieved`, and nothing writes `tokens_retrieved` anywhere), so proactive expansion's cost is not booked into net savings at all. Adding that channel is a cross-cutting accounting change and belongs in its own PR; this one only makes the growth visible in the log.
This commit is contained in:
parent
dcb674b5e4
commit
184146b688
2 changed files with 65 additions and 0 deletions
|
|
@ -191,6 +191,28 @@ class RequestOutcome:
|
|||
return 0.0
|
||||
return self.tokens_saved / self.original_tokens * 100.0
|
||||
|
||||
@property
|
||||
def tokens_inflated(self) -> int:
|
||||
"""Tokens the forwarded request grew by, if it ended up larger.
|
||||
|
||||
``tokens_saved`` is clamped at zero, so a request that leaves the
|
||||
proxy *bigger* than it arrived is indistinguishable from one the
|
||||
proxy simply could not compress: both report ``tok_saved=0``. That
|
||||
ambiguity hides real regressions — anything that adds to the body
|
||||
after compression (proactive context expansion, memory injection)
|
||||
can outweigh the compression it sits on top of and still look like
|
||||
a neutral turn.
|
||||
|
||||
Report the swallowed amount alongside it so the two cases are
|
||||
distinguishable. This is diagnostic only: it deliberately does not
|
||||
feed ``tokens_saved`` or ``attempted_input_tokens``, because
|
||||
``attempted_input_tokens = optimized_tokens + tokens_saved`` is a
|
||||
size, not a signed delta, and because injection paths already book
|
||||
their own cost through the retrieval-drawback channel — letting a
|
||||
negative land here too would count it twice.
|
||||
"""
|
||||
return max(0, self.optimized_tokens - self.original_tokens)
|
||||
|
||||
@classmethod
|
||||
def from_stream(
|
||||
cls,
|
||||
|
|
@ -512,6 +534,7 @@ async def emit_request_outcome(handler: Any, outcome: RequestOutcome) -> None:
|
|||
f"model={outcome.model} msgs={outcome.num_messages} "
|
||||
f"tok_before={outcome.original_tokens} tok_after={outcome.optimized_tokens} "
|
||||
f"tok_saved={outcome.tokens_saved} "
|
||||
f"tok_inflated={outcome.tokens_inflated} "
|
||||
f"tool_saved={tool_saved} "
|
||||
f"total_saved={total_saved} "
|
||||
f"cache_read={outcome.cache_read_tokens} cache_write={outcome.cache_write_tokens} "
|
||||
|
|
|
|||
|
|
@ -431,6 +431,7 @@ async def test_funnel_emits_perf_log_with_canonical_shape(
|
|||
assert "tok_before=1000" in line
|
||||
assert "tok_after=300" in line
|
||||
assert "tok_saved=700" in line
|
||||
assert "tok_inflated=0" in line
|
||||
assert "cache_read=200" in line
|
||||
assert "cache_write=100" in line
|
||||
assert "cache_hit_pct=67" in line # 200/(200+100) * 100 = 67
|
||||
|
|
@ -651,3 +652,44 @@ def test_from_stream_threads_waste_signals_for_openai_via_backend_site() -> None
|
|||
waste_signals={"skipped_units": 3, "applied_units": 7},
|
||||
)
|
||||
assert o.waste_signals == {"skipped_units": 3, "applied_units": 7}
|
||||
|
||||
|
||||
# ── tokens_inflated: distinguishing "could not compress" from "grew" ──
|
||||
|
||||
|
||||
def test_tokens_inflated_is_zero_when_request_shrank() -> None:
|
||||
"""A normally-compressed request reports no inflation."""
|
||||
o = _outcome(original_tokens=1000, optimized_tokens=300, tokens_saved=700)
|
||||
assert o.tokens_inflated == 0
|
||||
|
||||
|
||||
def test_tokens_inflated_is_zero_when_compression_was_a_no_op() -> None:
|
||||
"""Nothing compressible is not the same as growth — both keep tok_saved=0."""
|
||||
o = _outcome(original_tokens=1000, optimized_tokens=1000, tokens_saved=0)
|
||||
assert o.tokens_inflated == 0
|
||||
assert o.tokens_saved == 0
|
||||
|
||||
|
||||
def test_tokens_inflated_reports_growth_the_clamp_swallows() -> None:
|
||||
"""A request forwarded larger than it arrived is no longer indistinguishable.
|
||||
|
||||
tokens_saved stays clamped at 0 (its consumers treat it as a size, and
|
||||
injection paths book their own cost separately), so the grown amount has
|
||||
to surface as its own number or the regression is invisible.
|
||||
"""
|
||||
o = _outcome(original_tokens=55161, optimized_tokens=57845, tokens_saved=0)
|
||||
assert o.tokens_saved == 0
|
||||
assert o.tokens_inflated == 2684
|
||||
|
||||
|
||||
def test_tokens_inflated_does_not_disturb_derived_sizes() -> None:
|
||||
"""attempted_input_tokens and savings_pct keep their unsigned semantics."""
|
||||
o = _outcome(
|
||||
original_tokens=55161,
|
||||
optimized_tokens=57845,
|
||||
tokens_saved=0,
|
||||
attempted_input_tokens=57845,
|
||||
)
|
||||
assert o.attempted_input_tokens == 57845
|
||||
assert o.savings_pct == 0.0
|
||||
assert o.tokens_inflated == 2684
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue