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:
nangsontay 2026-08-04 10:18:01 +07:00 committed by GitHub
parent dcb674b5e4
commit 184146b688
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
2 changed files with 65 additions and 0 deletions

View file

@ -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} "

View file

@ -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