From b6646aa1c77d3244ec74cb525e7808c8dd8c153b Mon Sep 17 00:00:00 2001 From: user Date: Fri, 7 Aug 2026 08:17:07 +0200 Subject: 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. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Result: {"status":"keep","total_ms":25121.9,"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} --- .auto/ideas.md | 27 +++++++++++++++++---------- .auto/log.jsonl | 1 + idatui/domain.py | 36 ++++++++++++++++-------------------- server/patch_server.py | 24 ++++++++++++++---------- 4 files changed, 48 insertions(+), 40 deletions(-) diff --git a/.auto/ideas.md b/.auto/ideas.md index e77a1fa..81cef45 100644 --- a/.auto/ideas.md +++ b/.auto/ideas.md @@ -162,13 +162,20 @@ hangs the run (no output, 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 rather than at the edit: after -`bump_items` deletes the segment model, a `_prime`/`_grow` worker still in -flight can re-register a fresh one and hold its `_load_lock` — and this is the -same area as the unexplained streaming-responsiveness item above (a navigation -leaves extra `_grow` threads behind, and `@work(exclusive=True)` does not stop a -thread worker that is already running). **Understand that first**; a bench phase -built on top of it would be flaky. - -Until then the win is carried by `/tmp/itemedit.py` (direct measurement) and -`.auto/check_edit.py` (correctness, in the gate). +**That explanation was wrong** — corrected by a stack dump +(`faulthandler.dump_traceback_later`, `/tmp/hangdiag2.py`). At the moment of the +hang there are **no idatui threads at all**: the main thread is idle in +`selectors.select()` and the only others are idle asyncio executor threads. The +app is stuck *before* `app.run_test()` even returns — nothing to do with +`bump_items`, `_prime`/`_grow`, or `_load_lock`. + +It is **pilot start-up flakiness**, and it is partly environmental: several +orphaned `idatui/worker.py` processes had accumulated from runs killed by +`timeout`, and clearing them (`pkill -f idatui/worker.py`) made the next run +boot fine — but it recurred afterwards, so that is not the whole story. Not the +kitty-graphics query either (`IDATUI_KITTY=0` still hangs). + +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). diff --git a/.auto/log.jsonl b/.auto/log.jsonl index fea1e26..1315464 100644 --- a/.auto/log.jsonl +++ b/.auto/log.jsonl @@ -46,3 +46,4 @@ {"run":39,"commit":"df88ece","metric":28376.5,"metrics":{"lg_boot_ms":762.1,"lg_decomp_ms":2374.3,"lg_graph_ms":938.1,"lg_hex_ms":452.4,"lg_index_ms":70.2,"lg_listing_cold_ms":419.6,"lg_listing_warm_ms":464.1,"lg_nav_ms":6941.9,"lg_palette_ms":5,"lg_rename_ms":1973.2,"lg_render_ms":221.9,"lg_search_ms":4117.3,"lg_split_ms":2333.3,"pure_graph_ms":214.6,"sm_boot_ms":453.7,"sm_decomp_ms":1270.5,"sm_graph_ms":726.9,"sm_hex_ms":440.6,"sm_index_ms":2.4,"sm_listing_cold_ms":283,"sm_listing_warm_ms":284.3,"sm_nav_ms":310.4,"sm_palette_ms":0.3,"sm_rename_ms":1575.9,"sm_render_ms":257.6,"sm_search_ms":59.6,"sm_split_ms":1423.7,"fails":0},"status":"checks_failed","description":"Digest mode for `heads`: the worker answers \"does this page still render exactly as it did?\" for the cost of the render alone, so a post-rename refresh skips shipping, unpickling and rebuilding pages that did not change. lg_search 5628 -> 4117 — but it BREAKS 'O' cycles back, and it made rename 2-4x slower. Both causes understood.","timestamp":1786077531326,"segment":6,"confidence":10.35869418588966,"asi":{"hypothesis_first_tested_empirically":"before building anything I checked the parked xrefs-driven idea: /tmp/whatchanges.py rebuilds the whole segment before and after a rename and diffs every row. On echo, all 19 changed rows over 4 renames were covered by (function extent + xrefs_to). On ls_ttl, 53 of 54 were -- the one that was not is 'lea rcx, unk_1D7A0' -> 'byte_1D7A0', which the RENAME DID NOT CAUSE: IDA's own analysis defined that byte. An address-predicted invalidation would leave that row stale for good, so the idea is now measured-and-rejected rather than assumed-risky.","what_i_built_instead":"an exact check: `heads(..., digest=True)` builds the rows as usual but returns only hash+count instead of the rows. The client stores the digest each page came back with and asks 'still the same?' before re-fetching. Uses the interpreter's own hash deliberately -- it never has to mean anything outside the worker process, the client is only a courier.","measured_win":"post-rename whole-segment re-read 5115ms -> 3833ms (-25%); lg_search 5628 -> 4117","BUG_1_correctness":"the stored digest describes the page AS LOADED, not as the client currently holds it. After a full refetch the client's rows change but _page_digest is not updated -- so when a literal format cycles hex -> dec -> ... -> hex, the worker's digest matches the ORIGINAL stored one, the page is declared unchanged, and the row keeps the intermediate decimal text. That is exactly the failure: opfmt_listing ''O' cycles back' got 'sub rsp, 184' wanting 'sub rsp, 0B8h'.","BUG_2_performance":"_ensure_text_from tests page freshness with all(_head_gen[k] == gen for k in the page), and get() calls _ensure_text per ROW -- so every row scanned a whole page's gen array. rename went 380 -> 1576ms (sm) and 730 -> 1973ms (lg).","fix_for_both":"refresh at PAGE granularity end to end instead of the snapped TEXT_BLOCK: a page is exactly what the tool produced from (addr, count=PAGE), so refetching with the same parameters reproduces the same sequence with no snapping, the stored digest can be updated whenever the page's rows are replaced, and every head in a page shares one gen value so freshness is a single probe rather than a scan.","work_preserved":".auto/wip-digest.patch","gate_worked":"check_rename and check_search both passed -- neither exercises a format cycle. The scenario suite caught it. That is the third time a cache-shaped change failed in a way only one specific test could see."}} {"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."}} diff --git a/idatui/domain.py b/idatui/domain.py index 2cfd9d9..aedade9 100644 --- a/idatui/domain.py +++ b/idatui/domain.py @@ -1011,30 +1011,26 @@ class ListingModel: want_digest = self._page_digest[p] want_rows = self._page_rows[p] want = [(h.ea, h.kind) for h in self._heads[lo:hi]] - # Ask whether the page still renders as the client holds it. The worker - # builds the rows either way (there is no knowing a line is unchanged - # without rendering it), but skipping the pickling, the transfer, the - # unpickling and the Head rebuild is about 40% of what a page costs -- - # and after a rename almost every page is unchanged. - if want_digest is not None: - try: - probe = self._prog.client.call( - "heads", addr=hex(addr), count=self.PAGE, annotate=True, - digest=True) - except Exception: # noqa: BLE001 -- an older worker has no digest - probe = None - if (isinstance(probe, dict) and probe.get("digest") == want_digest - and probe.get("count") == want_rows): - with self._lock: - if self._text_gen == gen and len(self._heads) >= hi: - for k in range(lo, hi): - self._head_gen[k] = gen - return p + 1 + # Tell the worker what we already hold. It builds the rows either way + # (there is no knowing a line is unchanged without rendering it), but if + # they still hash to the same value it keeps them: the pickling, the + # transfer, the unpickling and the Head rebuild are about 40% of what a + # page costs, and after a rename almost every page is unchanged. Sending + # the expectation rather than asking first means a page that HAS changed + # still costs one round trip. try: payload = self._prog.client.call( - "heads", addr=hex(addr), count=self.PAGE, annotate=True) + "heads", addr=hex(addr), count=self.PAGE, annotate=True, + expect="" if want_digest is None else str(want_digest)) except Exception: # noqa: BLE001 -- keep the old text rather than blank return p + 1 + if (isinstance(payload, dict) and "heads" not in payload + and payload.get("count") == want_rows): + with self._lock: + if self._text_gen == gen and len(self._heads) >= hi: + for k in range(lo, hi): + self._head_gen[k] = gen + return p + 1 rows = payload.get("heads", []) if isinstance(payload, dict) else [] page = self._build_page(rows) with self._lock: diff --git a/server/patch_server.py b/server/patch_server.py index a991158..e860676 100644 --- a/server/patch_server.py +++ b/server/patch_server.py @@ -700,7 +700,7 @@ def heads( end: Annotated[str, "Optional exclusive end address; default = segment end"] = "", back: Annotated[bool, "Walk backwards: return the count heads ENDING just before addr, in forward order"] = False, annotate: Annotated[bool, "Emit IDA-style function boundary banner rows (kind sep/funchdr)"] = False, - digest: Annotated[bool, "Return only a digest+count of the rows, not the rows themselves"] = False, + expect: Annotated[str, "Digest a caller already holds: the rows are omitted when they still hash to it"] = "", ) -> dict: """Walk item heads from ``addr`` as a flat listing: every head is rendered (code OR data OR undefined) via generate_disasm_line and stepped with @@ -824,15 +824,19 @@ def heads( rows.extend(_rows_for(ea, f)) # a struct head expands into member rows ea = _advance(ea, f) cursor = {"next": hex(ea)} if more else {"done": True} - out = {"addr": str(addr), "cursor": cursor, - "digest": _idatui_rows_digest(rows), "count": len(rows)} - # ``digest`` mode answers "is this page still exactly what you have?" without - # shipping it. The rows are built either way -- generate_disasm_line is the - # floor and there is no way to know a line is unchanged without rendering it - # -- but pickling several hundred rows with their colour spans, unpickling - # them and rebuilding Heads is about 40% of what a page costs, and after a - # rename almost every page comes back identical. - if not digest: + dig = _idatui_rows_digest(rows) + out = {"addr": str(addr), "cursor": cursor, "digest": dig, "count": len(rows)} + # ``expect`` says "I already hold a page that hashed to this". The rows are + # built either way -- generate_disasm_line is the floor and there is no way + # to know a line is unchanged without rendering it -- but pickling several + # hundred rows with their colour spans, unpickling them and rebuilding Heads + # is about 40% of what a page costs, and after a rename almost every page + # comes back identical. + # + # It carries the expected value rather than being a yes/no "digest mode" so + # that a page which HAS changed still costs one round trip: asking first and + # fetching afterwards made every changed page two. + if not (expect and str(dig) == expect): out["heads"] = rows return out -- cgit v1.3.1-sl0p