diff options
| author | user <user@clank> | 2026-08-07 04:19:56 +0200 |
|---|---|---|
| committer | user <user@clank> | 2026-08-07 04:19:56 +0200 |
| commit | 722025af53a67af017641c8f7989001046f89fa0 (patch) | |
| tree | 2c0822d2d1cb246ce5745e7dd938378db0592bca | |
| parent | Keep a listing row's spans and operand extents exactly as they came off the w... (diff) | |
| download | ida-tui-722025af53a67af017641c8f7989001046f89fa0.tar.gz ida-tui-722025af53a67af017641c8f7989001046f89fa0.tar.xz ida-tui-722025af53a67af017641c8f7989001046f89fa0.zip | |
Confirmation re-run of #27, no code change: 17700 -> 17465, the best v5 reading. Confirms the wire-shape change holds and that the run-to-run spread is ~250ms even on the now-busier box.
Result: {"status":"keep","total_ms":17464.6,"lg_boot_ms":744.8,"lg_decomp_ms":2600.3,"lg_graph_ms":889.3,"lg_hex_ms":436.1,"lg_index_ms":95.5,"lg_listing_cold_ms":436.4,"lg_listing_warm_ms":407.8,"lg_nav_ms":6747.4,"lg_palette_ms":4.6,"lg_render_ms":218.9,"lg_search_ms":760.9,"pure_graph_ms":215.7,"sm_boot_ms":429.7,"sm_decomp_ms":1263.5,"sm_graph_ms":650.2,"sm_hex_ms":435.3,"sm_index_ms":2.3,"sm_listing_cold_ms":262.8,"sm_listing_warm_ms":264.7,"sm_nav_ms":305.4,"sm_palette_ms":0.3,"sm_render_ms":251.4,"sm_search_ms":41.1,"fails":0}
| -rw-r--r-- | .auto/log.jsonl | 1 |
1 files changed, 1 insertions, 0 deletions
diff --git a/.auto/log.jsonl b/.auto/log.jsonl index a392e8f..4ecfac1 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -29,3 +29,4 @@ {"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"}} {"run":26,"commit":"7683ca3","metric":17829.9,"metrics":{"lg_boot_ms":724.4,"lg_decomp_ms":2353.5,"lg_graph_ms":1041,"lg_hex_ms":434.9,"lg_index_ms":95.5,"lg_listing_cold_ms":545.6,"lg_listing_warm_ms":407.9,"lg_nav_ms":6922,"lg_palette_ms":4.8,"lg_render_ms":218.1,"lg_search_ms":884.3,"pure_graph_ms":213.6,"sm_boot_ms":432,"sm_decomp_ms":1250.2,"sm_graph_ms":687.4,"sm_hex_ms":457.5,"sm_index_ms":2.6,"sm_listing_cold_ms":265.4,"sm_listing_warm_ms":288.8,"sm_nav_ms":303.2,"sm_palette_ms":0.3,"sm_render_ms":253.9,"sm_search_ms":43,"fails":0},"status":"keep","description":"Highlight ranges are computed per line on demand instead of for every match. Searching one character over bash matches 177k lines at 310k places, and all but the forty on screen were built and thrown away. _MatchRanges keeps the line SET eagerly and works out the offsets when a line is painted or the cursor lands on it; the blob scan now also skips to the next line after a hit.","timestamp":1786068588431,"segment":4,"confidence":4.5317040951122864,"asi":{"hypothesis":"profiling the search phase directly showed the per-match range building, not the scanning, was the cost","microbench_before_after_ms_per_term":{"note":"targets/bash, 228659 rows, _compute_matches only","m":[139.7,41.6],"mo":[153.9,49.2],"mov":[55.4,47],"c":[329.6,66.1],"ca":[51.5,47.3],"cal":[32.9,30],"call":[29.2,26.8],"haystack_build":[458,459]},"equivalence":"the microbenchmark materialises every range afterwards and prints the totals: 116736 / 76271 / 76070 / 309827 / 25222 / 16312 / 15722 -- identical to the eager version, term for term. Plus .auto/check_search.py (140 prefixes, listing + pseudocode, 0 mismatches) and the full 830-check suite.","api_shape":"_MatchRanges quacks as the dict it replaced for the subset anything uses (in / get / [] / items / len). tests/test_scenarios.py reads dis._ranges.get(cursor) and dis._ranges[cursor][0][0] directly, so that had to keep working -- it does, untouched.","gains":"total 18608 -> 17830 on a box that has got busier since the earlier runs; lg_search 1409 -> 884 (-37%), sm_search 46 -> 43","whats_left_in_search":"the haystack build, 459ms: one _line_plain pass over 228k rows plus a 12.3MB join and lower(). That is the floor unless the plain text is cached with the rows.","next_action_hint":"budget: lg_nav 6922 (39%, and inflated by machine load), decomp 3604, graph 1728, search 927, listing 1508, boot 1156, hex 892, render 472, pure_graph 214."}} +{"run":27,"commit":"b2b59e0","metric":17700.4,"metrics":{"lg_boot_ms":776,"lg_decomp_ms":2690.1,"lg_graph_ms":888.1,"lg_hex_ms":449.1,"lg_index_ms":97.4,"lg_listing_cold_ms":439.4,"lg_listing_warm_ms":404.6,"lg_nav_ms":6762.9,"lg_palette_ms":4.6,"lg_render_ms":230.8,"lg_search_ms":762.9,"pure_graph_ms":217.1,"sm_boot_ms":452.6,"sm_decomp_ms":1270,"sm_graph_ms":698,"sm_hex_ms":433.2,"sm_index_ms":2.4,"sm_listing_cold_ms":259.1,"sm_listing_warm_ms":260.5,"sm_nav_ms":300.4,"sm_palette_ms":0.3,"sm_render_ms":258.3,"sm_search_ms":42.7,"fails":0},"status":"keep","description":"Keep a listing row's spans and operand extents exactly as they came off the wire instead of copying them into tuples. The copy re-proved types the worker's own tool guarantees, and it destroyed the object sharing the worker's line cache had created — 228k rows now reference 125k span lists, not 228k private tuples.","timestamp":1786068961469,"segment":4,"confidence":3.5430060816680973,"asi":{"hypothesis":"the tuple conversion in Head.from_raw is the last measurable client-side cost per listing row","microbench":"cold page load of bash's .text, broken into three: worker call 19.85 us/row, client _build_page 3.19 -> 2.51 us/row, index loop 0.37 us/row. The index loop (setdefault + three appends + a _span call per head) is NOT worth touching.","memory":"a full 228 659-row bash listing costs the client ~258MB RSS and now holds 125 510 distinct span objects rather than one per row -- the worker memoises its per-line render and pickle preserves that sharing within a page, which copying threw away.","safety_audit_done_first":"every reader of h.spans / h.ops only iterates or indexes (app.py _span_segments, _cursor_operand, GraphView._draw_node_row, Head.op_at, and four places in tests). Nothing mutates them and nothing hashes a Head -- which matters, because Head is a NamedTuple and a list field would make it unhashable.","gains":"total 17830 -> 17700; lg_search 884 -> 763; lg_graph 1041 -> 888; sm_nav_worst 177 -> 151","verified":"830-check full suite green, .auto/check_search.py 140 prefixes 0 mismatches","state":"the per-row cost is now 19.85us in the worker (of which generate_disasm_line is 5.9) and 2.9us in the client. There is no further client-side lever worth the risk."}} |
