autoresearch: note the machine-load caveat in the playbook

2 files changed, 10 insertions, 0 deletions

diff --git a/.auto/log.jsonl b/.auto/log.jsonl
index c94c009..cf6fadd 100644
--- a/.auto/log.jsonl
+++ b/.auto/log.jsonl
@@ -26,3 +26,5 @@
 {"run":21,"commit":"5a8027e","metric":18516,"metrics":{"lg_boot_ms":663.9,"lg_decomp_ms":2663.2,"lg_graph_ms":1012.3,"lg_hex_ms":436.1,"lg_index_ms":98.4,"lg_listing_cold_ms":437.7,"lg_listing_warm_ms":409.4,"lg_nav_ms":6841.9,"lg_palette_ms":4.7,"lg_render_ms":218.8,"lg_search_ms":1474.7,"pure_graph_ms":241.6,"sm_boot_ms":433.3,"sm_decomp_ms":1266.3,"sm_graph_ms":737.9,"sm_hex_ms":424.2,"sm_index_ms":2.3,"sm_listing_cold_ms":262.9,"sm_listing_warm_ms":283.2,"sm_nav_ms":301.2,"sm_palette_ms":0.3,"sm_render_ms":253.9,"sm_search_ms":47.9,"fails":0},"status":"keep","description":"Baseline for the v5 bench (landing polls every 2ms instead of 10ms; the poll interval was measurement overhead inside the timed regions). Final measurement shape — no further bench changes.","timestamp":1786065328607,"segment":4,"confidence":null,"asi":{"hypothesis":"the 10ms wait_for step was charging every timed landing up to 10ms of quantisation","effect":"sm_nav 373 -> 301, sm_decomp 1309 -> 1266 (12 timed waits each). lg_graph and lg_decomp did not move measurably -- their per-item costs are large enough that 5ms of expected overshoot is lost in the spread.","decision":"this is the last bench change. Any further one costs a re-baseline, and the measurement is now honest about cold vs warm (v4) and free of both the cache-hit and quantisation artefacts.","budget_ms":{"lg_nav":6842,"decomp lg+sm":3930,"graph lg+sm":1750,"search lg+sm":1523,"listing lg+sm":1393,"boot lg+sm":1097,"hex lg+sm":860,"render lg+sm":473,"pure_graph":242},"decomp_anatomy_echo":"12 small functions: Program.decompile (Hex-Rays) 562ms, UI F5 path with everything already cached 414ms, four scroll+paint frames 186ms, highlight_c 86ms. The 414ms of UI is two @work thread spawns, ~4 event-loop hops, and a loading-cover mount/unmount per F5 -- and show() runs exactly ONCE per F5 (checked by counting), so there is no double work to remove.","next_action_hint":"the loading cover is 4.6ms of mount+unmount per F5 and cannot be deferred (a scenario asserts F5 raises it synchronously). The remaining decomp lever is _show_active spawning _load_decomp as a thread even when Program already has the decompilation cached."}}
 {"run":22,"commit":"5a8027e","metric":18535.4,"metrics":{"lg_boot_ms":692.3,"lg_decomp_ms":2662.1,"lg_graph_ms":895.9,"lg_hex_ms":422.2,"lg_index_ms":94.1,"lg_listing_cold_ms":525.4,"lg_listing_warm_ms":404.2,"lg_nav_ms":6821.6,"lg_palette_ms":4.7,"lg_render_ms":215.7,"lg_search_ms":1489.3,"pure_graph_ms":247.8,"sm_boot_ms":437.2,"sm_decomp_ms":1258.5,"sm_graph_ms":749.3,"sm_hex_ms":437.6,"sm_index_ms":2.4,"sm_listing_cold_ms":263.3,"sm_listing_warm_ms":283.1,"sm_nav_ms":321.5,"sm_palette_ms":0.3,"sm_render_ms":257.5,"sm_search_ms":49.2,"fails":0},"status":"discard","description":"Apply an already-decompiled function inline instead of spawning a background worker for it (Program.cached_decompilation/cached_pc_nums + _decomp_now), and warm pc_nums in the thread that already decompiled. Total flat (18516 -> 18535) and the phase it targets did not move either (lg_decomp 2663 -> 2662, sm_decomp 1266 -> 1259).","timestamp":1786065730509,"segment":4,"confidence":null,"asi":{"hypothesis":"an F5 spawns two @work threads and hops the event loop four times; skipping the second when the answer is already cached should show up in decomp","result":"it does not. A Textual thread spawn plus its call_from_thread round trip is worth well under 1% of a 100-220ms F5. The cost is elsewhere: Hex-Rays itself (562ms of sm_decomp's 1266), the loading-cover mount/unmount, highlight_c, and the Strip/scroll work in DecompView.show.","rollback_reason":"no measurable gain on the targeted phase, and it adds a second path into _apply_decomp with its own generation-check reasoning to keep correct. Simpler is better.","correctness_was_fine":"301 scenarios passed with it in; this is a complexity-vs-payoff rejection, not a bug.","kept_knowledge":"Program.cached_decompilation / cached_pc_nums would be the right primitives if a future change needs to know whether an answer is in hand without paying for it","next_action_hint":"boot is 1097ms across both targets and ~300ms of it is the worker importing idapro before it can serve. Check whether launch.py can spawn the worker BEFORE Textual starts, so that import overlaps the app's own startup instead of following it."}}
 {"run":23,"commit":"98b3b98","metric":17944.4,"metrics":{"lg_boot_ms":703.7,"lg_decomp_ms":2453.7,"lg_graph_ms":1000,"lg_hex_ms":478,"lg_index_ms":96,"lg_listing_cold_ms":453,"lg_listing_warm_ms":411.2,"lg_nav_ms":6555.9,"lg_palette_ms":4.9,"lg_render_ms":218.4,"lg_search_ms":1308.8,"pure_graph_ms":212.3,"sm_boot_ms":432.4,"sm_decomp_ms":1267.8,"sm_graph_ms":742.7,"sm_hex_ms":440,"sm_index_ms":2.5,"sm_listing_cold_ms":264.3,"sm_listing_warm_ms":289.5,"sm_nav_ms":305.4,"sm_palette_ms":0.3,"sm_render_ms":258.6,"sm_search_ms":45,"fails":0},"status":"keep","description":"Three targeted cuts: the graph's transposition pass counts keep and swap in one pass over the neighbour pairs (was four _pair_cross calls); the barycentre median answers degree 1 and 2 without sorting; and the search body is built from windowed model reads instead of one locked row lookup per line.","timestamp":1786066135637,"segment":4,"confidence":29.46391752577091,"asi":{"hypothesis":"clear the last measurable constants in the layout engine and the search body build","gains":"total 18516 -> 17944 (-3.1%); lg_search 1475 -> 1309; pure_graph 242 -> 212; corpus layout 236 -> 204ms standalone","layout_change":"_swap_delta returns (keep, swap) from one pass over the neighbour pairs. _pair_cross was called four times per candidate swap -- 353k calls over the corpus -- and each pair was compared twice, once per direction. median() answers |neighbours| of 1 or 2 arithmetically; sorted() was called 67k times, almost always on a list of one or two.","layout_equivalence":"node geometry (id, x, y, w, h) is IDENTICAL for all 128 corpus functions; tests/test_graph.py passes 470 checks including the no-edge-inside-a-box invariant.","PRE_EXISTING_BUG_FOUND":"idatui/graph.py edge ROUTING is non-deterministic: running the UNCHANGED engine twice on the same input gives different painting.vruns for 71 of 128 functions. Node placement is stable; only the routing moves. That is why a naive old-vs-new painting diff is useless here -- old-vs-old fails it too. Logged in .auto/ideas.md; worth fixing on its own merits (a graph should not redraw differently when you reopen it).","search_change":"SearchMixin gained a _search_line_texts(start, count) hook; ListingView serves it from model.window(), so building the joined body takes the model lock and bisects its row table once per 4096-row chunk instead of once per row.","verified":".auto/check_search.py 140 prefixes 0 mismatches; 301 scenarios pass","next_action_hint":"budget: lg_nav 6556 (37%), decomp 3722, graph 1743, search 1354, listing 1418, boot 1136, hex 918, render 477, pure_graph 212. Everything except nav and Hex-Rays is now within ~2x of the Textual compositor's own per-frame cost."}}
