mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
fix(proxy/perf): tokenizer-consistent token accounting + surface tool-schema savings (#2542)
## Description Follow-up to #2520 (turn-hook message-fold accounting). While validating that PR on live Claude Code traffic, two accounting defects surfaced: 1. **Impossible/misleading token deltas.** The handler and the compression pipeline use *different* token estimators — the handler's `EstimatingTokenCounter(3.5)` (or real tiktoken on OpenAI) vs `content_router`'s adaptive `EstimatingTokenCounter()`. Cross-assigning `original_tokens` (handler) against `optimized_tokens = result.tokens_after` (pipeline) put the two endpoints on different scales, producing **`tok_after > tok_before` on 101/783 PERF lines** and phantom savings on `transforms=none` lines. It also made the turn-hook recount fire on the *scale difference* rather than a real fold, emitting a **spurious `turn_hook` tag with `tok_saved=0`**. 2. **Tool-schema savings were invisible.** Tool deferral (`defer_loading`) and turn-hook tool shrink save thousands of tool-schema tokens, but `tok_before`/`tok_after` count **messages only** — so a tool-heavy turn logged `tok_saved=0` while genuinely saving ~29k tool-schema tokens, reading as "no compression." Closes # ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) - [x] Performance improvement - [ ] Breaking change - [ ] Documentation update - [ ] Code refactoring (no functional changes) ## Changes Made - **Tier B.1 — tokenizer-consistent accounting.** On the Anthropic and OpenAI-chat paths, recount **both** endpoints with the **same** tokenizer (pre-compression snapshot vs final outbound messages) right before the outcome is recorded. This puts `tok_before`/`tok_after` on one scale (fixes the inflated + phantom lines), and it subsumes any turn-hook fold. `turn_hook` is now attributed **only** when the hook itself reduced tokens (same-tokenizer pre vs post), not when a recount merely normalized a scale difference. OpenAI preserves its existing tool-schema delta folding. - **Surface tool-schema savings.** New `tool_saved=` field on the PERF line (summed from `tool_search_deferred_tokens` + `turn_hook_tools_saved_tokens` tags) and a separate `Tool saved` line in `headroom perf`. Additive + backward-compatible (key=value parse; old lines default to 0). `tok_saved` still means message savings, so ratios and calibrated thresholds are unaffected. - The OpenAI **Responses** path already accumulates per-transform deltas (each consistent within its own transform), so it isn't exposed to the cross-scale subtraction bug and needs no change. ## Testing - [x] Unit tests pass (`pytest`) - [x] Linting passes (`ruff check` + `ruff format --check`) - [x] Type checking passes (`mypy`) - [x] Manual testing performed ### Test Output ```text $ ruff check headroom/proxy/handlers/anthropic.py headroom/proxy/handlers/openai.py \ headroom/proxy/outcome.py headroom/perf/analyzer.py All checks passed! $ ruff format --check <same files> 4 files already formatted $ mypy <same files> Success: no issues found in 4 source files $ pytest tests/test_turn_hooks.py tests/test_openai_chat_turn_hooks.py \ tests/test_openai_responses_context_compaction.py -q 26 passed in 14.34s ``` ## Real Behavior Proof - **Environment:** local proxy `headroom proxy --port 8793 --proxy-extension lossless_guard`, with `HEADROOM_LOSSLESS_GUARD_LOSSY=1`, `HEADROOM_TOOL_SEARCH=1`, model `claude-haiku-4-5` (Anthropic path = the one Claude Code uses). - **Observed, before vs after this PR:** - foldable tool_result: `tok_before=607 tok_after=178 tok_saved=429 transforms=turn_hook` (real fold, correctly attributed) - plain multi-turn (nothing foldable): `tok_before=3700 tok_after=3700 tok_saved=0 transforms=none` — **no inflation, no spurious `turn_hook`** (before this PR: same request showed a spurious `turn_hook`) - tool-heavy (12 tools): `tok_saved=0 tool_saved=1794` → `headroom perf` shows `Total saved: … (messages)` **and** `Tool saved: 1,794 tokens (tool schemas, deferral)` (before: the 1,794 was invisible) - **Not tested:** OpenAI chat/Responses paths verified by unit test, not a live client run (local setup routes Claude Code through the Anthropic handler only). ## 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 - [ ] Documentation changes — N/A (internal accounting; `tool_saved` is self-describing in `headroom perf`) - [x] My changes generate no new warnings - [x] New and existing unit tests pass locally with my changes - [x] I did **not** edit `CHANGELOG.md` ## Additional Notes - Behavior is unchanged when no turn hook is registered for the *attribution* tag; the consistency recount runs unconditionally so pure-OSS installs also get correct before/after (it only ever makes the two endpoints comparable — it never fabricates savings). - Follow-up (separate PR, intentionally not here): swap the char-estimator for a real BPE (tiktoken `o200k_base`) for private-tokenizer models like Claude. That's the "Tier B.2" accuracy upgrade; it shifts absolute numbers ~10–20% and touches calibrated thresholds, so it needs its own recalibration pass.
This commit is contained in:
parent
fa4763761b
commit
1cc53c9c92
4 changed files with 72 additions and 24 deletions
|
|
@ -146,6 +146,7 @@ class PerfRecord:
|
||||||
tokens_before: int = 0
|
tokens_before: int = 0
|
||||||
tokens_after: int = 0
|
tokens_after: int = 0
|
||||||
tokens_saved: int = 0
|
tokens_saved: int = 0
|
||||||
|
tool_saved: int = 0
|
||||||
cache_read: int = 0
|
cache_read: int = 0
|
||||||
cache_write: int = 0
|
cache_write: int = 0
|
||||||
cache_hit_pct: int = 0
|
cache_hit_pct: int = 0
|
||||||
|
|
@ -351,6 +352,7 @@ def parse_log_files(last_n_hours: float = 168.0) -> PerfReport:
|
||||||
tokens_before=int(kv.get("tok_before", 0)),
|
tokens_before=int(kv.get("tok_before", 0)),
|
||||||
tokens_after=int(kv.get("tok_after", 0)),
|
tokens_after=int(kv.get("tok_after", 0)),
|
||||||
tokens_saved=int(kv.get("tok_saved", 0)),
|
tokens_saved=int(kv.get("tok_saved", 0)),
|
||||||
|
tool_saved=int(kv.get("tool_saved", 0)),
|
||||||
cache_read=int(kv.get("cache_read", 0)),
|
cache_read=int(kv.get("cache_read", 0)),
|
||||||
cache_write=int(kv.get("cache_write", 0)),
|
cache_write=int(kv.get("cache_write", 0)),
|
||||||
cache_hit_pct=int(kv.get("cache_hit_pct", 0)),
|
cache_hit_pct=int(kv.get("cache_hit_pct", 0)),
|
||||||
|
|
@ -537,11 +539,17 @@ def format_report(report: PerfReport) -> str:
|
||||||
total_before = sum(r.tokens_before for r in records)
|
total_before = sum(r.tokens_before for r in records)
|
||||||
total_after = sum(r.tokens_after for r in records)
|
total_after = sum(r.tokens_after for r in records)
|
||||||
total_saved = sum(r.tokens_saved for r in records)
|
total_saved = sum(r.tokens_saved for r in records)
|
||||||
|
total_tool_saved = sum(r.tool_saved for r in records)
|
||||||
pct = (total_saved / total_before * 100) if total_before > 0 else 0
|
pct = (total_saved / total_before * 100) if total_before > 0 else 0
|
||||||
|
|
||||||
lines.append(f"Requests: {len(records)}")
|
lines.append(f"Requests: {len(records)}")
|
||||||
lines.append(f"Tokens: {total_before:,} -> {total_after:,} ({pct:.1f}% reduction)")
|
lines.append(f"Tokens: {total_before:,} -> {total_after:,} ({pct:.1f}% reduction)")
|
||||||
lines.append(f"Total saved: {total_saved:,} tokens")
|
lines.append(f"Total saved: {total_saved:,} tokens (messages)")
|
||||||
|
# Tool-schema savings (deferral + turn-hook tool shrink) are counted apart
|
||||||
|
# from message compression — messages never include tool bytes — so surface
|
||||||
|
# them explicitly instead of hiding a tool-heavy turn's win behind tok_saved=0.
|
||||||
|
if total_tool_saved > 0:
|
||||||
|
lines.append(f"Tool saved: {total_tool_saved:,} tokens (tool schemas, deferral)")
|
||||||
lines.append("")
|
lines.append("")
|
||||||
|
|
||||||
# Per-model breakdown with list prices
|
# Per-model breakdown with list prices
|
||||||
|
|
@ -786,6 +794,7 @@ PERF_RECORD_FIELDS = [
|
||||||
"tokens_before",
|
"tokens_before",
|
||||||
"tokens_after",
|
"tokens_after",
|
||||||
"tokens_saved",
|
"tokens_saved",
|
||||||
|
"tool_saved",
|
||||||
"cache_read",
|
"cache_read",
|
||||||
"cache_write",
|
"cache_write",
|
||||||
"cache_hit_pct",
|
"cache_hit_pct",
|
||||||
|
|
|
||||||
|
|
@ -2385,6 +2385,7 @@ class AnthropicHandlerMixin:
|
||||||
run_request_hooks,
|
run_request_hooks,
|
||||||
)
|
)
|
||||||
|
|
||||||
|
_pre_hook_tokens: int | None = None
|
||||||
if registered_turn_hooks():
|
if registered_turn_hooks():
|
||||||
_req_ctx = TurnContext(
|
_req_ctx = TurnContext(
|
||||||
provider="anthropic",
|
provider="anthropic",
|
||||||
|
|
@ -2393,6 +2394,13 @@ class AnthropicHandlerMixin:
|
||||||
tools=body.get("tools"),
|
tools=body.get("tools"),
|
||||||
config=self.config,
|
config=self.config,
|
||||||
)
|
)
|
||||||
|
# Snapshot BEFORE the hook (same tokenizer) so we can tell whether the
|
||||||
|
# hook itself folded — comparing against the pipeline's optimized_tokens
|
||||||
|
# instead conflates a real fold with a cross-estimator delta (see below).
|
||||||
|
try:
|
||||||
|
_pre_hook_tokens = tokenizer.count_messages(optimized_messages)
|
||||||
|
except Exception:
|
||||||
|
_pre_hook_tokens = None
|
||||||
run_request_hooks(_req_ctx)
|
run_request_hooks(_req_ctx)
|
||||||
if _req_ctx.messages is not optimized_messages:
|
if _req_ctx.messages is not optimized_messages:
|
||||||
optimized_messages = _req_ctx.messages
|
optimized_messages = _req_ctx.messages
|
||||||
|
|
@ -2400,21 +2408,27 @@ class AnthropicHandlerMixin:
|
||||||
if _req_ctx.tools is not body.get("tools"):
|
if _req_ctx.tools is not body.get("tools"):
|
||||||
tools = _req_ctx.tools
|
tools = _req_ctx.tools
|
||||||
body["tools"] = tools
|
body["tools"] = tools
|
||||||
# Turn hooks (e.g. lossless-guard) fold messages AFTER the pipeline's
|
|
||||||
# token accounting, and may mutate them IN PLACE (identity unchanged),
|
# Consistency: report tok_before/tok_after with ONE tokenizer. The pipeline
|
||||||
# so their savings were invisible to the PERF line / `headroom perf`
|
# and the handler use different token estimators, and cache-mode branches
|
||||||
# (record_compression /stats already counts them). Re-count regardless
|
# can leave original_tokens (handler, line ~1049) and optimized_tokens
|
||||||
# of replace-vs-in-place so original->optimized reflects the fold too.
|
# (pipeline, result.tokens_after) on different scales — which produced
|
||||||
# tokenizer is initialized → count_messages is a pure CPU call here.
|
# impossible tok_after>tok_before deltas and masked real savings. Recount
|
||||||
# Only ever lowers optimized_tokens.
|
# BOTH endpoints (pre-compression snapshot vs final outbound messages) with
|
||||||
try:
|
# the handler tokenizer so the delta is meaningful. This also captures any
|
||||||
_hooked_tokens = tokenizer.count_messages(optimized_messages)
|
# turn-hook fold (optimized_messages is post-hook). Runs unconditionally.
|
||||||
if _hooked_tokens < optimized_tokens:
|
try:
|
||||||
optimized_tokens = _hooked_tokens
|
_orig_snapshot = original_client_messages # noqa: F821 (bound at request start)
|
||||||
tokens_saved = max(0, original_tokens - optimized_tokens)
|
original_tokens = tokenizer.count_messages(_orig_snapshot)
|
||||||
transforms_applied.append("turn_hook")
|
optimized_tokens = tokenizer.count_messages(optimized_messages)
|
||||||
except Exception:
|
tokens_saved = max(0, original_tokens - optimized_tokens)
|
||||||
logger.debug("turn-hook token re-count skipped", exc_info=True)
|
# Attribute the fold to the hook ONLY when the hook itself reduced
|
||||||
|
# tokens (same-tokenizer pre vs post) — not when the recount above
|
||||||
|
# merely normalized a cross-estimator scale difference.
|
||||||
|
if _pre_hook_tokens is not None and optimized_tokens < _pre_hook_tokens:
|
||||||
|
transforms_applied.append("turn_hook")
|
||||||
|
except Exception:
|
||||||
|
logger.debug("consistency token re-count skipped", exc_info=True)
|
||||||
|
|
||||||
# Output shaping (opt-in via HEADROOM_OUTPUT_SHAPER): verbosity
|
# Output shaping (opt-in via HEADROOM_OUTPUT_SHAPER): verbosity
|
||||||
# steering appended to the system-prompt tail + effort routing on
|
# steering appended to the system-prompt tail + effort routing on
|
||||||
|
|
|
||||||
|
|
@ -3453,6 +3453,12 @@ class OpenAIHandlerMixin:
|
||||||
body["tools"] = tools
|
body["tools"] = tools
|
||||||
if presend_event.headers is not None:
|
if presend_event.headers is not None:
|
||||||
headers = presend_event.headers
|
headers = presend_event.headers
|
||||||
|
# Consistency: recount BOTH endpoints with the provider tokenizer. An upstream
|
||||||
|
# branch may have left original_tokens in the pipeline's char-estimator scale
|
||||||
|
# (result.tokens_before), which mismatches optimized_tokens (provider tokenizer)
|
||||||
|
# and yields impossible tok_after>tok_before. Recount original from the
|
||||||
|
# pre-compression snapshot so the message delta is on one scale.
|
||||||
|
original_tokens = tokenizer.count_messages(original_client_messages)
|
||||||
optimized_tokens = tokenizer.count_messages(body["messages"])
|
optimized_tokens = tokenizer.count_messages(body["messages"])
|
||||||
if tool_tokens_before_compaction > 0:
|
if tool_tokens_before_compaction > 0:
|
||||||
try:
|
try:
|
||||||
|
|
@ -3462,7 +3468,7 @@ class OpenAIHandlerMixin:
|
||||||
if 0 < tool_tokens_after_compaction < tool_tokens_before_compaction:
|
if 0 < tool_tokens_after_compaction < tool_tokens_before_compaction:
|
||||||
original_tokens += tool_tokens_before_compaction
|
original_tokens += tool_tokens_before_compaction
|
||||||
optimized_tokens += tool_tokens_after_compaction
|
optimized_tokens += tool_tokens_after_compaction
|
||||||
tokens_saved = original_tokens - optimized_tokens
|
tokens_saved = max(0, original_tokens - optimized_tokens)
|
||||||
|
|
||||||
# Turn hooks (opt-in extensions): a registered hook may rewrite the
|
# Turn hooks (opt-in extensions): a registered hook may rewrite the
|
||||||
# outbound tools/messages before we send. Buffered requests only — a
|
# outbound tools/messages before we send. Buffered requests only — a
|
||||||
|
|
@ -3489,6 +3495,13 @@ class OpenAIHandlerMixin:
|
||||||
tools=_th_tools_before,
|
tools=_th_tools_before,
|
||||||
config=self.config,
|
config=self.config,
|
||||||
)
|
)
|
||||||
|
# Snapshot messages BEFORE the hook (same tokenizer) so we can tell whether
|
||||||
|
# the hook itself folded — comparing against optimized_tokens instead
|
||||||
|
# conflates a real fold with a cross-estimator scale delta.
|
||||||
|
try:
|
||||||
|
_th_msg_before: int | None = tokenizer.count_messages(body["messages"])
|
||||||
|
except Exception:
|
||||||
|
_th_msg_before = None
|
||||||
run_request_hooks(_th_ctx)
|
run_request_hooks(_th_ctx)
|
||||||
# A hook may either replace ctx.messages/ctx.tools or mutate them in
|
# A hook may either replace ctx.messages/ctx.tools or mutate them in
|
||||||
# place (the contract allows both). Use object identity only to decide
|
# place (the contract allows both). Use object identity only to decide
|
||||||
|
|
@ -3500,15 +3513,17 @@ class OpenAIHandlerMixin:
|
||||||
if _th_ctx.tools is not _th_tools_before:
|
if _th_ctx.tools is not _th_tools_before:
|
||||||
tools = _th_ctx.tools
|
tools = _th_ctx.tools
|
||||||
body["tools"] = tools
|
body["tools"] = tools
|
||||||
# Message folds land AFTER the accounting above, and a hook may mutate
|
# Recount messages after the hook (it may fold in place), preserving the
|
||||||
# messages IN PLACE (identity unchanged), so re-count regardless or
|
# tool-schema delta already folded into the headline above and keeping the
|
||||||
# `headroom perf` sees 0 for them (record_compression /stats already
|
# scale consistent with original_tokens (both provider tokenizer).
|
||||||
# does). tokenizer is initialized → pure CPU. Only lowers the count.
|
|
||||||
try:
|
try:
|
||||||
_th_msg_after = tokenizer.count_messages(body["messages"])
|
_th_msg_after = tokenizer.count_messages(body["messages"])
|
||||||
if _th_msg_after < optimized_tokens:
|
optimized_tokens = _th_msg_after
|
||||||
optimized_tokens = _th_msg_after
|
if 0 < tool_tokens_after_compaction < tool_tokens_before_compaction:
|
||||||
tokens_saved = max(0, original_tokens - optimized_tokens)
|
optimized_tokens += tool_tokens_after_compaction
|
||||||
|
tokens_saved = max(0, original_tokens - optimized_tokens)
|
||||||
|
# Attribute to the hook ONLY when the hook itself reduced tokens.
|
||||||
|
if _th_msg_before is not None and _th_msg_after < _th_msg_before:
|
||||||
transforms_applied.append("turn_hook")
|
transforms_applied.append("turn_hook")
|
||||||
except Exception:
|
except Exception:
|
||||||
logger.debug("turn-hook token re-count skipped", exc_info=True)
|
logger.debug("turn-hook token re-count skipped", exc_info=True)
|
||||||
|
|
|
||||||
|
|
@ -470,11 +470,21 @@ async def emit_request_outcome(handler: Any, outcome: RequestOutcome) -> None:
|
||||||
# line unchanged, and gives ``headroom perf --client X``
|
# line unchanged, and gives ``headroom perf --client X``
|
||||||
# parsers a clean key to filter on.
|
# parsers a clean key to filter on.
|
||||||
client_part = f" client={outcome.client}" if outcome.client else ""
|
client_part = f" client={outcome.client}" if outcome.client else ""
|
||||||
|
# Tool-schema savings are tracked separately from message compression: tool
|
||||||
|
# deferral (defer_loading) and turn-hook tool shrink don't move tok_before/after
|
||||||
|
# (those count messages only), so a tool-heavy turn shows tok_saved=0 while
|
||||||
|
# genuinely saving thousands of tool-schema tokens. Surface it as its own field
|
||||||
|
# so `headroom perf` / log readers see the whole picture.
|
||||||
|
_tags = outcome.tags or {}
|
||||||
|
tool_saved = int(_tags.get("tool_search_deferred_tokens", 0) or 0) + int(
|
||||||
|
_tags.get("turn_hook_tools_saved_tokens", 0) or 0
|
||||||
|
)
|
||||||
logger.info(
|
logger.info(
|
||||||
f"[{outcome.request_id}] PERF "
|
f"[{outcome.request_id}] PERF "
|
||||||
f"model={outcome.model} msgs={outcome.num_messages} "
|
f"model={outcome.model} msgs={outcome.num_messages} "
|
||||||
f"tok_before={outcome.original_tokens} tok_after={outcome.optimized_tokens} "
|
f"tok_before={outcome.original_tokens} tok_after={outcome.optimized_tokens} "
|
||||||
f"tok_saved={outcome.tokens_saved} "
|
f"tok_saved={outcome.tokens_saved} "
|
||||||
|
f"tool_saved={tool_saved} "
|
||||||
f"cache_read={outcome.cache_read_tokens} cache_write={outcome.cache_write_tokens} "
|
f"cache_read={outcome.cache_read_tokens} cache_write={outcome.cache_write_tokens} "
|
||||||
f"cache_hit_pct={outcome.cache_hit_pct} "
|
f"cache_hit_pct={outcome.cache_hit_pct} "
|
||||||
f"opt_ms={outcome.overhead_ms:.0f} "
|
f"opt_ms={outcome.overhead_ms:.0f} "
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue