diff options
| -rw-r--r-- | .auto/log.jsonl | 1 | ||||
| -rw-r--r-- | .auto/prompt.md | 40 |
2 files changed, 21 insertions, 20 deletions
diff --git a/.auto/log.jsonl b/.auto/log.jsonl index ed0514f..271d99d 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -40,3 +40,4 @@ {"run":33,"commit":"44c311a","metric":27571.1,"metrics":{"lg_boot_ms":714.2,"lg_decomp_ms":2426.5,"lg_graph_ms":914.1,"lg_hex_ms":436.7,"lg_index_ms":109.8,"lg_listing_cold_ms":772.1,"lg_listing_warm_ms":437.2,"lg_nav_ms":6876.9,"lg_palette_ms":4.7,"lg_rename_ms":732.9,"lg_render_ms":224.7,"lg_search_ms":1209,"lg_split_ms":6623.7,"pure_graph_ms":214.1,"sm_boot_ms":463.8,"sm_decomp_ms":1282.5,"sm_graph_ms":755,"sm_hex_ms":444.3,"sm_index_ms":2.3,"sm_listing_cold_ms":268.7,"sm_listing_warm_ms":269.4,"sm_nav_ms":307.9,"sm_palette_ms":0.3,"sm_rename_ms":384.3,"sm_render_ms":260.2,"sm_search_ms":67.7,"sm_split_ms":1368.2,"fails":0},"status":"discard","description":"Chunk the post-rename text refresh into TEXT_BLOCK pieces instead of one call for the whole requested range (a search window asks for thousands of rows and the heads tool caps a response at 2000, so the oversized call came back short, failed the sequence check and condemned the model to a rebuild). Fixes lg_search 3314 -> 1209, but lg_split 2597 -> 6624 and total 25564 -> 27571: doing it properly is SLOWER here than the accidental rebuild was.","timestamp":1786074100440,"segment":6,"confidence":3.8252964033077643,"asi":{"hypothesis":"one heads call for a whole search-sized window overflows the tool's 2000-row cap, so the refresh always failed its sequence check and forced a rebuild","hypothesis_confirmed":"yes -- chunking removed the spurious rebuild and lg_search fell 3314 -> 1209","but":"lg_split rose 2597 -> 6624. The accidental rebuild was CHEAPER overall than refreshing block by block, because this bench reads most of the segment after renaming and 450 block calls cost more than one linear rebuild.","UNEXPLAINED_AND_MUST_BE_RESOLVED":"work counters moved between the two runs: lg_decomp_lines 3436 -> 3233, lg_split_mapped_lines 2070 -> 1990, lg_search_hits 91783 -> 92733. Same database (targets/bash.i64 mtime unchanged, staged fresh per run), same fixed function set. Something about which path runs is changing what the app SEES. That has to be understood before any version of this is kept -- a perf change must not alter observable work.","leads":["phase_rename renames six functions and undoes them; a function whose original name was auto-generated (sub_X) comes back as a USER name sub_X. Check whether that changes the listing (a label row, or is_auto_name affecting annotate).","the search terms are 'mov' and 'call'; the temporary name _bench_<pid>_<k> contains a 'c', so leftover names would inflate a 'c'-prefixed search -- but the terms are full words, so check for residue directly.","lg_listing_rows is a streamed-progress reading, not a work counter -- ignore that one."],"work_preserved":".auto/wip-chunk.patch","next_action_hint":"resolve the counter drift first. Then, if the chunking is kept, try TEXT_BLOCK = 2000 (the tool's cap) so a wholesale refresh costs about what a rebuild costs while a viewport still needs one call."}} {"run":34,"commit":"3ca9e1e","metric":28651.3,"metrics":{"lg_boot_ms":720.6,"lg_decomp_ms":2427.4,"lg_graph_ms":1222.4,"lg_hex_ms":440.9,"lg_index_ms":72.6,"lg_listing_cold_ms":433.6,"lg_listing_warm_ms":465.9,"lg_nav_ms":6809.7,"lg_palette_ms":4.7,"lg_rename_ms":710.1,"lg_render_ms":228.7,"lg_search_ms":6891.2,"lg_split_ms":2259.2,"pure_graph_ms":214.5,"sm_boot_ms":457.7,"sm_decomp_ms":1303.6,"sm_graph_ms":700.2,"sm_hex_ms":445.4,"sm_index_ms":2.4,"sm_listing_cold_ms":271.4,"sm_listing_warm_ms":270.9,"sm_nav_ms":309.2,"sm_palette_ms":0.3,"sm_rename_ms":386.6,"sm_render_ms":265.8,"sm_search_ms":70.1,"sm_split_ms":1266.2,"fails":0},"status":"keep","description":"CORRECTNESS FIX, kept despite a worse metric. The un-chunked refresh was showing STALE NAMES on any wide read: one heads call for a search-sized window overflows the tool's 2000-row cap, the short response fails the sequence check, and the block is left with its old text. Refresh is now done a block at a time. Adds .auto/check_rename.py to the gate, which fails hard on the previous code and passes on this one.","timestamp":1786074769473,"segment":6,"confidence":4.974025132789222,"asi":{"the_bug_the_metric_was_rewarding":"/tmp/stalewindow.py renames a function, then reads the segment through window() the way the search body does. On the previous commit: 0 rows show the new name, the old one is still there, stale_structure=True. The 25564ms reading was FASTER because it was skipping the refresh -- the bench only failed to notice because phase_rename undoes its renames, so the stale text happened to be right again by the time anything compared it.","why_it_happened":"_ensure_text issued ONE heads call for the whole requested range. The tool caps a response at 2000 rows; a 4096-row search window came back short, page[:len(want)] != want, and the code took its 'the walk moved' branch -- marking the block fresh and leaving the old text.","fix":"refresh a TEXT_BLOCK (500 heads) at a time, looping. The sequence check then only ever fires for a real structural change.","cost":"total 25564 -> 28651. A wholesale re-read after a rename is ~10% dearer than a rebuild would be (6.6s vs 6.0s measured directly), and this bench does exactly that -- six renames then a split-view pass and a whole-segment search. The user-facing trade is: a rename is 566x faster (10.3ms vs 5660ms to get the listing back on bash), and a full-segment search immediately after one is ~10% slower.","counter_drift_resolved":"the 3233/1990/92733 counters in experiment #33 were NOT caused by the change -- both configurations reproduce 3436/2070/91783 twice each. That run was CPU-starved (the box is at load 1.6 and the 60s tool deadline can truncate a big decompile). Watch decomp_lines as a starvation signal.","gate_extended":".auto/check_rename.py: narrow read (painting), wide read (search body), and the whole model against a rebuild. Verified it FAILS on the previous commit with 4 problems and passes on this one.","principle":"the second time this session that the honest number is worse than the dishonest one. A benchmark rewards whatever it can see; the guard has to be a check that fails, not a number that improves."}} {"run":35,"commit":"6ec4bd8","metric":29392.6,"metrics":{"lg_boot_ms":711.9,"lg_decomp_ms":2406.4,"lg_graph_ms":1271.9,"lg_hex_ms":445.3,"lg_index_ms":71.9,"lg_listing_cold_ms":748.5,"lg_listing_warm_ms":403.8,"lg_nav_ms":6596.2,"lg_palette_ms":4.8,"lg_rename_ms":715.8,"lg_render_ms":219.3,"lg_search_ms":7055.2,"lg_split_ms":2629.8,"pure_graph_ms":212.8,"sm_boot_ms":445.6,"sm_decomp_ms":1281,"sm_graph_ms":775,"sm_hex_ms":442.3,"sm_index_ms":2.3,"sm_listing_cold_ms":265.6,"sm_listing_warm_ms":266.7,"sm_nav_ms":302.9,"sm_palette_ms":0.3,"sm_rename_ms":380.8,"sm_render_ms":255.1,"sm_search_ms":67,"sm_split_ms":1414.2,"fails":0},"status":"discard","description":"Documentation-only commit (playbook + ideas). Re-measured to confirm the post-fix state: 28651 -> 29393 is within the spread on this now-loaded box, and lg_search holds at ~7.0s, confirming that a whole-segment read after renames costs a whole-segment re-render.","timestamp":1786075083972,"segment":6,"confidence":7.108776152564333,"asi":{"state":"v7 baseline 33243 -> 29393 (-11.6%). rename 10055 -> 716 is the headline; the cost of re-rendering after a rename did not disappear, it moved to whoever reads the rows (lg_search 775 -> ~7000, because this bench reads the entire segment right after renaming). For a user reading a viewport the rename is 566x faster and nothing else changes.","why_there_is_no_more_free_win_here":"after a rename, the rows you read have to be re-rendered; re-rendering N heads costs what loading N heads costs. Refreshing only the rows that ACTUALLY changed would need xrefs_to(renamed_ea) to enumerate them, and a name can reach a row without a direct xref (a comment, a struct field in an operand) -- miss one and you are back to showing a stale name, which is the bug just fixed. Logged in .auto/ideas.md rather than attempted.","highest_yield_activity_this_session":"asking what the benchmark does NOT measure. Three of the five bench corrections found an invisible cost, and two of those (split view, rename) were among the biggest wins of the whole session.","next_action_hint":"keep probing uncovered features with the /tmp/featprobe.py shape: xrefs (x), the strings browser (\"), literal formats (o), make-code/data edits, history, traces, RPC. Domain-level probes already say xrefs/strings/structs/resolve are fast, so drive them through the UI instead."}} +{"run":36,"commit":"1e9f47b","metric":28842.1,"metrics":{"lg_boot_ms":712.2,"lg_decomp_ms":2366.9,"lg_graph_ms":907.8,"lg_hex_ms":447.2,"lg_index_ms":72.2,"lg_listing_cold_ms":443.7,"lg_listing_warm_ms":453.7,"lg_nav_ms":6610.2,"lg_palette_ms":4.8,"lg_rename_ms":735.3,"lg_render_ms":228.4,"lg_search_ms":7122.8,"lg_split_ms":2609.7,"pure_graph_ms":212.3,"sm_boot_ms":438.7,"sm_decomp_ms":1279.7,"sm_graph_ms":783.2,"sm_hex_ms":447.3,"sm_index_ms":2.5,"sm_listing_cold_ms":267.7,"sm_listing_warm_ms":263.1,"sm_nav_ms":309.7,"sm_palette_ms":0.3,"sm_rename_ms":383.9,"sm_render_ms":255,"sm_search_ms":66.3,"sm_split_ms":1417.6,"fails":0},"status":"discard","description":"Tried and reverted: throttling the background listing streamer's UI reports by time, and adding a token so only the newest streamer survives a re-prime. Both measured WORSE on a direct responsiveness probe (xrefs dialog while streaming: 1314ms baseline, 1436ms throttled, 2038ms with the token). Reverted; the finding is recorded in .auto/ideas.md. This run confirms the committed state at 28842.","timestamp":1786075786983,"segment":6,"confidence":8.431402690090582,"asi":{"real_finding_worth_keeping":"the app is several times slower while a big segment streams in the background: an xrefs dialog is 691ms during the ~7s stream and 105ms after it. Two confirmed mechanisms -- Textual's @work(exclusive=True) does NOT stop a thread worker that is already running, and navigating inside the same segment re-primes against the SAME model, so every jump leaves another streamer behind; and each streamer reports growth to the UI every four pages (thread hop + virtual_size change + full repaint).","what_failed":"a 10/s time throttle made it worse (237 reports vs 112) because the count is per streamer and there are several. Adding a _grow_token so only the newest streamer survives did NOT reduce the report count either -- so the retirement is not happening where it looks like it should, and I do not understand the mechanism well enough to ship a fix.","why_i_stopped":"the probe navigates repeatedly, which is itself what spawns the extra streamers, so it measures the thing it perturbs. A clean probe would drive UI work from a SINGLE navigation while one streamer runs. Recorded in .auto/ideas.md with the reproduction.","also_found":"a PRE-EXISTING crash: StringsPalette.on_mount calls query_one(OptionList) before compose's children are mounted (NoMatches). Reproduces 3/3 on bash AND 3/3 on the pre-autoresearch commit 2b0ae8d, so it is not from this work. ProjectPalette has the same shape.","xrefs_is_fine":"the xrefs path is not a decomp_map-class problem: xrefs_to is 38ms for 12 functions, item building 2.6ms, and the whole 'x'-to-dialog cycle is ~105ms once the listing has finished streaming. Most of that is two modal screen mounts.","state":"v7 baseline 33243 -> 28842 (-13.2%)."}} diff --git a/.auto/prompt.md b/.auto/prompt.md index a430bda..0f03092 100644 --- a/.auto/prompt.md +++ b/.auto/prompt.md @@ -187,35 +187,29 @@ v1 bench baseline `total_ms` ≈ 46 600 → 18 900 after thirteen experiments runs on a background thread and starves the UI thread through a cold auto-analysis (see v5 #4). -**Where the time is now (17 830 ms on the v5 bench)** +**Where the time is now (28 842 ms on the v7 bench)** -`lg_nav` 6 922 (39%) · decomp lg+sm 3 604 · graph lg+sm 1 728 · listing lg+sm -1 508 · boot lg+sm 1 156 · search lg+sm 927 · hex lg+sm 892 · render 472 · -pure_graph 214. +`lg_search` 7 123 · `lg_nav` 6 610 · decomp lg+sm 3 647 · split lg+sm 4 027 · +graph lg+sm 1 691 · boot lg+sm 1 151 · listing lg+sm 1 428 · rename lg+sm 1 119 · +hex lg+sm 895 · render 483 · pure_graph 212. -**Four of those are at a floor that is not ours to move:** +`lg_search` is large *because of where it sits in the session*: the bench renames +six functions and then searches the whole 228 k-row segment, so it pays to +re-render everything the rename staled. Before the rename fix that same cost was +paid up front, inside the renames (`lg_rename` was 10 055 ms). Re-rendering N +heads costs what loading N heads costs; the win was in not doing it for rows +nobody reads. + +**Five things are at a floor that is not ours to move:** - `nav` — `generate_disasm_line` is 5.9 µs of the ~16.5 µs/row the worker spends, and the walk is inherently linear. - `decomp` — the raw `decompile` tool is 1 711 ms cold for echo's twelve largest functions and 218 ms warm; pickling the result is 0.1 ms. It is Hex-Rays. -- `search` — what remains is the 459 ms haystack build, one `_line_plain` pass - over 228 k rows. +- `search` — after a rename, what you read has to be re-rendered. - `listing`/`hex`/`graph`/`render` — mostly Textual's own compositing, ~6 ms per full-screen frame. Our `render_line` is ~1.8 ms of a ~10 ms hex frame. - -`lg_nav` is a linear walk of the segment at its floor: ~16.5 µs/row in the -worker (of which `generate_disasm_line` is 5.9 µs and IDA's) plus ~7 µs/row on -the client. The only lever left there is *not walking* — costed in -`.auto/ideas.md`, and it only nets ~5% because search needs the text anyway. - -`decomp` is 1.37 s of Hex-Rays on the big target plus ~35 ms per F5 of Textual -(a loading-cover mount/unmount, two `@work` threads, `highlight_c`). The cover -cannot be deferred — a scenario asserts F5 raises it synchronously, and that -assertion guards a real past regression. - -Most other phases are now within ~2× of Textual's own per-frame compositing -cost, which is not ours to remove. +- `boot` — ~150 ms of it is the worker importing `idapro`. **Benchmark history.** The bench was corrected five times. Three of those found a cost that was *entirely invisible*, and two of those three turned out to be @@ -231,6 +225,12 @@ among the largest wins of the whole session. Every re-baseline is in | v6 | 33 502 | 19 835 | **split view was not covered at all** (48% of a session) | | v7 | 33 243 | 28 651 | **rename was not covered at all** (1.7 s each on bash) | +Headline user-facing numbers, measured directly rather than through the bench: +a cold jump to a far address on bash 28.3 s → 6.4 s; drawing a chunked +function's graph 3.0 s → 0.01 s (and its far blocks are no longer empty); +opening the split view 850 ms → 110 ms; getting the listing back after a rename +5.7 s → 10 ms. + **The most productive thing in this session was asking what the bench does not measure.** Features still uncovered: xrefs (`x`), the strings browser (`"`), the struct editor, literal formats (`o`), make-code/data edits, history, execution |