+{"run":24,"commit":"8218b91","metric":18608,"metrics":{"lg_boot_ms":708.5,"lg_decomp_ms":2454.9,"lg_graph_ms":1034.5,"lg_hex_ms":431.9,"lg_index_ms":95.1,"lg_listing_cold_ms":530.2,"lg_listing_warm_ms":413.4,"lg_nav_ms":7057.9,"lg_palette_ms":5,"lg_render_ms":214.2,"lg_search_ms":1408.9,"pure_graph_ms":213.3,"sm_boot_ms":433.6,"sm_decomp_ms":1292,"sm_graph_ms":754,"sm_hex_ms":433.4,"sm_index_ms":2.6,"sm_listing_cold_ms":260.4,"sm_listing_warm_ms":280.5,"sm_nav_ms":286.1,"sm_palette_ms":0.3,"sm_render_ms":251,"sm_search_ms":46.5,"fails":0},"status":"keep","description":"CORRECTNESS REPAIR, kept on its merits. The full suite (which the gate was NOT running) revealed that the worker-connect poll change made test_project_ui flaky: 5ms polling on a background thread through a cold auto-analysis starved the UI thread enough that the loading overlay was still up when the test pressed Ctrl+O. Poll now backs off to a 25ms cap (keeps the boot win, no busy-wait), the racy boot wait is fixed, and checks.sh runs tests/run.py in full (830 checks) instead of just the scenario suite.","timestamp":1786068002977,"segment":4,"confidence":12.426086956521708,"asi":{"honesty_note":"total_ms 17944 -> 18608 is WORSE, and I am keeping it anyway. The whole delta is lg_nav (6556 -> 7058), a phase nothing here touches and whose characterised spread is +/-500ms; boot, the phase this actually affects, is unchanged (sm_boot 432 -> 434, lg_boot 704 -> 709). Discarding would auto-revert a regression repair and a gate fix, which is the wrong trade whatever the number says. Re-running next to confirm the drift.","the_regression":"tests/test_project_ui.py went from 4/4 passing on the pre-autoresearch code to 1/3 on the branch. Bisected to idatui/worker_client.py: reverting it alone gave 3/3, reverting idatui/app.py alone gave 1/3.","root_cause":"experiment #13 held the connect poll at 5ms for the first 5 seconds. That poll runs on a background thread while the UI thread draws; 200 wakeups a second through a cold auto-analysis (targets/cat has no prebuilt .i64) cost enough GIL time to delay the app's own startup. The loading overlay is a ModalScreen and was still up when the test pressed Ctrl+O, so the key was swallowed and the switcher never opened.","fix":"cap the geometric backoff at 25ms instead. Bounded overshoot on a fast open (the 351ms -> 273ms boot win survives) and 40 probes/sec during a real analysis, which is nothing.","test_repair_and_its_three_proofs":["bisect: worker_client.py flips it, app.py does not","race reproduced outside the suite: the same steps print screen_stack ['Screen','LoadingScreen'] on the fast backend and ['Screen'] on the slow one","repaired test passes 5/5 on the fast backend and 3/3 on the pre-autoresearch backend"],"test_edit_scope":"the boot wait now also requires the loading overlay to be gone; two later waits require an empty screen stack. No assertion changed. Same class of fix as graph_minimap in v1 #6.","GATE_GAP_CLOSED":"checks.sh ran only tests/run.py --fast + the scenario suite. test_project_ui, blob_ui, thumb_ui, trace_ui, trace_rpc, rawimage_rpc were never run -- 830 checks now run, not 645. Verified the failure path end to end by injecting a deliberate failing check: the gate names the file, re-runs it alone, and exits 1.","lesson":"'poll faster' is not free in a GIL runtime when the poller shares a process with a UI thread. And a gate that runs a subset of the suite will eventually let something through -- it took 13 experiments here."}}
+{"run":25,"commit":"8218b91","metric":18746.2,"metrics":{"lg_boot_ms":713.2,"lg_decomp_ms":2575.4,"lg_graph_ms":1010.9,"lg_hex_ms":457.3,"lg_index_ms":97.3,"lg_listing_cold_ms":561.7,"lg_listing_warm_ms":411.8,"lg_nav_ms":6936.8,"lg_palette_ms":4.7,"lg_render_ms":225.9,"lg_search_ms":1442.5,"pure_graph_ms":212.9,"sm_boot_ms":433.3,"sm_decomp_ms":1304.2,"sm_graph_ms":710.8,"sm_hex_ms":456.7,"sm_index_ms":2.3,"sm_listing_cold_ms":263.9,"sm_listing_warm_ms":285.7,"sm_nav_ms":334.7,"sm_palette_ms":0.3,"sm_render_ms":257.2,"sm_search_ms":46.5,"fails":0},"status":"discard","description":"Confirmation re-run of #24 with no code change. 18608 -> 18746, i.e. the elevated lg_nav is not drift within a run — the BOX got busier (load average 0.62 at session start, 1.55 now). The direct paging microbenchmark is unchanged at 24.4 us/row, so the code is the same speed; the wall clock is not.","timestamp":1786068203628,"segment":4,"confidence":7.8732782369147385,"asi":{"hypothesis":"is the +500ms on lg_nav since #23 a code cost or the environment?","answer":"environment. /tmp/domain_break.py (a direct cold walk of bash's .text through the worker, no UI) reads 20.31us/row in the heads call + 4.04us/row client-side -- identical to the reading taken before the correctness fix. Meanwhile the box's load average went 0.62 -> 1.55 during the session.","consequence":"totals measured from here on are NOT comparable with those from the first half of the session. lg_nav is 224k sequential worker round trips and is the phase most exposed to a co-tenant; the idatui skill already warns that idalib is reap-prone under load. Compare against a same-session baseline, or use the phase-level microbenchmarks (/tmp/domain_break.py, /tmp/spanbench2.py, .auto/diff_spans.py) which are far less exposed.","no_code_change":"nothing to revert; logged as discard because the metric did not improve","next_action_hint":"if the loop continues on a loaded box, prefer changes whose effect is verifiable in a microbenchmark rather than in total_ms"}}
diff --git a/.auto/prompt.md b/.auto/prompt.md
index 3965e3e..4c3bbef 100644
--- a/.auto/prompt.md
+++ b/.auto/prompt.md
@@ -180,6 +180,14 @@ it was measuring a cache hit or its own overhead. Every re-baseline is in
 
 **Measurement traps**
 
+- **Check `uptime` before believing a number.** This box started the session at
+  load 0.6 and drifted to 1.6; `lg_nav` (224 000 sequential worker round trips)
+  moved 6 556 → 7 058 with no code change, while the direct paging microbenchmark
+  stayed at 24.4 µs/row. Totals are not comparable across a load change — rebase
+  on a fresh same-session run, or verify in a microbenchmark:
+  `/tmp/domain_break.py` (cold paging), `.auto/diff_spans.py` (span walker),
+  `tests/test_graph.py <corpus>` (layout).
+
 - `cProfile` massively distorts this code (it is call-heavy): it reported
   `_idatui_spans` at 68% of the `heads` tool when the real share was ~10%.
   A/B with `time.perf_counter` in one process instead.