6krrt/plans/pinch-instrumentation-and-token-accounting.md

Pinch: instrument the 93% lever, then fix what it counts

Status: done -- pinch_summary in metrics.py

Date: 2026-09-01 Status: FINAL — ready to implement. Two commits, small. Follows: plans/conceptual-review-premise-and-execution.md finding #3.

---

1. Why this is the highest-leverage item in the repo

Decomposing the estimated cost of all 9,007 real chat decisions at the shipped assumed_cache_rate: 0.917:

prompt share of est cost:  $105.48  (92.6%)
completion share:            $8.40   (7.4%)

real billed tokens: 1,190,607,380 prompt / 5,880,453 completion  = 202:1

Pinch is the only thing in this codebase that touches the 92.6%. Every routing decision, every proficiency score, every tier rule adjudicates the other 7.4% plus whatever model-price multiple applies. A 20% reduction in prompt tokens is worth more than every routing decision in the measured window combined.

And it is currently the least observable component in the system.

---

2. Nothing can see it

surface	reports pinch?
journal	no — dispatcher.py:2414 and :2646 call logs.debug, logging.level is info. Zero pinch lines in 7 days of journal.
/metrics	no
route_decisions	no columns
TUI / admin dashboard	no

prune_context returns a perfectly good stats dict — pruned, original_tokens, final_tokens, tokens_saved — and every one of those values is computed, logged at a level nobody runs, and discarded.

Prompts are deliberately not stored, so this cannot be reconstructed retroactively. There is no analysis that recovers it; the only path is to start recording. That is the whole argument for doing this before anything else on the cost axis.

What is visible from route_decisions is suggestive but not conclusive. required_context_tokens (recorded at dispatcher.py:2450 as measured, computed on the post-pinch send_messages) distributes as:

p10 49,817   p25 66,097   p50 88,069   p75 127,517   p90 195,683   p99 279,995

against pinch.budget_tokens: 50000. The median request ships at 1.8x the budget and p90 at 3.9x. That is consistent with pinch working correctly on an untrimmable conversation, and with pinch barely firing at all. Without tokens_saved there is no way to tell which — which is the point.

---

3. The budget is denominated in the wrong units

Found while writing this, and it is the substantive bug rather than a reporting gap.

prune_context decides whether to prune from message text alone (context_prune.py:263):

orig_tokens = sum(estimate_tokens(extract_text(m)) for m in messages)
if orig_tokens <= budget_tokens:
    return messages, {"pruned": False, ...}

estimate_prompt_tokens — what actually governs routing and tracks the bill — counts messages plus tool definitions (dispatcher.py:1839), and its own docstring says why:

Tool definitions ride along in upstream_body on every call, so they count against the same context window and belong in this estimate too — omitting them undercounts every tool-carrying request, which is nearly all agent traffic.

Pinch never got that fix. So the two disagree by exactly the tool-definitions payload — and CLAUDE.md records that opencode sends ~32K prompt tokens of system prompt and tool definitions on a trivial request. 8,910 of 9,007 requests in the window carried tools.

Concretely: a conversation whose messages total 45,000 tokens sits under the 50,000 budget, so prune_context returns pruned: False and touches nothing — while the request that actually ships and bills is ~77,000 tokens. The knob labelled "trim once the conversation exceeds 50k" is comparing against a number that excludes the single largest fixed component of every agent request.

This is the same error the project has already corrected twice elsewhere (list price vs. billed cost; cheap_completion_max gating on the 7.4% axis): measure the quantity you are billed for. The dispatcher learned it and wrote it into a docstring; pinch is still on the old side of it.

---

4. The fix, in order

Instrument before changing behaviour, so the change has a baseline to be judged against. Fixing §3 first would move the numbers with nothing recorded to compare them to.

Commit 1 — make it visible (no behaviour change)

1. logs.debug → logs.info at both pinch call sites (dispatcher.py:2414, :2646). One line per request is consistent with what logging.level: info already promises ("one line per request: what it was classified as, which model won, what it cost, how long each stage took"). Emit it only when pruned is true, so the no-op case stays quiet.

2. Persist it. Add to route_decisions:

   ALTER TABLE route_decisions ADD COLUMN pinch_original_tokens INTEGER;
   ALTER TABLE route_decisions ADD COLUMN pinch_final_tokens    INTEGER;
   

   tokens_saved is their difference and pruned is original > final, so two columns carry all four stats without redundancy. Same ensure_columns / _ensure_route_decisions_table migration pattern as everything else. NULL means pinch was disabled or the request predates this.

   If the exposure-bias plan lands first, fold these into the same migration — it already adds request_id and exploration to this table.

