diff options
| -rw-r--r-- | .auto/ideas.md | 16 | ||||
| -rw-r--r-- | .auto/log.jsonl | 1 | ||||
| -rw-r--r-- | .auto/prompt.md | 60 |
3 files changed, 63 insertions, 14 deletions
diff --git a/.auto/ideas.md b/.auto/ideas.md index 3a18b33..a2d9b4f 100644 --- a/.auto/ideas.md +++ b/.auto/ideas.md @@ -52,3 +52,19 @@ - The bench's `NOTES` counters (`search_hits`, `graph_blocks`, `decomp_ok`, `render_cells`, `nav_rows`, `listing_cells`) are the standing guard against "faster because it did less". + +## Added late in the session + +- **Refresh only the rows a rename actually changed.** `bump_names` currently + stales every row's text; a wholesale re-read then costs about what a rebuild + costs (~10% more, measured). Only rows that *mention* the symbol change, and + `xrefs_to(renamed_ea)` plus the function's own extent would name most of them. + The catch: `bump_names()` is called from half a dozen places that don't have + an address (comment, retype, literal reformat), and a name can reach a row + through more than a direct xref. Would make a rename free everywhere. +- **Features the bench still doesn't drive end to end**, in the order they seem + worth probing: xrefs (`x`), the strings browser (`"`), literal formats (`o`), + make-code/data/function edits, history (`back`), execution traces, the RPC + layer. Use the `/tmp/featprobe.py` shape: call the domain API for each and look + for a number that is absurd for the work done. That is how the flowchart hull, + `decomp_map` and the rename walk were all found. diff --git a/.auto/log.jsonl b/.auto/log.jsonl index 5feb84e..fcebe68 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -38,3 +38,4 @@ {"run":31,"commit":"7b8c37a","metric":33242.6,"metrics":{"lg_boot_ms":710.8,"lg_decomp_ms":2401.2,"lg_graph_ms":898.1,"lg_hex_ms":448.7,"lg_index_ms":72.1,"lg_listing_cold_ms":439.3,"lg_listing_warm_ms":426.8,"lg_nav_ms":7060.2,"lg_palette_ms":4.8,"lg_rename_ms":10055,"lg_render_ms":220.2,"lg_search_ms":774.6,"lg_split_ms":3539.8,"pure_graph_ms":215.1,"sm_boot_ms":429.1,"sm_decomp_ms":1244.1,"sm_graph_ms":744.3,"sm_hex_ms":444.2,"sm_index_ms":2.5,"sm_listing_cold_ms":269.8,"sm_listing_warm_ms":263.3,"sm_nav_ms":282.9,"sm_palette_ms":0.3,"sm_rename_ms":638.3,"sm_render_ms":255.6,"sm_search_ms":44.2,"sm_split_ms":1357.4,"fails":0},"status":"keep","description":"RE-BASELINE (v7 bench). Rename — the commonest operation in reverse engineering — was not covered, and it costs 10.1s for SIX renames on bash (1.7s each) because bump_names discards the segment's ListingModel and the reload re-walks it from the start. lg_split also rose to 3540ms: the split phase now runs after renames have thrown the listing away.","timestamp":1786073435987,"segment":6,"confidence":null,"asi":{"hypothesis":"keep probing unbenched features -- the last two probes each found a 10x","finding":"rename costs 1.7s per rename on bash (10.1s for six) and 106ms on echo. Program.bump_names() clears _listings, so the reload builds an empty ListingModel and ensure_ea walks the segment from its start to find the row the cursor was already on.","the_irony":"idatui/edit_ctl.py already documents that a rename cannot move a row: 'a rename or comment doesn't change how many rows anything takes' -- it restores the cursor by INDEX afterwards. It just throws away the walk that gives the index meaning.","fix_ready_and_verified":".auto/wip-renamekeep.patch. ListingModel.invalidate_text() keeps the walk and marks the rendered text stale; _ensure_text re-renders a 500-head block at a time, snapped out to whole ADDRESS groups (a function start emits three banner rows at the same ea, so an unsnapped block boundary refetches the group and never lines up). If a refetch does come back with a different head sequence it sets stale_structure and Program.listing() rebuilds, so a mis-routed structural edit degrades to today's behaviour instead of showing stale names.","measured":"bash, cursor at row 220036 of 228659: viewport back in 10.3ms instead of 6320ms (593x). A FULL re-read of every row is break-even with a rebuild (6.8s vs 6.9s), which is the right shape -- refreshing N heads costs what loading N heads costs.","equivalence":"/tmp/renameeq.py renames a function, snapshots every row (ea, kind, text, name) from the kept model, then rebuilds from scratch and compares: 0 mismatches over 5952 rows (echo), 28807 (ls_ttl) and 228659 (bash), three renames each.","one_open_question":"one full-suite run showed a follow_xrefs failure with the patch in; it passed 10/10 in isolation afterwards and 6/7 full runs green vs 6/6 without. Watch it.","next_action_hint":"apply the patch"}} {"run":32,"commit":"44c311a","metric":25563.7,"metrics":{"lg_boot_ms":732.6,"lg_decomp_ms":2714,"lg_graph_ms":919.3,"lg_hex_ms":566.8,"lg_index_ms":71.4,"lg_listing_cold_ms":441.4,"lg_listing_warm_ms":411.7,"lg_nav_ms":6708,"lg_palette_ms":4.8,"lg_rename_ms":741.5,"lg_render_ms":227.7,"lg_search_ms":3314.1,"lg_split_ms":2596.9,"pure_graph_ms":213.6,"sm_boot_ms":422.9,"sm_decomp_ms":1284,"sm_graph_ms":789.5,"sm_hex_ms":468.1,"sm_index_ms":2.6,"sm_listing_cold_ms":258.7,"sm_listing_warm_ms":257.3,"sm_nav_ms":306.5,"sm_palette_ms":0.3,"sm_rename_ms":388.2,"sm_render_ms":256,"sm_search_ms":105.1,"sm_split_ms":1360.5,"fails":0},"status":"keep","description":"A rename keeps the listing's walk instead of throwing it away. bump_names now marks the rendered text stale (invalidate_text) and ListingModel re-renders a 500-head block at a time on demand, snapped out to whole address groups; a refetch that comes back with a different head sequence sets stale_structure so Program.listing() rebuilds. lg_rename 10055 -> 742.","timestamp":1786073731826,"segment":6,"confidence":null,"asi":{"gains":"total 33243 -> 25564 (-23.1%); lg_rename 10055 -> 742 (-93%); sm_rename 638 -> 388; lg_split 3540 -> 2597 (the split phase runs after the renames and no longer inherits a discarded listing)","honest_tradeoff":"lg_search 775 -> 3314. The cost did not vanish, it moved: the six renames used to pay for a full rebuild each (10s), and search then found a warm model. Now renames are ~120ms and the first WHOLE-SEGMENT search afterwards pays to re-render the blocks it reads. Net -7.7s, and the cost only lands if you search the entire segment right after renaming. A full re-read is break-even with a rebuild by design -- re-rendering N heads costs what loading N heads costs.","work_unchanged":"rename_ok 6/6 both targets, search_hits 91783, split_mapped_lines 2070, graph_blocks 1000, decomp_ok 12 -- all identical to the baseline","design_notes":["blocks are snapped out to whole ADDRESS groups: a function start emits three banner rows at the same ea, so an unsnapped boundary refetches the group, never lines up, and would leave stale names forever","on a sequence mismatch the model sets stale_structure and Program.listing() rebuilds -- degrading to the old behaviour rather than showing an old name","_renamed is a boolean gate so that before the first rename every read takes exactly the path it always did, with no extra lock round trips"],"equivalence":"/tmp/renameeq.py: rename, snapshot every row (ea, kind, text, name) from the kept model, rebuild from scratch, compare. 0 mismatches over 5952 rows (echo), 28807 (ls_ttl), 228659 (bash), three renames each. Full 830-check gate green.","viewport_case":"bash with the cursor at row 220036: the listing is back in 10.3ms instead of 6320ms","next_action_hint":"lg_nav 6708 and lg_search 3314 are the top two. Search after a rename could refresh in PAGE-sized chunks driven from load_all rather than block-by-block from window()."}} {"run":33,"commit":"44c311a","metric":27571.1,"metrics":{"lg_boot_ms":714.2,"lg_decomp_ms":2426.5,"lg_graph_ms":914.1,"lg_hex_ms":436.7,"lg_index_ms":109.8,"lg_listing_cold_ms":772.1,"lg_listing_warm_ms":437.2,"lg_nav_ms":6876.9,"lg_palette_ms":4.7,"lg_rename_ms":732.9,"lg_render_ms":224.7,"lg_search_ms":1209,"lg_split_ms":6623.7,"pure_graph_ms":214.1,"sm_boot_ms":463.8,"sm_decomp_ms":1282.5,"sm_graph_ms":755,"sm_hex_ms":444.3,"sm_index_ms":2.3,"sm_listing_cold_ms":268.7,"sm_listing_warm_ms":269.4,"sm_nav_ms":307.9,"sm_palette_ms":0.3,"sm_rename_ms":384.3,"sm_render_ms":260.2,"sm_search_ms":67.7,"sm_split_ms":1368.2,"fails":0},"status":"discard","description":"Chunk the post-rename text refresh into TEXT_BLOCK pieces instead of one call for the whole requested range (a search window asks for thousands of rows and the heads tool caps a response at 2000, so the oversized call came back short, failed the sequence check and condemned the model to a rebuild). Fixes lg_search 3314 -> 1209, but lg_split 2597 -> 6624 and total 25564 -> 27571: doing it properly is SLOWER here than the accidental rebuild was.","timestamp":1786074100440,"segment":6,"confidence":3.8252964033077643,"asi":{"hypothesis":"one heads call for a whole search-sized window overflows the tool's 2000-row cap, so the refresh always failed its sequence check and forced a rebuild","hypothesis_confirmed":"yes -- chunking removed the spurious rebuild and lg_search fell 3314 -> 1209","but":"lg_split rose 2597 -> 6624. The accidental rebuild was CHEAPER overall than refreshing block by block, because this bench reads most of the segment after renaming and 450 block calls cost more than one linear rebuild.","UNEXPLAINED_AND_MUST_BE_RESOLVED":"work counters moved between the two runs: lg_decomp_lines 3436 -> 3233, lg_split_mapped_lines 2070 -> 1990, lg_search_hits 91783 -> 92733. Same database (targets/bash.i64 mtime unchanged, staged fresh per run), same fixed function set. Something about which path runs is changing what the app SEES. That has to be understood before any version of this is kept -- a perf change must not alter observable work.","leads":["phase_rename renames six functions and undoes them; a function whose original name was auto-generated (sub_X) comes back as a USER name sub_X. Check whether that changes the listing (a label row, or is_auto_name affecting annotate).","the search terms are 'mov' and 'call'; the temporary name _bench_<pid>_<k> contains a 'c', so leftover names would inflate a 'c'-prefixed search -- but the terms are full words, so check for residue directly.","lg_listing_rows is a streamed-progress reading, not a work counter -- ignore that one."],"work_preserved":".auto/wip-chunk.patch","next_action_hint":"resolve the counter drift first. Then, if the chunking is kept, try TEXT_BLOCK = 2000 (the tool's cap) so a wholesale refresh costs about what a rebuild costs while a viewport still needs one call."}} +{"run":34,"commit":"3ca9e1e","metric":28651.3,"metrics":{"lg_boot_ms":720.6,"lg_decomp_ms":2427.4,"lg_graph_ms":1222.4,"lg_hex_ms":440.9,"lg_index_ms":72.6,"lg_listing_cold_ms":433.6,"lg_listing_warm_ms":465.9,"lg_nav_ms":6809.7,"lg_palette_ms":4.7,"lg_rename_ms":710.1,"lg_render_ms":228.7,"lg_search_ms":6891.2,"lg_split_ms":2259.2,"pure_graph_ms":214.5,"sm_boot_ms":457.7,"sm_decomp_ms":1303.6,"sm_graph_ms":700.2,"sm_hex_ms":445.4,"sm_index_ms":2.4,"sm_listing_cold_ms":271.4,"sm_listing_warm_ms":270.9,"sm_nav_ms":309.2,"sm_palette_ms":0.3,"sm_rename_ms":386.6,"sm_render_ms":265.8,"sm_search_ms":70.1,"sm_split_ms":1266.2,"fails":0},"status":"keep","description":"CORRECTNESS FIX, kept despite a worse metric. The un-chunked refresh was showing STALE NAMES on any wide read: one heads call for a search-sized window overflows the tool's 2000-row cap, the short response fails the sequence check, and the block is left with its old text. Refresh is now done a block at a time. Adds .auto/check_rename.py to the gate, which fails hard on the previous code and passes on this one.","timestamp":1786074769473,"segment":6,"confidence":4.974025132789222,"asi":{"the_bug_the_metric_was_rewarding":"/tmp/stalewindow.py renames a function, then reads the segment through window() the way the search body does. On the previous commit: 0 rows show the new name, the old one is still there, stale_structure=True. The 25564ms reading was FASTER because it was skipping the refresh -- the bench only failed to notice because phase_rename undoes its renames, so the stale text happened to be right again by the time anything compared it.","why_it_happened":"_ensure_text issued ONE heads call for the whole requested range. The tool caps a response at 2000 rows; a 4096-row search window came back short, page[:len(want)] != want, and the code took its 'the walk moved' branch -- marking the block fresh and leaving the old text.","fix":"refresh a TEXT_BLOCK (500 heads) at a time, looping. The sequence check then only ever fires for a real structural change.","cost":"total 25564 -> 28651. A wholesale re-read after a rename is ~10% dearer than a rebuild would be (6.6s vs 6.0s measured directly), and this bench does exactly that -- six renames then a split-view pass and a whole-segment search. The user-facing trade is: a rename is 566x faster (10.3ms vs 5660ms to get the listing back on bash), and a full-segment search immediately after one is ~10% slower.","counter_drift_resolved":"the 3233/1990/92733 counters in experiment #33 were NOT caused by the change -- both configurations reproduce 3436/2070/91783 twice each. That run was CPU-starved (the box is at load 1.6 and the 60s tool deadline can truncate a big decompile). Watch decomp_lines as a starvation signal.","gate_extended":".auto/check_rename.py: narrow read (painting), wide read (search body), and the whole model against a rebuild. Verified it FAILS on the previous commit with 4 problems and passes on this one.","principle":"the second time this session that the honest number is worse than the dishonest one. A benchmark rewards whatever it can see; the guard has to be a check that fails, not a number that improves."}} diff --git a/.auto/prompt.md b/.auto/prompt.md index e41e95d..a430bda 100644 --- a/.auto/prompt.md +++ b/.auto/prompt.md @@ -42,12 +42,22 @@ length-prefixed pickle). Three layers, kept separate: ## How to Run -`./.auto/measure.sh` (~95 s). Prints `METRIC name=value` lines. +`./.auto/measure.sh` (~45 s). Prints `METRIC name=value` lines. `./.auto/measure.sh --only sm` benches just the small target while iterating. -`./.auto/checks.sh` runs automatically after every passing benchmark: the pure -suites (344 checks) plus the pilot scenario suite (301 checks against a real -worker, ~80 s). Both must pass. +`./.auto/checks.sh` runs automatically after every passing benchmark (~160 s): + +1. `.auto/check_search.py` — the search fast paths against the plain per-line + loop, for every typed prefix. +2. `.auto/check_rename.py` — the listing after a rename, read narrow (painting) + and wide (search body), and the whole model against a rebuild. +3. `tests/run.py` — every suite, 830 checks. + +**The two `.auto/check_*.py` scripts exist because the things they guard fail +silently.** A stale cache still returns *an* answer, and the benchmark rewards +it for being fast. Twice this session the honest change measured worse than the +broken one. If you optimise a cache, write the check that fails on the old code +first. ## Files in Scope @@ -76,7 +86,11 @@ expected payoff: - `tests/**` — the correctness gate. Do not weaken, skip, shorten or "fix" a test to make a change pass. If a test fails, **assume the change is wrong**. - One narrow exception, and it costs you a proof: a scenario whose *setup* is + Two narrow exceptions have been used, each with proof recorded in the log: + the racy-setup one below, and adding `.auto/check_*.py` gates (which only ever + *add* coverage). + + The racy-setup exception, and what it costs you: a scenario whose *setup* is racy, where the speedup merely decides which of two async loads lands first. Before touching it you must (a) bisect to show which change flips it, (b) reproduce the race outside the suite, showing the app reaching two different @@ -119,19 +133,28 @@ v1 bench baseline `total_ms` ≈ 46 600 → 18 900 after thirteen experiments 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. *(v2 #2, −32%)* **`Program.flowchart` fetched the convex hull of the basic +2. *(v6 #2, −41%)* **`decomp_map` swept every column three times over.** Three + SWIG allocations per column, the TAGGED line length as the bound (124 columns + for a 23-column line), and a `dstr()` format per column when consecutive + columns are the same ctree item. bash's 25 largest: 67.4 s → 6.8 s. This is + the split view's whole cost. +3. *(v7 #2, −23%)* **A rename kept the listing's walk.** `bump_names` discarded + the segment model, so the reload re-walked it to find a row the cursor was + already on — 1.7 s per rename on bash. Now the walk stays and the text is + re-rendered a block at a time: 10.3 ms. +4. *(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`): +5. *(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 +6. *(v1 #7, −9%)* **Incremental search narrows instead of rescanning** — typing a character can only remove lines. -5. *(v5 #6)* **Highlight ranges are computed per line on demand.** Searching +7. *(v5 #6)* **Highlight ranges are computed per line on demand.** Searching one character over bash matches 177 k lines at 310 k places; all but the forty on screen were built and thrown away. -6. *(v1 #9/#10/#13, v2 #3, v5 #3)* Constants: `bytes.hex(" ")` for the opcode +8. *(v1 #9/#10/#13, v2 #3, v5 #3)* 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, `_CellRow` writing by slice, `HexView` emitting @@ -194,16 +217,25 @@ assertion guards a real past regression. Most other phases are now within ~2× of Textual's own per-frame compositing cost, which is not ours to remove. -**Benchmark history** — the bench was corrected three times, each time because -it was measuring a cache hit or its own overhead. Every re-baseline is in +**Benchmark history.** The bench was corrected five times. Three of those found +a cost that was *entirely invisible*, and two of those three turned out to be +among the largest wins of the whole session. Every re-baseline is in `.auto/log.jsonl`: | bench | baseline | best | what changed | |---|---|---|---| | v1 | 46 572 | 19 006 | — | -| v2 | 27 913 | 17 501 | graph opens were timing a cache hit | +| v2 | 27 913 | 17 501 | graph opens were timing a **cache hit** | | v4 | 18 498 | — | decomp/search/index reps were timing cache hits | -| v5 | 18 516 | 17 944 | landing polls every 2 ms, not 10 | +| v5 | 18 516 | 17 465 | landing polls every 2 ms, not 10 | +| v6 | 33 502 | 19 835 | **split view was not covered at all** (48% of a session) | +| v7 | 33 243 | 28 651 | **rename was not covered at all** (1.7 s each on bash) | + +**The most productive thing in this session was asking what the bench does not +measure.** Features still uncovered: xrefs (`x`), the strings browser (`"`), the +struct editor, literal formats (`o`), make-code/data edits, history, execution +traces, the RPC layer. Domain-level probes say xrefs/strings/structs/resolve are +all fast (`/tmp/featprobe.py` pattern), but nothing has driven them end to end. **Measurement traps** |