1 commit

Author	SHA1	Message	Date
Tejas Chopra	04e1517ede	fix(telemetry): stop mixing tokenizer scales in RequestOutcome, and fix the overhead framing (#2756) ... ## Description Two defects found by reading real beacon payloads, not by inspection. ### 1. `eligible_pct: 120` A gpt-4o-mini session shipped this: ```json "tokens": {"original": 10, "attempted": 12, "input": 12, "saved": 0}, "rates": {"eligible_pct": 120} ``` 120% is structurally impossible — you cannot attempt to compress more than arrived. And nothing had grown. `original_tokens` is our **local tokenizer** count. `optimized_tokens` on the OpenAI path carried the **provider's** `usage.prompt_tokens`. Our estimator undercounted gpt-4o-mini by 2 tokens on a 10-token request, and every quantity derived from that pair inherited the mismatch: - `attempted_input_tokens = optimized + saved` → 12, exceeding `original` → `eligible_pct` 120, `yield_pct` contaminated - `tokens_inflated` (added in #2708) → reported **2 tokens of phantom growth** `optimized_tokens` was dual-purpose by design — *"post-compression bytes actually forwarded, for `input_tokens` and `tok_after`"*. Billing wants the provider's count; deltas need the same ruler as `original_tokens`. Those are different jobs sharing one field. This is the same class of bug as #2743, on the request path instead of `/v1/compress`, and it is the exact false positive I flagged as theoretical when reviewing #2708 — where I measured the margin on a real 722-request log as **exactly zero**, so any provider counting above our estimator would flip it. gpt-4o-mini does, and it is now in production telemetry. ### 2. `overhead_pct` was documented as wall-clock, and is not A 1393-turn session shipped `latency_ms_total: 16396565.8` against `duration_s: 8904` — **4.55h of latency inside a 2.47h session, 1.84× over wall clock.** Both terms are sums over turns, and turns run concurrently (parallel tool calls, subagents, several clients per proxy), so each sum over-counts elapsed time. `overhead_pct` is still a meaningful latency-weighted per-request share, but the comment claiming *"what fraction of wall-clock did Headroom itself add?"* was wrong, and shipping `latency_ms_total` beside `duration_s` invites a comparison that yields nonsense. Closes # ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) ## Changes Made **Scale split (`outcome.py`, `handlers/openai.py`)** - `optimized_tokens` is now always the **local** count — same tokenizer as `original_tokens`, so every delta built from the pair is coherent. - New optional `provider_input_tokens` carries the provider's own count. Defaults to `0`, so the other emit sites need no change. - Cost and volume totals read `provider_input_tokens or optimized_tokens`, so **billing is unchanged** wherever a provider reports usage, and falls back exactly as before where it doesn't. - Removes a band-aid: one of the three OpenAI sites already computed `effective_original_tokens = max(original_tokens, optimized + saved)`, inflating `original` upward so `attempted` could not exceed it. That hid the symptom at one site while the other two shipped the impossible ratio. **Overhead framing (`telemetry/session.py`)** - Corrects the wall-clock comment on `overhead_pct` and states what it actually is. - Documents that `latency_ms_total` is a sum of per-request durations, not elapsed time, and why it can exceed `session.duration_s`. - Adds `overhead_ms_per_turn` and `latency_ms_per_turn` — unambiguous under concurrency and comparable across sessions. - Field names kept for schema-v1 consumers; **additive only**, no schema bump. ## Testing - [x] Unit tests pass (new file) - [x] Linting passes (`ruff check` + `format --check`, pinned 0.15.17) - [x] New tests added for new functionality - [x] Manual testing performed ### Test Output ```text $ uvx ruff@0.15.17 check headroom/proxy/outcome.py headroom/proxy/handlers/openai.py headroom/telemetry/session.py All checks passed! $ uvx ruff@0.15.17 format --check <same three> 3 files already formatted $ pytest tests/test_outcome_token_scale.py -q 5 passed in 0.24s ``` ## Real Behavior Proof - **Environment:** macOS 26.4 arm64, isolated git worktree off `upstream/main`, throwaway venv (see caveat). Replayed both reported payloads through the corrected arithmetic: ```text ENTRY 1 (gpt-4o-mini, the eligible_pct:120 case) BEFORE: original=10 (local) optimized=12 (PROVIDER) saved=0 attempted = 12+0 = 12 eligible_pct = 120.0 <- impossible tok_inflated = max(0, 12-10) = 2 <- phantom AFTER : original=10 (local) optimized=10 (local) provider_input=12 attempted = 10+0 = 10 eligible_pct = 100.0 tok_inflated = 0 billed_input = 12 -> cost/cache math unchanged ENTRY 2 (1393 turns, the overhead case) latency_ms_total = 16397s vs duration 8904s -> 1.84x wall clock NEW overhead_ms_per_turn = 333.5 latency_ms_per_turn = 11770.7 wall clock per turn = 6392.0 -> per-turn latency exceeds it => concurrency ``` Genuine post-compression growth still surfaces: `55,161 → 57,845` reports `tokens_inflated = 2,684` (pinned as a test), so the fix doesn't mute what #2708 exists to show. - **Not tested locally beyond the new file.** The repo venv currently has no `pytest`, no `ruff`, and no compiled `headroom._core`, so I used a throwaway venv. The outcome/telemetry suites fail there for missing deps — `click` (12/12), then `headroom._core` (10/10) — with **zero assertion failures**, and an **identical failure set on this branch and on clean `upstream/main`** in the same env. So they are environment-only, not regressions. CI on this PR is the authoritative signal for the full suite. - Unrelated: `Wrap E2E / docker-wrap-e2e` is currently red on `main` from a quay.io CDN `tls: internal error` pulling the manylinux base image — infrastructure, transient, and green on the three prior runs. ## 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 - [x] My changes generate no new warnings - [x] I have added tests that prove my fix is effective - [x] I did **not** edit `CHANGELOG.md` ## Follow-ups not in this PR - **`cache_write` and `uncached` double-count** on inferred-cache providers. The same beacon entry shows `input: 12, cache_read: 0, cache_write: 12, uncached: 12` — both fields describe the identical 12 tokens, because `_infer_openai_cache_write_tokens` and `uncached_input_tokens` are computed the same way (`input − cache_read`). Any consumer summing them gets 2×. The payload also carries no `cache_inferred` flag, so a reader can't distinguish an inferred write from an Anthropic-reported one. - **No skip reason for compression itself.** That entry records `memory_skip:no_handler` but nothing explains why compression didn't fire; "below the size floor" and "compressor failed" are indistinguishable — the same ambiguity #2708 just removed for inflation. - **`eligible_pct` can still legitimately exceed 100** when a request genuinely grows after compression (memory injection, proactive expansion), since `attempted = optimized + saved` uses the forwarded size. Left alone deliberately: clamping would hide real inflation, and `tokens_inflated` now expresses it properly. 🤖 Generated with [Claude Code](https://claude.com/claude-code)	2026-08-04 13:02:47 -07:00