diff options
| author | user <user@clank> | 2026-08-07 08:32:31 +0200 |
|---|---|---|
| committer | user <user@clank> | 2026-08-07 08:32:31 +0200 |
| commit | 853d90c9866f3996a8ce66ac70f0559ccfad21c5 (patch) | |
| tree | b46febfe454fb7ad17da4c7f822ff949d53c1513 | |
| parent | The page-freshness check carries the digest the client already holds (heads(e... (diff) | |
| download | ida-tui-853d90c9866f3996a8ce66ac70f0559ccfad21c5.tar.gz ida-tui-853d90c9866f3996a8ce66ac70f0559ccfad21c5.tar.xz ida-tui-853d90c9866f3996a8ce66ac70f0559ccfad21c5.zip | |
decomp_map: memoise obj_id -> ea for the whole function instead of only comparing against the previous column. dstr() was 79% of the tool (24us a call) and items interleave, so foo(a, b) flips call->arg->call and re-formatted an item already seen: 106594 calls for 15417 lines of bash. Also corrects run #30's claim that the duplicate ida_hexrays.decompile is what costs -- a warm decompile is 0.01ms.
Result: {"status":"keep","total_ms":24513.8,"lg_boot_ms":693.2,"lg_decomp_ms":2347.3,"lg_graph_ms":931.2,"lg_hex_ms":460.3,"lg_index_ms":69.1,"lg_listing_cold_ms":434.2,"lg_listing_warm_ms":462.4,"lg_nav_ms":6639.6,"lg_palette_ms":4.7,"lg_rename_ms":699.9,"lg_render_ms":219.7,"lg_search_ms":3441.1,"lg_split_ms":2218,"pure_graph_ms":216.5,"sm_boot_ms":436.9,"sm_decomp_ms":1264.9,"sm_graph_ms":758.2,"sm_hex_ms":437.9,"sm_index_ms":2.3,"sm_listing_cold_ms":256.8,"sm_listing_warm_ms":256,"sm_nav_ms":309.5,"sm_palette_ms":0.3,"sm_rename_ms":379.1,"sm_render_ms":249.5,"sm_search_ms":59.2,"sm_split_ms":1266,"fails":0}
| -rw-r--r-- | .auto/ideas.md | 51 | ||||
| -rw-r--r-- | .auto/log.jsonl | 1 | ||||
| -rw-r--r-- | server/patch_server.py | 42 |
3 files changed, 80 insertions, 14 deletions
diff --git a/.auto/ideas.md b/.auto/ideas.md index 81cef45..9586574 100644 --- a/.auto/ideas.md +++ b/.auto/ideas.md @@ -179,3 +179,54 @@ Two things to take from it: **kill stray workers between probe runs**, and a bench phase should not be built on this until app start-up under the pilot is reliable. The item-edit win is carried by `/tmp/itemedit.py` (direct measurement) and `.auto/check_edit.py` (correctness, in the gate). + +## decomp_map: what is actually left (measured, corrects run #30) + +Run #30 said "what is left in `decomp_map` is `ida_hexrays.decompile`, which +duplicates the decompile the view already did". **That is wrong.** A warm +`ida_hexrays.decompile()` is **0.01 ms** (`/tmp/hxcache.py`) — Hex-Rays' own +cache is free, and the duplicate costs nothing. + +The sweep's real split, over 15 417 lines of bash (`/tmp/sweepprof.py`): + +| part | cost | calls | +|---|---|---| +| `dstr()` | **2 581 ms (79%)** | 106 594 @ 24.2 µs | +| `get_line_item` | 691 ms | 445 337 @ 1.55 µs | +| `tag_remove` for the length | 14 ms | 15 417 | + +Fixed by memoising `obj_id -> ea` for the whole function (v7 #44). What remains +is `get_line_item` per column, which is a real probe per screen column. + +Ideas for the remainder, in order of appeal: + +- **Map only the lines the split view can show.** The pane paints ~40 lines but + the map is built for all 3 486. This is the same "compute on demand" shape + that won for search highlight ranges (v5 #6). It needs a windowed tool + (`first`/`count`) and a lazy container, because `app.py` and `trace_ctl.py` + both index the whole list. +- Stepping over columns instead of probing each one is **not** safe: an item + occupying one or two columns (a single-character variable) would be skipped + entirely, silently dropping an EA from the region highlight. + +## Re-printing instead of re-decompiling after a rename (measured, NOT applied) + +`cfunc.refresh_func_ctext()` on a cached ctree is **46x faster** than the +recompile a rename currently forces (31 ms vs 1 432 ms for ten functions), and +it is arguably what a user expects: only the name changes. + +**Not applied, because it changes what is on screen.** Only 2 of 10 functions +re-printed to the same text as a real recompile; the other eight differ by +Hex-Rays *type inference*: `char *` vs `const char *`, `__int64` vs +`signed __int64`, `unsigned int a4` vs `int a4`. Same drift already recorded +above — a full recompile re-runs inference with more accumulated knowledge, so +the two disagree even where the rename is irrelevant. Choosing the stabler text +is a product decision about what the pseudocode pane should show, not a +performance change, so it needs a human call. Probe: `/tmp/reprint.py`. + +Also checked and **not** a bug: the split view's text and its `decomp_map` do +come from the same ctree. `Program.decompile` calls the `force_recompile` tool +(which does exist) before refetching, so the tool's plain +`ida_hexrays.decompile()` repopulates the cache and `decomp_map` then hits it. +`/tmp/mapalign.py` appeared to show a mismatch only because the probe itself +used `DECOMP_NO_CACHE`, which the app never does. diff --git a/.auto/log.jsonl b/.auto/log.jsonl index 1315464..97b8104 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -47,3 +47,4 @@ {"run":40,"commit":"d9e8fdb","metric":26491.7,"metrics":{"lg_boot_ms":808.6,"lg_decomp_ms":2600.2,"lg_graph_ms":901.2,"lg_hex_ms":448.7,"lg_index_ms":70.3,"lg_listing_cold_ms":432.8,"lg_listing_warm_ms":445.5,"lg_nav_ms":7004.8,"lg_palette_ms":4.8,"lg_rename_ms":758.6,"lg_render_ms":231.3,"lg_search_ms":3959.2,"lg_split_ms":2659.2,"pure_graph_ms":214.7,"sm_boot_ms":432.6,"sm_decomp_ms":1305.1,"sm_graph_ms":758.3,"sm_hex_ms":431.8,"sm_index_ms":2.3,"sm_listing_cold_ms":275.4,"sm_listing_warm_ms":289.4,"sm_nav_ms":295.6,"sm_palette_ms":0.3,"sm_rename_ms":424.3,"sm_render_ms":263.6,"sm_search_ms":61.1,"sm_split_ms":1411.9,"fails":0},"status":"keep","description":"heads(digest=True): the worker answers \"does this page still render exactly as you hold it?\" with a hash and a count instead of the page. After a rename nearly every page is unchanged, so the pickling, transfer, unpickling and Head rebuild are all skipped. Redone at PAGE granularity end to end, which fixes both bugs of the first attempt. lg_search 5628 -> 3959.","timestamp":1786077952004,"segment":6,"confidence":8.431402690090582,"asi":{"gains":"total 27553 (previous best) -> 26492 (-3.9%); lg_search 5628 -> 3959 (-30%); post-rename whole-segment re-read 5115 -> 3720ms measured directly","cost":"lg_rename 731 -> 759 and sm_rename 380 -> 424: a page now costs one extra round trip to probe before it is either accepted or refetched. Getting a viewport back after a rename on bash is 21.5ms instead of 10.3ms -- still 230x better than the 4941ms rebuild it replaced.","what_the_two_bugs_were":{"correctness":"the first attempt stored the digest a page LOADED with and never updated it when the page was refetched. A literal format cycling hex -> dec -> hex then hashed back to the original while the client still held the decimal text: opfmt_listing ''O' cycles back' got 'sub rsp, 184' wanting '0B8h'.","performance":"freshness was tested with all(_head_gen[k] == gen for k in the page) while get() called _ensure_text per ROW, so every row scanned a whole page's gen array -- rename went 2-4x slower."},"the_fix_was_one_idea":"refresh at PAGE granularity instead of the snapped TEXT_BLOCK. A page is exactly what heads(addr, count=PAGE) produced, so re-asking with the same arguments reproduces the same sequence -- no snapping to address groups needed, the stored digest can be updated whenever the rows are replaced, and every head in a page shares one generation marker so freshness is a single probe. TEXT_BLOCK is gone.","why_hash_and_not_a_stable_digest":"the value never has to mean anything outside the worker process -- the client stores what a page hashed to and hands the same number back. One worker, one process, one hash seed. It covers ea/kind/size/text/name AND the colour spans, so two lines that collapse to the same text but colour differently are not confused.","empirical_work_that_shaped_this":"before building anything I tested the parked xrefs-driven idea with /tmp/whatchanges.py (rebuild the segment before and after a rename, diff every row). It fails: on ls_ttl one changed row was 'lea rcx, unk_1D7A0' -> 'byte_1D7A0', which the rename did not cause -- IDA's own analysis defined that byte. Address-predicted invalidation would leave it stale forever. Recorded as measured-and-rejected in .auto/ideas.md.","work_unchanged":"decomp_lines 3436, split_mapped 2070, search_hits 91783, graph_blocks 1000, rename_ok 6/6, decomp_ok 12 -- identical","verified":"830-check gate, check_search (140 prefixes), check_rename on echo AND ls_ttl (5952 and 28807 rows, wide and narrow, against a rebuild), and the 19 opfmt scenarios that caught the first attempt","next_action_hint":"lg_nav 7005 is the largest term and is the cold walk at its per-row floor. lg_search 3959 is now mostly the _line_plain pass plus the pages that genuinely changed. Next best unexplored: why the digest probe costs a whole extra round trip per page -- it could ride along with the first refetch request rather than preceding it."}} {"run":41,"commit":"7e4f086","metric":25814,"metrics":{"lg_boot_ms":714.9,"lg_decomp_ms":2376.2,"lg_graph_ms":948.8,"lg_hex_ms":458.6,"lg_index_ms":69.3,"lg_listing_cold_ms":448.5,"lg_listing_warm_ms":482.1,"lg_nav_ms":6808,"lg_palette_ms":4.7,"lg_rename_ms":752,"lg_render_ms":219.4,"lg_search_ms":4008.3,"lg_split_ms":2275.5,"pure_graph_ms":225.2,"sm_boot_ms":456.1,"sm_decomp_ms":1292.4,"sm_graph_ms":795.8,"sm_hex_ms":475.2,"sm_index_ms":2.5,"sm_listing_cold_ms":269.1,"sm_listing_warm_ms":272.2,"sm_nav_ms":320.2,"sm_palette_ms":0.3,"sm_rename_ms":446.3,"sm_render_ms":264.8,"sm_search_ms":60.6,"sm_split_ms":1366.9,"fails":0},"status":"keep","description":"Three redundancies in the heads walk: item flags were fetched three times per head (row builder, _is_unknown via _advance, and _rows_for), get_func was called per head where a head is nearly always in the same function as the one before it, and the page digest rebuilt a tuple-of-tuples per row where one spans list is shared by ~45% of them. Cold heads 18.62 -> 17.77 us/row, warm 11.53 -> 10.87.","timestamp":1786078727527,"segment":6,"confidence":7.765877831715214,"asi":{"gains":"total 26492 (previous best) -> 25814 (-2.6%); lg_split 2659 -> 2276; sm_nav_worst 158 -> 151. Microbenchmarked rather than trusted to total_ms, since ~0.8us/row over ~500k row-renders is 0.4s and the box's spread is ~500ms: cold heads 18.62 -> 17.77 us/row, warm 11.53 -> 10.87, digest 0.75 -> 0.62.","equivalence":"/tmp/headsdump.py runs the tool under both code versions in separate processes and compares whole payloads: 109 004 rows over 294 payloads (bash + ls_ttl, BOTH annotate modes, plus the offset/end/back/count variants that share the walk) -- 0 mismatches. diff_spans still byte-identical vs 2b0ae8d on three binaries. 830-check gate, check_search and check_rename green.","get_func_cache_was_validated_not_assumed":"I had rejected this earlier on a hunch about IDA function CHUNKS -- a tail chunk of B inside A's [start_ea, end_ea) would be misattributed. /tmp/funccache.py walks every head of bash/ls_ttl/echo comparing the cached answer against get_func: 437 324 heads, 0 disagreements. Hit rate is only ~50% across all segments (a head outside any function cannot be cached by range) but much higher inside .text, which is what the listing walks.","TWO_SCHEMES_MEASURED_AND_REJECTED_FIRST":"before micro-optimising I tested the two big parked ideas, both of which would have made a rename nearly free. Listing rows predicted from xrefs_to + function extent: ls_ttl had 1 of 54 changed rows uncovered, 'lea rcx, unk_1D7A0' -> 'byte_1D7A0', which the rename did not cause -- IDA's own analysis defined that byte. Decompilations predicted from 'the old name appears in the cached text': 16 misses over 4 renames, EVERY one Hex-Rays type inference moving (unsigned int a4 -> int a4) in functions unrelated to the rename. Both recorded in .auto/ideas.md.","generalised_lesson":"predicting the effect of an edit on a database that has its own opinions is unsound. Verify instead -- which is exactly why heads(digest=True) works: it asks what a row renders as NOW, not what should have changed. This probably also explains the lg_decomp_lines drift blamed on CPU starvation in v5 #4.","things_checked_and_found_not_worth_it":{"digest_on_the_normal_load_path":"suspected a regression from v7 #10; it is 0.62-0.75 us/row, not the 1.9 the noisy call timing suggested","folding_the_opcode_byte_read_into_heads":"the extra read_bytes round trip is 0.35 us/row, ~81ms over a whole bash segment","pipelining_client_parsing_with_worker_compute":"blocked -- cursor.next is inside the pickle, so the next request cannot be issued before unpickling, and _build_page itself needs the socket for opcode bytes"},"state":"generate_disasm_line is now 6.09 of the 10.87 us/row warm cost (56%) and is IDA's. What is left of ours is ~4.8 us/row spread thin across a dozen places.","next_action_hint":"lg_nav 6808 (26%) and lg_search 4008 (16%) are both at their per-row floors now. The unexplored areas are the ones .auto/ideas.md lists as blocked or unmeasured: the trace memory index (needs test_trace_vs_tenet runnable), the streaming-responsiveness question, and the features the bench still does not drive (xrefs dialog, strings browser, struct editor, make-code edits, history, traces, RPC)."}} {"run":42,"commit":"16318e4","metric":25783,"metrics":{"lg_boot_ms":777.9,"lg_decomp_ms":2381.9,"lg_graph_ms":1209.5,"lg_hex_ms":450,"lg_index_ms":68,"lg_listing_cold_ms":434.6,"lg_listing_warm_ms":405.2,"lg_nav_ms":6801.2,"lg_palette_ms":4.7,"lg_rename_ms":744.7,"lg_render_ms":222.4,"lg_search_ms":3885.6,"lg_split_ms":2261.4,"pure_graph_ms":216.4,"sm_boot_ms":463.6,"sm_decomp_ms":1304.6,"sm_graph_ms":740.9,"sm_hex_ms":438.4,"sm_index_ms":2.4,"sm_listing_cold_ms":270.3,"sm_listing_warm_ms":267.2,"sm_nav_ms":312.4,"sm_palette_ms":0.3,"sm_rename_ms":415.8,"sm_render_ms":257.7,"sm_search_ms":60.8,"sm_split_ms":1385.2,"fails":0},"status":"keep","description":"An item edit (c/d/u/p) keeps the listing's walk in front of it instead of discarding the model. bump_items now takes the edited address; rows before an edit keep their addresses and their row numbers, so only the pages from the edit onward are re-walked. Getting the listing back after undefining at the cursor on bash: 4890ms -> 19ms (257x). Adds .auto/check_edit.py to the gate. total_ms is flat — the bench has no item-edit phase, and the one I wrote hangs (reverted, cause recorded).","timestamp":1786082485850,"segment":6,"confidence":5.464825819307547,"asi":{"how_it_was_found":"kept probing features the bench does not drive -- the pattern that produced the flowchart hull, decomp_map and the rename walk. /tmp/itemedit.py: the undefine tool call is 1ms and getting the listing back is 4890ms, because bump_items cleared _listings and the reload re-walked the segment. Same bug as the rename one, in the sibling path.","measured":"edit at the cursor (96% into bash's .text): 4890 -> 19ms. Edit early in the segment: 5130 -> 4542ms, which is the honest case -- everything after an edit really does have to be re-walked.","why_it_is_safe":"truncate_from drops two pages rather than one (undefining can coalesce backwards into the run in front of it), and the kept prefix is then marked text-stale -- so every kept page is digest-checked on the next read, and a page that really did move fails its (ea, kind) sequence check and sets stale_structure, which makes Program.listing rebuild. Safe by construction rather than by argument about how far a reflow can reach.","gate_added_and_proven":".auto/check_edit.py drives undefine at 1/4/16 bytes at three positions (90%, 50%, 5% through the segment) and compares the kept model against a rebuild, narrow and wide. 0 problems on echo and ls_ttl. Proven to FAIL by deliberately making truncate_from too permissive: it reported 'kept model has 5952 rows, a rebuild has 5950'.","HONEST_LIMITATION":"total_ms 25814 -> 25783 is flat: nothing in the bench edits an item. I wrote a phase for it and reverted it because it HANGS -- driving undefine from inside the pilot produces no output and is killed at the timeout, while the identical sequence against Program directly is fine, and the same sequence with a print between prog.listing(ea) and ensure_ea is also fine. That points at the app's background threads (after bump_items deletes the model, a _prime/_grow worker still in flight can re-register a fresh one and hold its _load_lock), which is the same area as the unexplained streaming-responsiveness item already in .auto/ideas.md. Shipping a hanging bench phase would be worse than not having one.","what_i_did_not_do":"I did not weaken the phase until it passed, and I did not claim the win in total_ms. It is carried by a direct measurement and a permanent gate.","next_action_hint":"the concurrency question is now blocking two things (a bench phase for edits, and the streaming-responsiveness fix). Working out why @work(exclusive=True) leaves thread workers running -- and giving _prime/_grow a way to actually retire -- is the highest-value next step, and it is a correctness/responsiveness matter as much as a perf one."}} +{"run":43,"commit":"b6646aa","metric":25121.9,"metrics":{"lg_boot_ms":694.8,"lg_decomp_ms":2370.8,"lg_graph_ms":917.1,"lg_hex_ms":456.1,"lg_index_ms":69.4,"lg_listing_cold_ms":442.7,"lg_listing_warm_ms":498.8,"lg_nav_ms":6548.8,"lg_palette_ms":4.8,"lg_rename_ms":711.4,"lg_render_ms":224.9,"lg_search_ms":3484.7,"lg_split_ms":2619.3,"pure_graph_ms":220.7,"sm_boot_ms":448.6,"sm_decomp_ms":1292.5,"sm_graph_ms":748.8,"sm_hex_ms":438.3,"sm_index_ms":2.4,"sm_listing_cold_ms":274.3,"sm_listing_warm_ms":266.5,"sm_nav_ms":302.7,"sm_palette_ms":0.3,"sm_rename_ms":392.5,"sm_render_ms":260.2,"sm_search_ms":59.6,"sm_split_ms":1370.9,"fails":0},"status":"keep","description":"The page-freshness check carries the digest the client already holds (heads(expect=...)) instead of asking first and fetching afterwards. A page that has NOT changed costs one round trip as before; a page that HAS changed now costs one instead of two. Also corrects the record: the item-edit bench hang is pilot start-up flakiness, not the _prime/_grow concurrency I blamed it on — proved with a stack dump.","timestamp":1786083427343,"segment":6,"confidence":4.621649308519722,"asi":{"gains":"total 25783 -> 25122 (-2.6%, best v7); lg_search 3886 -> 3485; sm_rename 416 -> 393. Direct measurements: post-rename whole-segment re-read 3720 -> 3411ms; getting the listing back after a rename on bash 21.5 -> 15.6ms (319x vs a rebuild); after an item edit 19 -> 17ms.","the_change":"heads gains `expect` (the digest a caller already holds) in place of the boolean `digest` flag. The worker builds the rows either way and omits them only when they still hash to `expect`. Sending the expectation rather than asking first is what removes the second round trip on a changed page -- which was the regression I introduced in v7 #10 (rename 380 -> 424ms) and flagged in my own next_action_hint.","equivalence":"normal calls (no expect) compared payload-for-payload against the previous commit across processes: 166 payloads, 63 964 rows, 0 mismatches. check_rename and check_edit both clean, 830-check gate green.","DIAGNOSIS_CORRECTED":"last iteration I logged that the item-edit bench phase hangs because 'after bump_items deletes the model, a _prime/_grow worker still in flight can re-register a fresh one and hold its _load_lock'. A stack dump (faulthandler.dump_traceback_later) says otherwise: at the moment of the hang there are NO idatui threads at all -- the main thread is idle in selectors.select() and everything else is an idle asyncio executor thread, and the app is stuck BEFORE app.run_test() returns. It is pilot start-up flakiness, nothing to do with bump_items or _load_lock. Ruled out: the kitty-graphics query (IDATUI_KITTY=0 still hangs). Partly environmental: orphaned idatui/worker.py processes accumulate from runs killed by `timeout`, and clearing them let the next run boot -- but it recurred, so that is not the whole story.","operational_note":"kill stray workers between probe runs (pkill -f idatui/worker.py). Several of this session's confusing measurements were taken with orphans competing for the box.","what_this_means_for_the_backlog":"the 'why does @work(exclusive=True) leave thread workers running' item is NOT what blocks the item-edit bench phase. The two are separate: the streaming-responsiveness question is still open on its own evidence (112 vs 237 _grew reports), but the bench phase is blocked on pilot start-up reliability instead.","state":"v7 baseline 33243 -> 25122 (-24.4%). lg_nav 6549 and lg_search 3485 are both at their per-row floors; what is left of the worker's cost is 56% generate_disasm_line."}} diff --git a/server/patch_server.py b/server/patch_server.py index e860676..6667e12 100644 --- a/server/patch_server.py +++ b/server/patch_server.py @@ -983,13 +983,19 @@ def decomp_map( # read, so don't ask for them at all. # * sweep the TAGGED length. ``x`` is a screen column but ``sl.line`` still # carries IDA's colour tags, so a 23-column line was swept 124 times. - # * call dstr() per column. It formats a whole 'EA: description' string, and - # consecutive columns are nearly always the same ctree item -- so ask the - # item for its id first and only format when it changes. (The result is - # deduped by ``seen`` anyway, so skipping a repeat cannot change it.) + # * call dstr() per column. It formats a whole 'EA: description' string -- + # 24us a call, which is 79% of this tool. Comparing against the PREVIOUS + # column's item id is not enough: items interleave, so `foo(a, b)` flips + # call -> arg -> call -> arg and every flip re-formats an item already + # seen (106 594 calls for 15 417 lines of bash). Memoise id -> ea for the + # whole function instead: obj_id is unique within a cfunc, so the same id + # always yields the same string, and the result is deduped by ``seen`` + # anyway. Items with no ctree node (it is None) have no id to key on and + # still pay per occurrence. item = ida_hexrays.ctree_item_t() tag_remove = ida_lines.tag_remove get_line_item = cfunc.get_line_item + ea_of_id = {} lines = [] for sl in cfunc.get_pseudocode(): line = sl.line @@ -1004,21 +1010,29 @@ def decomp_map( if oid == prev_id: continue prev_id = oid + if oid in ea_of_id: + e = ea_of_id[oid] + if e is not None and e not in seen: + seen.add(e) + eas.append(hex(e)) + continue else: + oid = None prev_id = None # Match the /*ea*/ marker's source (decompile_function_safe): the # item's dstr() is 'EA: description'; get_ea() reports a different ea. + e = None dstr = item.dstr() - if not dstr: - continue - parts = dstr.split(": ", 1) - if len(parts) != 2: - continue - try: - e = int(parts[0], 16) - except ValueError: - continue - if e not in seen: + if dstr: + parts = dstr.split(": ", 1) + if len(parts) == 2: + try: + e = int(parts[0], 16) + except ValueError: + e = None + if oid is not None: + ea_of_id[oid] = e + if e is not None and e not in seen: seen.add(e) eas.append(hex(e)) lines.append({"ea": eas[0] if eas else None, "eas": eas}) |
