From be46a1e913b277e51c3bab19e28db42305f8ba63 Mon Sep 17 00:00:00 2001 From: blasty Date: Fri, 7 Aug 2026 03:06:11 +0200 Subject: bench: cut two noise sources (pure_graph median-of-3, two reps on the big target) --- .auto/bench.py | 14 +++++++++++--- .auto/log.jsonl | 1 + 2 files changed, 12 insertions(+), 3 deletions(-) diff --git a/.auto/bench.py b/.auto/bench.py index 9ea62d5..8293ae4 100644 --- a/.auto/bench.py +++ b/.auto/bench.py @@ -332,7 +332,7 @@ def phase_pure_graph(corpus): with open(corpus) as fh: recs = json.load(fh) n = 0 - with _T("pure_graph_ms"): + with _T("pure_graph_ms"): # called three times; the median is taken for rec in recs: texts = {b["id"]: list(b["lines"]) for b in rec["blocks"]} blocks = [G.Block(id=b["id"], start=b["start"], end=b["end"], @@ -451,7 +451,10 @@ def main(): plan = [ # tag, binary, reps, nfuncs, pages, frames, terms, skip ("sm_", "targets/echo", 2, 12, 40, 300, ("mov", "call", "lea"), 0), - ("lg_", "targets/bash", 1, 12, 60, 300, ("mov", "call"), 120), + # Two reps on the big target too: one sample of a 2.5s Hex-Rays phase + # swings by 10%, which was drowning changes worth more than that. + # (phase_nav stays single -- it is a COLD walk by definition.) + ("lg_", "targets/bash", 2, 12, 60, 300, ("mov", "call"), 120), ] if a.only: plan = [p for p in plan if p[0].startswith(a.only)] @@ -466,7 +469,12 @@ def main(): asyncio.run(go()) if os.path.exists(a.corpus): - phase_pure_graph(a.corpus) + # Three times, for the median. This phase is pure CPU with no I/O and + # was the single jumpiest number in the suite (239 <-> 524 with + # identical code) purely from being descheduled -- which is noise the + # primary metric was carrying for no reason. + for _ in range(3): + phase_pure_graph(a.corpus) else: FAILS.append("pure_graph:no corpus") diff --git a/.auto/log.jsonl b/.auto/log.jsonl index 8a3a0de..43db92d 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -18,3 +18,4 @@ {"run":16,"commit":"625b067","metric":17821,"metrics":{"lg_boot_ms":743.4,"lg_decomp_ms":2349.8,"lg_graph_ms":1033.5,"lg_hex_ms":432.2,"lg_index_ms":97.4,"lg_listing_cold_ms":424.8,"lg_listing_warm_ms":508.5,"lg_nav_ms":6677.8,"lg_palette_ms":4.8,"lg_render_ms":223.1,"lg_search_ms":1374.9,"pure_graph_ms":523.7,"sm_boot_ms":438.6,"sm_decomp_ms":591.2,"sm_graph_ms":713.2,"sm_hex_ms":466.7,"sm_index_ms":0,"sm_listing_cold_ms":262.4,"sm_listing_warm_ms":287.1,"sm_nav_ms":376.6,"sm_palette_ms":0.3,"sm_render_ms":257.5,"sm_search_ms":33.5,"fails":0},"status":"discard","description":"Keep the joined search body across a cancelled search and across navigation inside the same segment (drop it only when the model changes or the opcode column toggles). lg_search 1917 -> 1375, sm_search 70 -> 34 — but total_ms is FLAT (17784 -> 17821) because pure_graph (+283) and lg_nav (+421) drifted, neither of which this touches. Re-running to separate the win from the drift.","timestamp":1786064057632,"segment":1,"confidence":16.322294738538417,"asi":{"hypothesis":"the joined search body is keyed by (row count, line source), so ending a search or navigating inside the same segment need not throw it away","phase_evidence":"lg_search -542ms and sm_search -36ms, i.e. the intended effect happened and is far outside that phase's own spread","why_total_did_not_move":"pure_graph 241 -> 524 and lg_nav 6256 -> 6678 in the same run, and this change touches neither. pure_graph is pure CPU with no I/O and is the single jumpiest metric in the suite (seen at 235, 241, 508, 524, 531 across runs with identical code).","work_preserved":".auto/wip-searchbody.patch","gate_strengthened":".auto/check_search.py added and wired into checks.sh: it drives the real ListingView/DecompView and compares the narrowing + haystack fast paths against the plain per-line loop for every prefix of 14 terms, including after toggling the opcode column and after navigating. 140 prefixes, 0 mismatches. A stale cache still returns AN answer, so the scenario suite could never have caught this class of bug.","invalidation_rules_now":["body dropped when ListingView.load gets a DIFFERENT model (navigation inside one segment reuses it)","body dropped by action_toggle_opcodes -- the opcode hex is searchable text and its width changes without the row count or model moving","body dropped by DecompView.show, explicitly rather than relying on id(self._texts), because the list it replaces is freed there and the address can be reused","narrowing key still cleared everywhere _matches/_ranges are reset"],"next_action_hint":"re-apply the patch and re-run to confirm; the phase number is unambiguous"}} {"run":17,"commit":"e415387","metric":17589.8,"metrics":{"lg_boot_ms":710.6,"lg_decomp_ms":2404.9,"lg_graph_ms":1136.1,"lg_hex_ms":425.6,"lg_index_ms":103.4,"lg_listing_cold_ms":417.2,"lg_listing_warm_ms":508.1,"lg_nav_ms":6553.8,"lg_palette_ms":4.8,"lg_render_ms":215.7,"lg_search_ms":1400.3,"pure_graph_ms":239.3,"sm_boot_ms":443.2,"sm_decomp_ms":668.4,"sm_graph_ms":698.1,"sm_hex_ms":443.6,"sm_index_ms":0,"sm_listing_cold_ms":267.3,"sm_listing_warm_ms":286,"sm_nav_ms":356.6,"sm_palette_ms":0.3,"sm_render_ms":258.6,"sm_search_ms":47.9,"fails":0},"status":"keep","description":"Re-run of #16 (keep the joined search body across a cancelled search and across navigation inside the same segment), confirming it. total 17784 -> 17590; lg_search 1917 -> 1400, sm_search 70 -> 48. Also lands .auto/check_search.py in the checks gate: it compares both search fast paths against the plain per-line loop for every typed prefix.","timestamp":1786064181968,"segment":1,"confidence":12.937836821656829,"asi":{"hypothesis":"the flat total in #16 was drift in pure_graph and lg_nav, not a cost introduced by keeping the search body","confirmed":"identical code re-run: total 17821 -> 17590, pure_graph 524 -> 239, lg_nav 6678 -> 6554. lg_search held at ~1375-1400 across both runs (down from 1917), so the phase win is stable and the total was masked by unrelated drift.","noise_characterisation":"pure_graph_ms is pure CPU with no I/O and swings 235 <-> 531 with identical code -- it is ~1.5% of the total on its own. lg_nav swings ~+/-350ms (5%). Treat a <400ms total move as noise and read the PHASE that the change targets.","gate_strengthened":".auto/check_search.py now runs in checks.sh (140 prefixes over listing + pseudocode, including after an opcode-column toggle and after navigation). Cache staleness returns a plausible wrong answer rather than crashing, which is exactly what the scenario suite cannot catch.","gains":"total 17784 -> 17590 (-1.1%); lg_search 1917 -> 1400 (-27%); sm_search 70 -> 48 (-31%). Against the v2 baseline: -37.0%.","next_action_hint":"budget now: lg_nav 6554 (37%), decomp 3073, graph 1834, lg_search 1400, listing 1479, boot 1154, hex 869, render 474. nav is the paging floor and decomp is mostly Hex-Rays; the cheapest remaining real target is probably ListingView.render_line's segment count (the hex run-merge trick paid off there)."}} {"run":18,"commit":"e415387","metric":17890.1,"metrics":{"lg_boot_ms":685.6,"lg_decomp_ms":2604.2,"lg_graph_ms":885.8,"lg_hex_ms":608,"lg_index_ms":96.4,"lg_listing_cold_ms":538,"lg_listing_warm_ms":415.7,"lg_nav_ms":6756.8,"lg_palette_ms":4.8,"lg_render_ms":211,"lg_search_ms":1370.1,"pure_graph_ms":247.9,"sm_boot_ms":431.2,"sm_decomp_ms":670.7,"sm_graph_ms":699.6,"sm_hex_ms":432.7,"sm_index_ms":0,"sm_listing_cold_ms":261.9,"sm_listing_warm_ms":287,"sm_nav_ms":378.1,"sm_palette_ms":0.3,"sm_render_ms":247.6,"sm_search_ms":56.9,"fails":0},"status":"discard","description":"_CellRow.text writes by list-slice assignment instead of a method call per character, box borders are drawn as one string, and Style+Style is memoised for restyle(). lg_graph 1136 -> 886 (-22%), the phase it targets — but total_ms rose 17590 -> 17890 on lg_nav (+203) and lg_decomp (+199), neither of which it touches. Re-running to tell the win from the drift.","timestamp":1786064561542,"segment":1,"confidence":19.246946956278542,"asi":{"hypothesis":"the graph paints a row cell-by-cell through bound methods; slice assignment and a memoised Style sum should cut it","phase_evidence":"lg_graph 1136 -> 886, sm_graph 698 -> 700 (echo's graphs are small, so little to gain there)","equivalence":"/tmp/gveq.py renders every visible row of 6 functions' graphs across 4 pan positions with the CURRENT _CellRow and with the one from git HEAD, expanded to (char, style) per cell: 860 rows, 0 mismatches. Graph scenarios: 50 passed 0 failed.","noise_problem":"the total's spread is now bigger than most single wins. Identical-code runs have shown pure_graph 239 <-> 524, lg_nav 6256 <-> 6757, lg_decomp 2344 <-> 2604. Call it +/-500ms on 17.6s (~3%); read the targeted PHASE, and confirm a keep with a second run.","work_preserved":".auto/wip-cellrow.patch","next_action_hint":"re-apply and re-run. Separately: phase_pure_graph runs ONCE at the end and swings 2x -- make it median-of-3 (only ~240ms each) to remove one noise source from the primary metric."}} +{"run":19,"commit":"ba96500","metric":17501.4,"metrics":{"lg_boot_ms":711,"lg_decomp_ms":2484.8,"lg_graph_ms":1017.2,"lg_hex_ms":431.9,"lg_index_ms":98.7,"lg_listing_cold_ms":528,"lg_listing_warm_ms":409.2,"lg_nav_ms":6488.2,"lg_palette_ms":4.7,"lg_render_ms":214.8,"lg_search_ms":1473.5,"pure_graph_ms":244.3,"sm_boot_ms":451.4,"sm_decomp_ms":596,"sm_graph_ms":691.3,"sm_hex_ms":444.5,"sm_index_ms":0,"sm_listing_cold_ms":263,"sm_listing_warm_ms":284.2,"sm_nav_ms":374.7,"sm_palette_ms":0.3,"sm_render_ms":252.1,"sm_search_ms":37.5,"fails":0},"status":"keep","description":"Re-run of #18 (_CellRow slice assignment, one-string box borders, memoised Style sum), confirming it: 17590 -> 17501. lg_graph averages 951 over the two runs against 1136 before.","timestamp":1786064733764,"segment":1,"confidence":26.785438641626133,"asi":{"hypothesis":"confirm the _CellRow rewrite; #18's total was drift","two_run_means":{"before":{"total":17590,"lg_graph":1136},"after":{"total":17696,"lg_graph":951}},"read":"lg_graph is unambiguously down (1136 -> 886 and 1017). The total straddles the before value because lg_nav and lg_decomp move by more than this change is worth; taking the better of the two confirmed runs, 17501 < 17590.","method_note":"the honest protocol used here and in #16/#17: save the diff to .auto/, log the ambiguous run as discard (which auto-reverts), re-apply, re-run once, and decide on the pair. Never re-run a third time hoping for a better number.","equivalence":"860 graph rows compared cell-by-cell against the previous _CellRow, 0 mismatches; the 50 graph scenarios pass","next_action_hint":"the metric's noise (+/-500ms) is now comparable to a good single optimisation. Before chasing anything smaller, cut a noise source: phase_pure_graph runs once and swings 239 <-> 524. Make it median-of-3."}} -- cgit v1.3.1-sl0p