autoresearch: refresh the playbook and idea backlog

3 files changed, 55 insertions, 12 deletions

diff --git a/.auto/ideas.md b/.auto/ideas.md
index 8d049e3..f802898 100644
--- a/.auto/ideas.md
+++ b/.auto/ideas.md
@@ -30,3 +30,16 @@
   scenario's setup in experiment #6, but the app behaviour is still ambiguous).
   A fix would be to enter graph mode immediately with a loading state when a
   sticky navigation starts.
+
+## Verification patterns that worked (reuse them)
+
+- **Differential against a git ref.** `.auto/diff_spans.py` loads the *current*
+  and a *past* `server/patch_server.py`, execs the same slice of each `BODY`,
+  and compares outputs over every disassembly line of a real binary. Catch:
+  `BODY` is a normal triple-quoted string, so you must import the module and
+  read `mod.BODY` — slicing the file text tests an undecoded program.
+- **Differential inside one process** (`/tmp/fceq.py`, `/tmp/hleq.py`,
+  `/tmp/searcheq.py`): build the input twice, run old and new, compare the
+  structures. Cheap, and it catches "faster because it does less".
+- The bench's `NOTES` counters (`search_hits`, `graph_blocks`, `decomp_ok`,
+  `render_cells`, `nav_rows`) are the standing guard against that.
diff --git a/.auto/log.jsonl b/.auto/log.jsonl
index 9168c26..3058a9b 100644
--- a/.auto/log.jsonl
+++ b/.auto/log.jsonl
@@ -12,3 +12,4 @@
 {"type":"config","name":"ida-tui performance (v2 bench: graph opens are now measured cold)","metricName":"total_ms","metricUnit":"ms","bestDirection":"lower"}
 {"run":11,"commit":"26fa14c","metric":27912.9,"metrics":{"lg_boot_ms":742.8,"lg_decomp_ms":2595.7,"lg_graph_ms":9561.4,"lg_hex_ms":554.4,"lg_index_ms":77.6,"lg_listing_cold_ms":548.6,"lg_listing_warm_ms":405.5,"lg_nav_ms":6552.9,"lg_palette_ms":4.9,"lg_render_ms":216.1,"lg_search_ms":2218,"pure_graph_ms":507.6,"sm_boot_ms":535.6,"sm_decomp_ms":620.2,"sm_graph_ms":962,"sm_hex_ms":587.4,"sm_index_ms":0,"sm_listing_cold_ms":261.8,"sm_listing_warm_ms":261.7,"sm_nav_ms":368.8,"sm_palette_ms":0.3,"sm_render_ms":252.4,"sm_search_ms":77.1,"fails":0},"status":"keep","description":"RE-BASELINE on a corrected benchmark. phase_graph was measuring a cache hit: the fixture picker called Program.flowchart (which caches per function), so the timed Space press only did a dict lookup. Fixtures now use the raw flowchart tool and the graph cache is cleared before the phase. Cold graph opens cost lg_graph 9561ms — 34% of the total, previously invisible.","timestamp":1786062344258,"segment":1,"confidence":null,"asi":{"hypothesis":"the graph phase looked suspiciously cheap; check whether it was measuring real work","bench_flaw_found":"run_target picked its 12 fixture functions by calling app.program.flowchart(f.addr) to count blocks. Program.flowchart caches per (function, name generation) AND fetches every listing row in the function's extent, so the fixture loop paid the whole cost and phase_graph then timed a cache hit. Fixed: fixtures use client.call('flowchart') directly, and phase_graph clears program._flowcharts first.","carried_forward_from_v1":"experiments 1-10 took total_ms from 46572 to 19006 (-59%) on the old bench; that history is in the archived log and summarised in .auto/prompt.md","bug_this_exposed":"Program.flowchart does rows = _heads_between(min(block.start), max(block.end)) -- the CONVEX HULL of the blocks. IDA function chunks put tail blocks hundreds of KB from the entry, so a 1384-byte function (jobs_builtin) fetches 128000 listing rows and takes 2961ms to graph. Measured on bash: 4 of the 12 fixtures have spans of 280KB-680KB and cost 258-2961ms each; the other 8 have span == size and cost 7-32ms. Then b.rows = [h for h in rows if ...] is O(blocks x rows) on top -- 541ms for the set.","fix_planned":"fetch the MERGED BLOCK INTERVALS instead of the hull (adjacent blocks coalesce, so a normal function is still one call), and assign rows to blocks by bisect instead of a full scan per block","next_action_hint":"apply that fix; it should take lg_graph from 9561 to well under 1000"}}
 {"run":12,"commit":"870f89e","metric":19062.1,"metrics":{"lg_boot_ms":751.3,"lg_decomp_ms":2605.7,"lg_graph_ms":1022,"lg_hex_ms":554.5,"lg_index_ms":103.9,"lg_listing_cold_ms":545,"lg_listing_warm_ms":405.6,"lg_nav_ms":6636.8,"lg_palette_ms":4.7,"lg_render_ms":212.2,"lg_search_ms":2269,"pure_graph_ms":239.9,"sm_boot_ms":538.5,"sm_decomp_ms":688.4,"sm_graph_ms":712.7,"sm_hex_ms":557.5,"sm_index_ms":0,"sm_listing_cold_ms":259.9,"sm_listing_warm_ms":260.2,"sm_nav_ms":363.8,"sm_palette_ms":0.3,"sm_render_ms":252.7,"sm_search_ms":77.5,"fails":0},"status":"keep","description":"Fetch a graph's listing rows from the blocks' MERGED EXTENTS, not their convex hull, and assign them per block by bisect. IDA puts a function's cold/tail chunks far from its entry, so the hull of a 1.4KB function could be 680KB wide: it fetched 128k rows, took 3s, and still came back EMPTY for the far blocks because the pager's 64-page bound ran out first. lg_graph 9561 -> 1022.","timestamp":1786062629380,"segment":1,"confidence":null,"asi":{"hypothesis":"Program.flowchart fetches the convex hull of the basic blocks, which is enormous for a function with IDA chunks","gains":"total 27913 -> 19062 (-31.7%); lg_graph 9561 -> 1022 (-89%); sm_graph 962 -> 713","correctness_is_BETTER_not_equal":"differential over the 80 largest functions of bash: 1201 blocks differ, and EVERY one of them is a block the old code returned ZERO rows for. _heads_between is bounded to 64 pages x 2000 heads = 128k, and a 680KB hull exhausted that before reaching the tail chunk -- so far blocks drew as empty boxes. No block lost a row. targets/echo: 0 differences at all (no chunked functions).","scale":"80 bash functions: hull 44.4s / 1,864,814 rows fetched -> intervals 1.4s / 77,221 rows. 24x less data, 31x faster.","design":"blocks are sorted and merged with a 256-byte tolerance so alignment padding does not split an interval; an ordinary contiguous function is still exactly ONE heads call, as before. Row->block assignment is now bisect on the address list instead of a full scan per block (541ms -> ~0 for the 12-function set).","verify_script":"/tmp/fceq.py (kept the pattern in .auto/ideas.md): rebuild the blocks twice, fetch both ways, compare per-block row lists","next_action_hint":"lg_nav 6637 is now 35% of the total and sits at the per-row floor (~16.5us worker + ~7us client). decomp lg+sm 3294 is next: 1370ms of Hex-Rays, 240ms of pygments highlight_c, ~600ms of Textual loading-cover churn. Also unmeasured by the bench: domain.decomp_map costs 280ms per function on the split-view path."}}
