From 26fa14cfdb8030e48cbd6d651b8415f078d4fee9 Mon Sep 17 00:00:00 2001 From: user Date: Fri, 7 Aug 2026 02:25:44 +0200 Subject: 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. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Result: {"status":"keep","total_ms":27912.9,"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} --- .auto/log.jsonl | 1 + 1 file changed, 1 insertion(+) diff --git a/.auto/log.jsonl b/.auto/log.jsonl index c9e3f14..e257ed7 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -9,3 +9,4 @@ {"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."}} +{"type":"config","name":"ida-tui performance (v2 bench: graph opens are now measured cold)","metricName":"total_ms","metricUnit":"ms","bestDirection":"lower"} -- cgit v1.3.1-sl0p