bench: time a COLD graph open, and stop the fixture picker warming its cache

2 files changed, 15 insertions, 2 deletions

diff --git a/.auto/bench.py b/.auto/bench.py
index d869ea3..9ea62d5 100644
--- a/.auto/bench.py
+++ b/.auto/bench.py
@@ -222,6 +222,11 @@ async def phase_graph(app, pilot, funcs):
     gv = app.query_one(GraphView)
     ok = blocks = 0
     spent = 0.0
+    # Space on a function you have not graphed before is the case that hurts:
+    # it pays the flowchart tool, a heads walk over the function's extent, and
+    # the layout. Program caches flowcharts per function, so without this the
+    # phase would time a dict lookup.
+    app.program._flowcharts.clear()
     for fn in funcs:
         app._open_function(fn.addr, fn.name)
         if not await _wait(pilot, lambda fn=fn: app._cur is not None
@@ -400,10 +405,17 @@ async def run_target(binary, reps, nfuncs, pages, frames, terms, skip=0):
                 if len(big) >= nfuncs:
                     break
                 try:
-                    fc = app.program.flowchart(f.addr)
+                    # The raw tool, NOT Program.flowchart: the latter caches, and
+                    # picking the fixtures through it left phase_graph measuring
+                    # cache hits instead of the work a user waits for.
+                    payload = app.program.client.call("flowchart",
+                                                      addr=hex(f.addr))
                 except Exception:  # noqa: BLE001
                     continue
-                if fc is None or len(fc.blocks) > IdaTui.GRAPH_MAX_BLOCKS:
+                if not isinstance(payload, dict) or payload.get("error"):
+                    continue
+                nblocks = len(payload.get("blocks") or [])
+                if not nblocks or nblocks > IdaTui.GRAPH_MAX_BLOCKS:
                     continue
                 big.append(f)
             if len(big) < nfuncs:
diff --git a/.auto/log.jsonl b/.auto/log.jsonl
index b6959a9..c9e3f14 100644
--- a/.auto/log.jsonl
+++ b/.auto/log.jsonl
@@ -8,3 +8,4 @@
 {"run":7,"commit":"5045ba1","metric":20835.7,"metrics":{"lg_boot_ms":754.4,"lg_decomp_ms":2593.7,"lg_graph_ms":929.5,"lg_hex_ms":1080.2,"lg_index_ms":76.1,"lg_listing_cold_ms":526.7,"lg_listing_warm_ms":410.1,"lg_nav_ms":6674.8,"lg_palette_ms":5,"lg_render_ms":225.2,"lg_search_ms":3310.3,"pure_graph_ms":239.3,"sm_boot_ms":537.9,"sm_decomp_ms":630.1,"sm_graph_ms":734.3,"sm_hex_ms":869.9,"sm_index_ms":0,"sm_listing_cold_ms":260.8,"sm_listing_warm_ms":262.3,"sm_nav_ms":334.8,"sm_palette_ms":0.3,"sm_render_ms":268.4,"sm_search_ms":111.6,"fails":0},"status":"keep","description":"Incremental search narrows instead of rescanning. Typing a character onto the term can only remove lines (a line holding \"mov\" holds \"mo\"), so _compute_matches rescans the previous hit list when the term grew and nothing else moved. Keyed on (term, case-fold, row count, line-source id) so a listing still streaming rows in behind the search falls back to a full scan.","timestamp":1786060806344,"segment":0,"confidence":8.383192182410422,"asi":{"hypothesis":"as-you-type search rescans every row per keystroke; the match set is monotonically shrinking so it need not","gains":"total 22980 -> 20836 (-9.3%); lg_search 5630 -> 3310 (-41%); sm_search 196 -> 112 (-43%)","results_identical":"search_hits 91783 (bash) / 2461 (echo) unchanged from baseline -- the same lines still match","equivalence_test":"/tmp/searcheq.py drives the real ListingView keystroke by keystroke over 9 terms (mov/call/rsp/Mov/1a/push/e/lea/sub_) and compares the narrowed _matches AND _ranges against a forced full rescan at every prefix: 0 mismatches","invalidation_traps":["case folding is per-term (_ci = term.islower()) and can FLIP as you type: '1' -> '1a' goes False -> True, which can ADD matches. The key stores _ci and only narrows when it is unchanged.","the listing streams rows in behind the search, so row count is in the key -- rows that arrived since the last pass have never been looked at.","action_toggle_opcodes changes the plain line's prefix, so it changes WHICH rows match (the opcode hex is searchable text), not just the highlight offsets. It now clears the key too.","every site that resets _matches/_ranges must reset _matched_key, or a cancelled search leaves a stale prefix and the next search narrows from an empty list. Six sites."],"next_action_hint":"lg_nav 6675 is again the biggest term, then lg_decomp 2594 and lg_search 3310. For search what is left is _line_plain: it rebuilds the whole formatted row (address gutter + opcode field + name prefix + text) per row on the first, unnarrowed pass. For nav see .auto/ideas.md (skeleton walk)."}}
 {"run":8,"commit":"8b40fd2","metric":20412.8,"metrics":{"lg_boot_ms":752.9,"lg_decomp_ms":2418.6,"lg_graph_ms":811.6,"lg_hex_ms":1020.1,"lg_index_ms":73.2,"lg_listing_cold_ms":573.7,"lg_listing_warm_ms":456.7,"lg_nav_ms":6640.1,"lg_palette_ms":4.8,"lg_render_ms":237.6,"lg_search_ms":3210.2,"pure_graph_ms":242.5,"sm_boot_ms":536.5,"sm_decomp_ms":643.1,"sm_graph_ms":689.8,"sm_hex_ms":866.6,"sm_index_ms":0,"sm_listing_cold_ms":262.9,"sm_listing_warm_ms":265.9,"sm_nav_ms":330.1,"sm_palette_ms":0.3,"sm_render_ms":265.2,"sm_search_ms":110.5,"fails":0},"status":"keep","description":"Three micro-wins on the listing-row path: merge the colour-tag and operand-tag dicts into one lookup, skip both isspace() probes when a span needs no whitespace collapsing at all (the common case), and give Head slots=True. Spans 11.07 -> 10.18 us/line; Head construction 3.18 -> 2.53 us/row.","timestamp":1786061248935,"segment":0,"confidence":8.593443053776156,"asi":{"hypothesis":"shave the remaining per-row constants now that the structural wins are in","cost_model_measured":{"note":"cold walk of targets/bash .text, per LISTING ROW","worker_tool_compute_cold_us":18.1,"worker_tool_compute_warm_cache_us":10.3,"pickle_dumps_us":0.9,"pickle_loads_us":2.4,"client_build_page_us":4.5,"socket_round_trip_us_per_call":25},"worker_internals_us_per_head":{"generate_disasm_line":5.9,"head_row_warm_cache":8.4,"spans_on_a_cache_miss":10.2,"get_func":0.4,"get_ea_name":0.4,"struct_member_rows_per_DATA_row":3.8},"wire_shape_dead_end":"tried costing dict-with-hex-string-ea vs dict-with-int-ea vs plain tuples for the heads payload: 0.75/0.70/0.54 us dumps and 1.11/1.26/1.04 us loads per row. At most 0.3 us/row for a breaking change to the tool's wire format -- not worth it, do not revisit.","equivalence":"spans still byte-identical vs 2b0ae8d over 118k lines (bash/echo/ls_ttl); all NOTES counters unchanged","gains":"total 20836 -> 20413 (-2.0%); lg_graph 930 -> 812","next_action_hint":"lg_nav 6640 (33% of total) is now mostly irreducible per-row worker cost: generate_disasm_line is 5.9us of the ~18us and is IDA's. The only big lever left is NOT DOING IT -- a skeleton (ea,size,kind + row counts) walk so ensure_ea can find a row index without rendering text (.auto/ideas.md). Beware: the worker is a single serial process, so work moved to the background does not overlap; a skeleton only wins if the text is never needed."}}
 {"run":9,"commit":"4148738","metric":19476.3,"metrics":{"lg_boot_ms":756.3,"lg_decomp_ms":2495.1,"lg_graph_ms":946,"lg_hex_ms":905.4,"lg_index_ms":72,"lg_listing_cold_ms":547.5,"lg_listing_warm_ms":410.4,"lg_nav_ms":6723.4,"lg_palette_ms":5,"lg_render_ms":218.8,"lg_search_ms":2312.4,"pure_graph_ms":239.5,"sm_boot_ms":535.3,"sm_decomp_ms":616.4,"sm_graph_ms":682.2,"sm_hex_ms":824.9,"sm_index_ms":0,"sm_listing_cold_ms":258.9,"sm_listing_warm_ms":261,"sm_nav_ms":339.5,"sm_palette_ms":0.3,"sm_render_ms":248.7,"sm_search_ms":77.3,"fails":0},"status":"keep","description":"Two hot-path fixes found by profiling the plain-line builder: the opcode-bytes column used a per-byte f-string generator where bytes.hex(' ').upper() does it in one C call (12x), and ListingModel._phys/_head_index_at re-imported bisect on every call. _line_plain 2.64 -> 1.57 us/row.","timestamp":1786061547254,"segment":0,"confidence":9.517985106084026,"asi":{"hypothesis":"search's remaining cost is _line_plain, and _line_plain is dominated by something silly","profile_us_per_row_before":{"model.get":0.67,"model._phys":0.44,"_op_field":1.29,"_line_plain":2.64},"profile_us_per_row_after":{"model.get":0.56,"model._phys":0.34,"_op_field":0.4,"_line_plain":1.57},"finding":"the opcode-bytes column (op_mode=1 by default, so it is ALWAYS built) was ' '.join(f'{b:02X}' for b in raw): 1.74us vs 0.14us for raw.hex(' ').upper(). Verified byte-identical for every length 0..19.","finding2":"ListingModel._phys and _head_index_at each did 'import bisect' inside the function body, on a path that runs once per rendered row and once per row a search reads. bisect is already imported at module scope.","gains":"total 20413 -> 19476 (-4.6%); lg_search 3210 -> 2312 (-28%); sm_search 111 -> 77; sm_render 265 -> 249","work_unchanged":"search_hits, render_cells, all counters identical","remaining_budget_ms":{"lg_nav":6723,"lg_decomp+sm_decomp":3112,"lg_search":2312,"hex(lg+sm)":1730,"graph(lg+sm)":1628,"listing cold+warm(lg+sm)":1478,"boot(lg+sm)":1292,"render":468,"pure_graph":240},"next_action_hint":"decomp: 12 bash functions cost 1370ms of Hex-Rays (irreducible) + 240ms of pygments highlight_c (70us/line -- a hand-rolled C lexer would be faster but risks colour changes). hex: 1730ms for 120 frames = 14ms/frame, unprofiled, look there next. ALSO NOTED: domain.decomp_map costs 280ms per function (more than decompile itself) and is on the split-view path, which the bench does not cover."}}
+{"run":10,"commit":"f8fb9b7","metric":19005.8,"metrics":{"lg_boot_ms":788.9,"lg_decomp_ms":2752.5,"lg_graph_ms":899,"lg_hex_ms":565.2,"lg_index_ms":71.9,"lg_listing_cold_ms":416.1,"lg_listing_warm_ms":402.3,"lg_nav_ms":6756.3,"lg_palette_ms":4.7,"lg_render_ms":217.1,"lg_search_ms":2335.8,"pure_graph_ms":235.3,"sm_boot_ms":537.4,"sm_decomp_ms":600.9,"sm_graph_ms":693.1,"sm_hex_ms":549.9,"sm_index_ms":0,"sm_listing_cold_ms":280.9,"sm_listing_warm_ms":261.2,"sm_nav_ms":309,"sm_palette_ms":0.3,"sm_render_ms":249.3,"sm_search_ms":78.7,"fails":0},"status":"keep","description":"Only re-apply a scroll after the next refresh when it actually clamped. Both _apply_scroll implementations unconditionally scheduled a deferred scroll_to + refresh(layout=True) — a whole-screen re-arrange on every scroll — as a workaround for scrolling before the view's size is computed. Now the deferred pass runs only when scroll_offset didn't reach the target.","timestamp":1786061776694,"segment":0,"confidence":8.386589391381065,"asi":{"hypothesis":"the hex phase spends its time in the event loop, not in render_line -- something the app schedules per scroll is expensive","measurement":"profiling the hex sweep split it as ensure 0.1ms / scroll 6.7ms / pilot.pause 700ms / paint 106ms over 60 frames. The cost was in what the pause had to process.","isolation":"60 scroll frames on a live HexView: idle pause 73ms, scroll_to alone 497ms, scroll_to+refresh() 519ms, scroll_to+refresh(layout=True) 522ms, the shipped _apply_scroll 650ms. So the deferred call_after_refresh pass was ~25% on top of an already-costly scroll. After the fix: 453ms.","why_the_workaround_exists":"setting virtual_size then scrolling immediately clamps to 0 because max_scroll_y is not recomputed until layout (documented in the idatui skill). Keeping the deferred pass but only when scroll_offset actually missed the target preserves that and skips it otherwise. NOTE the pilot lays out synchronously, so under test the scroll always lands and the deferred pass is skipped -- the real-terminal path is the one that still schedules it.","gains":"total 19476 -> 19006 (-2.4%); hex(lg+sm) 1730 -> 1115 (-36%); lg_listing_cold 548 -> 416","noise_seen":"lg_decomp 2495 -> 2753 (+10%) with no change on that path -- Hex-Rays timing is the jumpiest phase; do not chase it","next_action_hint":"lg_nav 6756 is 36% of the total and is ~18us/row of worker time over 225k rows. Its parts: generate_disasm_line 5.9us (IDA's, irreducible), _idatui_spans ~10us on an lru miss, ~2us of dict building. Next: instrument _idatui_spans' four internal stages (split / token loop / whitespace collapse / operand extents) and see which is left."}}