+{"run":13,"commit":"60f0d70","metric":18856.8,"metrics":{"lg_boot_ms":689.7,"lg_decomp_ms":2484.2,"lg_graph_ms":1120,"lg_hex_ms":700.1,"lg_index_ms":96.5,"lg_listing_cold_ms":425.6,"lg_listing_warm_ms":511.5,"lg_nav_ms":6590.7,"lg_palette_ms":4.8,"lg_render_ms":215.1,"lg_search_ms":2195.5,"pure_graph_ms":238.1,"sm_boot_ms":431.5,"sm_decomp_ms":667.2,"sm_graph_ms":686.9,"sm_hex_ms":569.8,"sm_index_ms":0,"sm_listing_cold_ms":258.1,"sm_listing_warm_ms":283.2,"sm_nav_ms":365.2,"sm_palette_ms":0.3,"sm_render_ms":243.7,"sm_search_ms":79,"fails":0},"status":"keep","description":"Two independent constants: memoise the pygments token -> Rich style lookup (a decompilation uses ~18 distinct token types but each token walked up to nine 'token in ttype' hierarchy checks), and hold the worker-connect poll at 5ms for the first 5s instead of backing off geometrically from the first probe.","timestamp":1786062907221,"segment":1,"confidence":44.11154408183163,"asi":{"hypothesis":"boot time is a polling artefact, and highlighting is a style-lookup problem not a lexing problem","boot_smoking_gun":"WorkerClient.connect() returned in 351ms for BOTH targets/echo (47KB) and targets/bash (1.2MB) -- an identical number for very different work is a polling artefact, not a cost. The geometric backoff (5ms x1.6, capped at 200ms) has reached 134ms by the time a seeded database is ready at ~250ms. Holding 5ms for 5s first: echo 351 -> 260ms. bash is genuinely ~350ms so it did not move.","highlight_split":"on a 40KB body: lexer 52.2ms, _style_for 19.4ms, rest ~10ms of 82ms total. Memoised _style_for is 1.2ms (18 distinct token types in the whole corpus). highlight_c 84.2 -> 62.0ms.","equivalence":"/tmp/hleq.py compares old vs new highlight_c segment-for-segment over 5 bodies x 4 slices including an empty string and hex-rays-shaped pseudocode: 0 mismatches","gains":"total 19062 -> 18857 (-1.1%); sm_boot 539 -> 432 (-20%); lg_boot 751 -> 690","rejected_this_round":"a per-page identity memo for the spans->tuple conversion in Head.from_raw. The worker's line cache does share span objects across rows, but the repeats are spread over the whole segment, not within a 500-row page, so a page-scoped memo never hits: _build_page 4.52 -> 4.68 us/row. A model-scoped memo is UNSAFE because id() is reused once the page's row dicts are collected.","next_action_hint":"lg_nav 6591 (35%) is at the per-row floor. Left: pygments lexing itself (52ms per 40KB), the ~600ms of Textual loading-cover churn across 12 F5s, and lg_search 2196 (two unnarrowed passes over 224k rows at ~2.6us each)."}}
diff --git a/.auto/prompt.md b/.auto/prompt.md
index a2ced97..73d9692 100644
--- a/.auto/prompt.md
+++ b/.auto/prompt.md
@@ -23,6 +23,8 @@ length-prefixed pickle). Three layers, kept separate:
 ## Metrics
 
 - **Primary**: `total_ms` (ms, lower is better) — the sum of every phase median.