3. Surface it in /metrics. A pinch block alongside the existing aggregates: share of requests pruned, median and total tokens_saved, and estimated dollars saved. Price the saved tokens at the same BLENDED rate routing.estimated_cost uses, not at the cached rate:

   saved_usd = saved_tokens
             * ( (1 - cache_rate) * cost_per_1m_prompt
               + cache_rate * COALESCE(cost_per_1m_prompt_cached, cost_per_1m_prompt) )
             / 1_000_000
   

   (Corrected 2026-09-01. An earlier draft said "price the delta at the cached prompt rate", which is wrong twice over: cost_per_1m_prompt_cached is already the discounted per-1M price, so multiplying by cache_rate applies the discount a second time, and it silently drops the (1 - cache_rate) fraction billed at full price. Match routing.estimated_cost — src/routing.py:363-374 — or the dashboard will report a savings figure that disagrees with the cost model the router actually ranks on. Note the COALESCE: cost_per_1m_prompt_cached can be NULL, and routing falls back to the full prompt price in that case.)

   This is the number that says whether pinch earns its place, and there is currently no way to ask for it.

Commit 2 — count what gets billed

4. Give prune_context the tool-definitions size. Add a extra_fixed_tokens: int = 0 parameter, added to orig_tokens before the budget comparison, and have dispatcher pass len(json.dumps(tools)) // CHARS_PER_TOKEN when the request carries tools.

   A parameter rather than passing tools itself, deliberately: the tool array is not trimmable — it ships verbatim on every call — so pinch has no reason to see its contents. It only needs to know how much of the budget is already spent before it starts. This keeps context_prune pure and its signature honest about what it can act on.

   Reuse dispatcher.estimate_prompt_tokens's arithmetic rather than re-deriving it, so the two cannot drift again — that drift is this bug.

5. Expect pinch to start firing much more often, and read commit 1's numbers before touching budget_tokens. Do not tune the budget in the same commit.

Then — and only then — tune

budget_tokens: 50000 was set when the budget excluded ~32k of fixed overhead. Under correct accounting it is a materially tighter setting than it was written to be. Whether to raise it, or to widen what pinch may trim, is a question for the data from commits 1-2, not a guess now. config.yaml's own note applies: "start conservative (large budget, small reduction) and watch route_decisions / pinch stats on real traffic before widening it." Commit 1 is what makes that sentence executable.

---

4b. Bundled cleanup: the test suite is 39% one test

Unrelated to pinch, folded in deliberately (requested 2026-09-01) because it is small, self-contained, and touches nothing the rest of this plan touches. Do it as its own commit so it can be reverted independently.

Measured on feat/catalog-staleness-and-ceiling-warnings, 848 tests, 38.55s total. Collection is only 1.54s, so startup is not the problem. The --durations profile is dominated by a single test:

15.08s  tests/test_eval_scoring.py::test_infinite_loop_is_bounded_not_hung
 3.40s  tests/test_tui.py::test_auto_refresh_rerenders_updated_payload
 1.38s  tests/test_admin_frontend.py::test_admin_frontend_path_does_not_depend_on_base_dir
 1.09s  tests/test_admin_health.py::test_admin_does_not_import_dispatcher
 …everything below 0.6s

4b.1 Bound the timeout the test is waiting on — free, no dependency

test_infinite_loop_is_bounded_not_hung calls score_code on while True: pass and genuinely waits out eval_proficiency.CODE_TIMEOUT_SECONDS = 15 (src/eval_proficiency.py:54, consumed at :171). It is a module-level constant, so the test can bound it. Verified live:

CODE_TIMEOUT_SECONDS = 15  ->  15.08s
CODE_TIMEOUT_SECONDS = 1   ->   1.01s, returns (0.0, 'timeout') — identical

def test_infinite_loop_is_bounded_not_hung(monkeypatch):
    monkeypatch.setattr(eval_proficiency, "CODE_TIMEOUT_SECONDS", 1)
    score, detail = score_code("def f(x):\n    while True: pass", ["f(1)==1"])
    assert (score, detail) == (0.0, "timeout")

38.5s → ~24.5s from one line. It also makes the test better: it pins the bounding mechanism rather than the specific 15-second duration, so it stays fast if the real timeout is ever tuned. Do not change CODE_TIMEOUT_SECONDS itself — 15s is the right production value for a model's code; only the test needs it short.

While in the file, check whether test_auto_refresh_rerenders_updated_payload (3.40s) is waiting on a real Textual timer that a monkeypatched interval would also collapse. Fix it only if it is the same shape; do not restructure the TUI tests to chase it.

4b.2 Then parallelize — pytest-xdist, -n auto

nproc is 20 and pytest-xdist is not installed. Tests look independent (temp-file SQLite, no shared server fixture), so -n auto should distribute cleanly. Estimated floor after 4b.1 lands: ~5-8s, bounded by the slowest remaining test.

Order matters. With the 15s test still in place, xdist cannot beat 15s on any number of cores — a suite is bounded below by its slowest single test. Land 4b.1 first, measure, then add xdist.

Add to requirements.txt pinned, matching the file's existing convention. Note that file's standing warning — dependencies are pinned deliberately because a service that restarts on boot should not change its dependency tree underneath itself. pytest-xdist is dev-only and never imported by the dispatcher, so it does not reach the service, but it is still an addition and belongs in its own commit with that reasoning recorded.

