# 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. |