From 4bc162ddc82dda13ca527b686190a8b723fdadd2 Mon Sep 17 00:00:00 2001 From: blasty Date: Fri, 7 Aug 2026 03:13:22 +0200 Subject: bench: poll landings every 2ms, not 10 -- the wait interval was measurement overhead --- .auto/bench.py | 9 ++++++++- .auto/log.jsonl | 1 + 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/.auto/bench.py b/.auto/bench.py index d286c14..5d135f7 100644 --- a/.auto/bench.py +++ b/.auto/bench.py @@ -78,7 +78,14 @@ def fail(msg): FAILS.append(PREFIX + msg) -async def _wait(pilot, pred, t=60.0, step=0.01): +#: Poll interval for every "has it landed yet" wait. The phases time the wait, +#: so the interval is measurement overhead: at the 10ms this used to use, a +#: graph open that really took 30ms was charged up to 40, and the graph phase +#: (24 timed waits) carried ~12% of pure quantisation. +_STEP = 0.002 + + +async def _wait(pilot, pred, t=60.0, step=_STEP): return await wait_for(pred, pilot.pause, t, step) diff --git a/.auto/log.jsonl b/.auto/log.jsonl index 8f706b4..d7d8b7f 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -21,3 +21,4 @@ {"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."}} {"type":"config","name":"ida-tui performance (v3 bench: lower-noise estimator)","metricName":"total_ms","metricUnit":"ms","bestDirection":"lower"} {"type":"config","name":"ida-tui performance (v4 bench: cold phases measured once, repeatable ones averaged)","metricName":"total_ms","metricUnit":"ms","bestDirection":"lower"} +{"run":20,"commit":"49184b6","metric":18497.9,"metrics":{"lg_boot_ms":694.8,"lg_decomp_ms":2674,"lg_graph_ms":992.7,"lg_hex_ms":429.1,"lg_index_ms":94.9,"lg_listing_cold_ms":545.3,"lg_listing_warm_ms":410.7,"lg_nav_ms":6489,"lg_palette_ms":4.7,"lg_render_ms":220.6,"lg_search_ms":1489.8,"pure_graph_ms":241,"sm_boot_ms":467.1,"sm_decomp_ms":1308.5,"sm_graph_ms":761,"sm_hex_ms":431.7,"sm_index_ms":2.5,"sm_listing_cold_ms":273.9,"sm_listing_warm_ms":289,"sm_nav_ms":373,"sm_palette_ms":0.3,"sm_render_ms":257.2,"sm_search_ms":47,"fails":0},"status":"keep","description":"RE-BASELINE (v4 bench). Adding a second repetition on the big target exposed the same flaw the graph phase had: decompile, search and the function index all cache their answer, so a second rep reported a dict lookup under the name of the thing a user waits for. Cold-sensitive phases (listing_cold, decomp, search, index) now run ONCE; repeatable ones (render, hex, graph, listing_warm) run every rep and take the median. pure_graph is median-of-3.","timestamp":1786065121146,"segment":3,"confidence":null,"asi":{"hypothesis":"reduce the metric's noise so changes worth 1-2% are readable","what_changed_in_the_bench":"pure_graph median-of-3 (it swung 239 <-> 524 with identical code); two reps on targets/bash; and cold-sensitive phases pinned to the first rep only","flaw_this_caught":"sm_decomp had been min-of-2 since the start, i.e. it was reporting a WARM decompile (Program._decomp is cached per function). Honest cold value is 1308ms, not ~650. Same for sm_search and sm_index. All comparisons within v1-v3 were still valid (consistent measurement), but the absolute picture was wrong: decomp is 22% of the total, not 12%.","cumulative_history":"v1 baseline 46572 -> 19006 over 10 experiments. v2 (cold graph opens measured) baseline 27913 -> 17501 over 9. v3 abandoned after one run for the flaw above. v4 baseline 18498.","budget_ms":{"lg_nav":6489,"decomp lg+sm":3983,"graph lg+sm":1754,"search lg+sm":1537,"listing lg+sm":1519,"boot lg+sm":1162,"hex lg+sm":861,"render lg+sm":478,"pure_graph":241},"next_action_hint":"decomp is now clearly #2 at 22%. sm_decomp is 1308ms for TWELVE small echo functions (109ms each), which is far more than Hex-Rays should need on a 1.6KB function -- profile the cold F5 path on echo before assuming it is the decompiler."}} -- cgit v1.3.1-sl0p