If parallel runs turn out to be flaky, suspect shared state before suspecting xdist — a test writing to a fixed path (router.db in the repo root) rather than a tmp path would fail only under concurrency. Fix the test; do not fall back to serial.

4b.3 Reframe src/gate_step2.py — DEFERRED, wrong branch

Deferred 2026-09-01. src/gate_step2.py does not exist on main or on the pinch branch — it was created by feat/proficiency-exposure-bias-and-exploration, which is still unmerged. Implementing this here would mean porting recompute_category and the outcome schema across, dragging the whole exposure-bias surface into a cleanup task. Do it on that branch, or as a follow-up once it merges. The analysis below stands; only the location is wrong.

Added 2026-09-01, after the exposure-bias work landed and its backlog was spent.

gate_step2.py was written as a one-shot pre-step-3 gate: it asserts that stored proficiency.blended_score still equals a benchmark-only blend() on the same components, proving the empirical-Bayes code was inert before any outcome data was folded in. That gate has served its purpose. The backlog has since been applied — 886 of 982 succeeded and 199 of 226 failed client outcomes are now applied_at, and 33 proficiency rows carry 1,059 outcome samples — so stored scores now legitimately read outcome_blended / outcome_prior while a benchmark-only recompute reads self_eval.

Run today it prints FAIL: stored blended_score does not equal recomputed blend(); regression? and reports 108 mismatches. All of them are correct. Leaving a checked-in script that loudly cries regression when the system is healthy is a trap for whoever runs it next — including a future agent, which will try to "fix" it.

Two acceptable resolutions; prefer the second:

1. Delete it. Its job is done and git history preserves it.
2. Reframe it as an idempotence check, which stays useful forever: run recompute_category over a COPY of the live DB and assert the stored (source, blended_score) snapshot is byte-identical afterwards. That pins the property the single-writer invariant actually depends on — recomputing changes nothing when inputs have not changed — and it is true both before and after a backlog spend. Keep the DB-copy discipline (VACUUM INTO / cp, never the live file) and the triage output, which are the good parts.

Whichever is chosen, remove the "step-2" framing from the name and docstring so it no longer implies a one-time migration gate.

---

5. File-by-file

Commit 1

• src/dispatcher.py — logs.debug → logs.info at both call sites, gated on pinch_stats["pruned"]; add the two columns to ensure_route_decisions and _ensure_route_decisions_table; write them in persist_route_decision (both the chat path and the passthrough path, so a pinned-model request still records what pinch did).
• config/schema.sql — the two columns in the route_decisions DDL.
• src/metrics.py — the pinch block in the returned dict.
• admin/frontend/index.html and src/tui_model.py — surface the block. Follow the existing "Local compute" card as the pattern; it solves the same problem (a cost the operator otherwise cannot see).

Commit 2

• src/context_prune.py — extra_fixed_tokens parameter on prune_context, added to orig_tokens before the budget check. Docstring: say that the caller owns fixed, untrimmable overhead and why pinch is not given the tool array.
• src/dispatcher.py — pass it at both call sites.

Commit 3 — bundled test-speed cleanup (§4b), independent of the above

• tests/test_eval_scoring.py — monkeypatch CODE_TIMEOUT_SECONDS in test_infinite_loop_is_bounded_not_hung. Own commit. Measure before/after.
• requirements.txt — add pytest-xdist pinned. Separate commit from the above, with the dev-only-never-imported-by-the-service reasoning in the message.

Tests

• tests/test_context_prune.py — a conversation under budget on messages alone but over once extra_fixed_tokens is supplied now prunes (this is the §3 bug, pinned); extra_fixed_tokens=0 reproduces current behaviour byte-for-byte; the parameter never makes the tool array itself trimmable.
• tests/test_route_decisions.py — the two columns are written when pinch prunes and left NULL when it is disabled.
• tests/test_metrics.py — the pinch block, including the zero-traffic case.
• The existing rule that the write path stores no conversation text still holds: these are two integers.

---

6. Summary

Why	92.6% of estimated cost is prompt tokens; pinch is the only lever on it.
Problem A	Its stats are computed and thrown away — logs.debug under level: info, nothing in /metrics or route_decisions. Prompts aren't stored, so this cannot be reconstructed later.
Problem B	Its budget is compared against message text only, while ~32k of tool definitions ship on 8,910 of 9,007 requests and count against both the window and the bill.
Fix	Commit 1: promote the log, persist two integers, surface a /metrics block. Commit 2: give prune_context the fixed overhead it is currently blind to.
Then	Re-tune budget_tokens from data, not from a guess. Not in either commit.
Bundled (§4b)	Unrelated test-speed cleanup: one monkeypatch takes the suite 38.5s → ~24.5s, then pytest-xdist -n auto on 20 cores targets ~5-8s. Separate commits; revertable independently.