+  Re-baselined once (experiment v2 #1) when `phase_graph` was found to be timing
+  a cache hit; the v1 history below is still the record of what was learned.
 - **Secondary** (all in ms, per target: `sm_` = echo, `lg_` = bash):
   - `nav_ms` — jump to a function's entry in the listing, cold. **The single
     biggest term today** (`lg_nav_ms` ≈ 28 s of a 46 s total, and
@@ -105,32 +107,55 @@ expected payoff:
 
 ## What's Been Tried
 
-Baseline: `total_ms` ≈ 46 600. `lg_nav_ms` ≈ 29 000 (62% of it), of which a
-single cold jump to a high address was ≈ 28 200.
+v1 bench baseline `total_ms` ≈ 46 600 → 18 900 after thirteen experiments
+(−59% on v1, then a re-baseline at 27 913 and −32% on v2).
 
-**Wins**
+**Wins, biggest first**
 
-1. *(#3, −42%)* **ida-pro-mcp installs a `sys.setprofile` hook around every tool
-   call.** Its deadline mechanism profiles every python call/return so a
+1. *(v1 #3, −42%)* **ida-pro-mcp installs a `sys.setprofile` hook around every
+   tool call.** Its deadline mechanism profiles every python call/return so a
    pure-python tool body can be interrupted — a 3.3× tax on a backend whose
    tools are call-heavy (`heads`: 92 → 28 µs/row without it). `worker.py` now
    sets `IDA_MCP_TOOL_TIMEOUT_SEC=0` and arms the deadline itself with one
    polling watchdog thread + `ida_kernwin.set_cancelled()` — the half that
    actually frees the IDA main thread.
-2. *(#4, −3%)* **`_idatui_spans` via one capturing `re.split`**, and whitespace
-   collapsed with `" ".join(txt.split())` rather than `re.sub`. 13.2 → 11.1
-   µs/line.
-3. *(#6)* **`lru_cache` on the per-line render** (`_idatui_line_parts`) plus
-   building `Head`s with their opcode bytes already attached.
+2. *(v2 #2, −32%)* **`Program.flowchart` fetched the convex hull of the basic
+   blocks.** IDA function chunks live far from the entry, so a 1.4 KB function
+   could span 680 KB: 128 000 rows fetched, 3 s to draw, and the far blocks
+   came back *empty* because the pager's 64-page bound ran out first. Now it
+   fetches the merged block intervals and assigns rows by bisect.
+3. *(v1 #6)* **`lru_cache` on the per-line render** (`_idatui_line_parts`):
+   196 k listing lines of bash are only 53 k distinct, 26.7 → 16.5 µs/row.
+4. *(v1 #7, −9%)* **Incremental search narrows instead of rescanning** — typing
+   a character can only remove lines.
+5. *(v1 #9/#10/#13)* Constants: `bytes.hex(" ")` for the opcode column (12×),
+   `bisect` imported at module scope, the deferred `refresh(layout=True)` only
+   when a scroll actually clamped, a memoised pygments token→style lookup, and
+   a worker-connect poll that doesn't back off before the worker can be ready.
 
 **Dead ends / things not to re-try**
 
 - `re.finditer` per tag in the span walker is *slower* than a plain character
   loop (14.4 vs 13.2 µs/line): Match objects cost more than the ~54 trivial
-  iterations they replace.
+  iterations they replace. One capturing `re.split` is what wins (10.2).
 - `ListingModel.PAGE` (500 / 1000 / 2000) makes no measurable difference —
   the cost is per row, not per round trip. Don't tune it.
-- `re.sub` for the whitespace collapse costs ~1 µs per call at ~6.5 calls/line.
+- Changing the `heads` wire shape (int `ea`, tuples instead of dicts) buys at
+  most 0.3 µs/row. Measured; not worth a breaking change.
+- A page-scoped identity memo for the spans→tuple conversion never hits: the
+  repeats are spread across the segment, not within a 500-row page. A
+  model-scoped one is unsafe (`id()` is reused once the page dicts die).
+- Growing the line cache past 16 384 does nothing for a *cold* sweep (16.5
+  µs/row at both 16 k and 64 k); it only helps a second sweep (10.6 vs 16.4).
+
+**Where the time is now (18 857 ms)**
+
+`lg_nav` 6 591 (35%) · decomp lg+sm 3 151 · `lg_search` 2 196 · graph lg+sm
+1 807 · listing 1 478 · hex 1 270 · boot 1 121 · render 459 · pure_graph 238.
+
+`lg_nav` is a linear walk of the segment at its floor: ~16.5 µs/row in the
+worker (of which `generate_disasm_line` is 5.9 µs and IDA's) plus ~7 µs/row on
+the client. The only lever left there is *not walking* — see `.auto/ideas.md`.
 
 **Measurement traps**
 
@@ -140,3 +165,7 @@ single cold jump to a high address was ≈ 28 200.
 - Anything that walks the listing twice in one process is measuring a warm
   `_idatui_line_parts` cache the second time. Run cold cases first, or in
   separate processes.
+- Anything that goes through `Program.flowchart`, `Program.decompile` or
+  `Program.functions` twice is measuring a cache. Clear it or use the raw tool.
+- **The worker is a single serial process.** Work "moved to the background"
+  does not overlap with anything; only doing less work helps.