diff options
| -rw-r--r-- | .fastfeedback/SPEED.md | 98 |
1 files changed, 77 insertions, 21 deletions
diff --git a/.fastfeedback/SPEED.md b/.fastfeedback/SPEED.md index e402ea1..996aefe 100644 --- a/.fastfeedback/SPEED.md +++ b/.fastfeedback/SPEED.md @@ -31,9 +31,16 @@ python3 tests/run.py graph -x # one suite by substring, fail-fa **Narrow test — DEFAULT RUNG.** The pilot suite takes `--only <substr,...>`: ```bash -~/ida-venv/bin/python tests/test_scenarios.py /tmp/scratch_bin --only rename # ~10s +~/ida-venv/bin/python tests/test_scenarios.py /tmp/scratch_bin --only rename # ~2s ~/ida-venv/bin/python tests/test_scenarios.py --list # scenario names +~/ida-venv/bin/python tests/test_scenarios.py targets/echo --profile # where the time went ``` + +**`--profile` is how you find the next 20 seconds.** It reports, per scenario, +seconds spent settling / in `wait()` / in keystrokes, and — the important one — +any wait that **EXPIRED**, with its line number. An expired wait costs its whole +timeout *and* means the check after it passed vacuously. Do not optimise this +suite by guessing; run `--profile` and fix the top line. `--only` matches substrings, so `--only listing` runs listing_view + listing_name_addr + listing_make_string + listing_struct_expand. Name the scenario exactly to stay narrow. @@ -92,6 +99,43 @@ run. Do not `kill -9` it — a hard-killed IDA wedges its database. --- +## Simulated keypresses cost 85ms each unless you patch Textual + +The single biggest cost in this repo's UI suites was **Textual's own key path**, +not our code. `Pilot.press` → `App._press_keys` calls `wait_for_idle` *twice per +key*, and that helper sleeps in 20ms granules until *process* time stops +advancing — a CPU-load heuristic for "the state is predictable now", which takes +more granules the busier the box is. Measured on this box: **84ms per keypress**, +and the pilot presses enough keys for that to be **23s of its 43s**. + +`tests/_fixtures.py: fast_keys()` replaces it (call it at import; every UI suite +does). Two halves, and the second is the point: + +- `textual.app.wait_for_idle` → a bare `await asyncio.sleep(0)`. +- `Pilot.press` → send the keys, then **`settle(app)`** — pump drained, workers + finished. Deleting the heuristic *without* this broke nine checks, so it was + doing a job, badly; `settle` is strictly stronger and ~2ms. + +**What `settle` still cannot see — and what to do instead:** + +| driven by | example | gate | +|---|---|---| +| a worker | decompile, navigation, index load | `settle(app, pred)` | +| a **timer** | the function filter's `set_timer(0.08)` debounce | `wait(lambda: rows < full)` | +| a **frame** | `widget.region` / `size` / a repaint trace | `wait(lambda: inp.region.height >= 1)` | + +A settled app has not necessarily been laid out or painted. Every site in this +repo that needs a frame or a debounce is commented as such — if a check that +reads geometry or a filtered row count starts flaking, that is the reason, and +the fix is a wait on the effect, never a longer sleep. + +The frame-dependent ones found this way, as a shopping list of what to suspect: +`si.region` after the search prompt opens, `gv._minimap_rect()` / `gv.size` after +the graph opens, `gv.render_line()` scraping box glyphs, and a `render_line` +trace asserting a repaint happened at a restored scroll. All four passed for +years on the 85ms-per-key sleep and failed within three runs without it — they +were always races, just paid-for ones. + ## The four ways a test here wastes minutes Every slow suite in this repo was slow for one of these, not for doing real work. @@ -119,32 +163,45 @@ Check them before optimising anything else. listing. → Give each phase its own temp copy (`fresh_copy`). Never `os.remove` an `.i64` a suite is about to reopen. +5. **A flat `pause(d)` where a gate belongs.** `Ctx.pause` in the pilot *is* + `settle` now (`d` is the upper bound, not the cost), which took 20.4s of + fixed sleeping down to 2.8s across ~140 call sites. `Ctx.sleep(d)` is the + escape hatch for the genuinely timer-driven; reach for it only after + checking the table above. In the other suites the same conversion took + `test_trace_ui` from 19.6s to 5.5s — it was 13.5s of `pilot.pause(1.0)`. + **`settle(app, pred, timeout=...)`** (`idatui/_sync.py`) is the one true gate: it drains the message pump, waits for workers, and returns the moment `pred` holds. It is what the live RPC layer uses, so tests and driver agree on what "done" means. A bare `settle(app)` (no pred) means "the app finished reacting" — the right gate when the edit may legitimately do nothing (e.g. carving random bytes). -## Measured timings (2026-08-07, this box, warm) +## Measured timings (2026-08-07, this box, warm; keypress work 2026-08-08) | command | time | notes | |---|---|---| | `python3 tests/run.py --fast` | **0.6s** | 302 checks, all pure suites | | `python3 tests/test_graph.py` | ~1s | 86 checks, pure layout engine | | `python3 tests/test_codemode_client.py` | ~0.1s | 14 checks, fakes the DatabaseHandle | -| `~/ida-venv/bin/python tests/test_rawimage_rpc.py` | ~60s | 21 checks, owns batch rename | -| pilot boot (first scenario) | ~10-25s | opens the DB; seeded from `.pristine.i64` | -| pilot `--only graph` | ~10s | 50 checks | -| **pilot full (`test_scenarios.py`)** | **62.2s** | 56 scenarios, 301 checks (was 166s) | -| `test_trace_ui.py` | 19.4s | 39 checks | +| pilot boot (first scenario) | ~1.7s | opens the DB; seeded from `.pristine.i64` | +| pilot `--only rename` | ~2s | 11 checks | +| **pilot full (`test_scenarios.py`)** | **21.2s** | 57 scenarios, 313 checks (was 166s, then 62s) | | `test_rawimage_rpc.py` | 7.5s | 21 checks, owns batch rename | -| `test_project_ui.py` | 8.1s | 30 checks | -| `test_thumb_ui.py` | **8.5s** | 20 checks — was 313s AND crashing | -| `test_blob_ui.py` | **4.1s** | 30 checks — was 39.8s | -| `tests/run.py` (everything) | **115s** | 788 checks. was ~9m20s. BACKGROUND ONLY | +| `test_trace_ui.py` | **5.5s** | 39 checks — was 19.6s | +| `test_trace_rpc.py` | 5.1s | 45 checks | +| `test_project_ui.py` | **3.8s** | 30 checks — was 8.1s | +| `test_thumb_ui.py` | **3.6s** | 20 checks — was 313s AND crashing | +| `test_blob_ui.py` | **1.3s** | 30 checks — was 39.8s | +| `tests/run.py` (everything) | **49s** | 800 checks. was ~9m20s, then 117s | + +IDA-suite total: ~9m21s → 117s (the four wastes below) → **49s** (keypresses and +the pause→settle conversion). No check was removed to get there; the suite gained +12 and the two runs behind these numbers were 49.2s and 48.9s, 800/800 both. -IDA-suite total went from ~9m21s to ~2m16s (4.1x) by fixing the four wastes above — -not by removing a single check. +Where the pilot's remaining ~20s goes (`--profile`): 10.8s keystrokes (which now +includes the real work each key triggers, since `press` settles), 2.9s settling, +2.1s waits, ~5s scenario bodies. The rest of the gate is dominated by per-suite +IDA boot — 7 processes, each opening its own database. ### Backend performance (worker vs Code Mode), after the two transport fixes @@ -205,14 +262,13 @@ picks whichever client the checked-out tree has, so it runs on master too). ## Known-flaky -- `test_scenarios.py --only listing_view` (**codemode backend only**). Passed 2 runs, - failed the 3rd, on an unchanged tree and a fresh scratch DB. Symptom: `listing shows - data heads (not just code)` reports `{'label','sep','funchdr','code'}` and - `total=1500`, i.e. the model is read before its pages have materialised. Adding *any* - delay (even a single `stderr.write`) makes it pass, which is the signature of a settle - race, not a logic bug. The scenario waits on `c.lst.total > 0`, which becomes true - before the rows exist. **Do not chase this as a regression without reproducing it - 3+ times.** Real fix would be a wait on materialised rows, not on `total`. +- _(fixed 2026-08-08)_ `test_scenarios.py --only listing_view` used to fail about one + run in three: `listing shows data heads (not just code)` reported + `{'label','sep','funchdr','code'}`, i.e. the model was read before its pages had + materialised. The scenario waited on `c.lst.total > 0`, which is computed from the + segment size and is true **before any row exists** — the textbook "wait on a signal + that is set too early". It now waits for a materialised data row. Nothing else is + known-flaky; if something starts flaking, check the timer/frame table above first. --- |