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`):

```python
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`:
   ```sql
   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
```

```python
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. |