diff --git a/.claude/skills/profile-picocalc/SKILL.md b/.claude/skills/profile-picocalc/SKILL.md index 4a2c241..eb6b17f 100644 --- a/.claude/skills/profile-picocalc/SKILL.md +++ b/.claude/skills/profile-picocalc/SKILL.md @@ -49,9 +49,11 @@ byte to `/dev/tty1` so the screen shows exactly what a person would see (JP can along live), injects the scripted keys, and prints p50/p90/max per key group. Tour scripts are one step per line: `down 8`, `enter`, `text:y`, `sleep 3`, -`label: contacts` to start a new measurement group, `shot NAME` to grab the screen. +`label: contacts` to start a new measurement group, `shot NAME` to grab the screen, +`burst right 12 100` to send keys at a fixed rate without waiting (see below). `tours/` has `nav_all.txt` (every page), `nav_ab.txt` (short, for A/B runs), -`nav_opens.txt` (screen opens, timed with `expect`), `nav_map.txt`, and +`nav_opens.txt` (screen opens, timed with `expect`), `nav_map.txt`, `map_burst.txt` +(the map driven faster than it can keep up), and `nav_changed.txt` (every optimised paint plus a real dialog — the A/B tour). ## A/B'ing a change: revert the device, don't rebuild it @@ -131,6 +133,34 @@ later as an untriggered `~tick` (the menu loop resumes asynchronously, so it is attributed to the key). Judging Esc by its own row alone understates it; judging it by console quiescence overstates it — the truth was ~90 ms, from the sequence. +## When the app falls behind, or freezes + +The per-key clock waits for each key to finish, so it can never see the failure a fast thumb +causes: keys arriving faster than the app answers them. `burst KEY N MS` sends N presses MS +apart regardless, then reports the **catch-up** (last key sent to the app quiet for 1.5 s) +and the **longest gap** in its output. A long catch-up with short gaps is the app working +through a backlog while staying live; a long gap is a freeze. + +To see *why*, run the app under `scripts/watchdog.py` (`--exe .../run_watchdog.sh`, with +`watchdog.py` copied to the repo root like `instrument.py`). A thread outside the event loop +pings it every 50 ms and, while a ping goes unanswered, samples every thread's stack; twice a +second it logs RSS, swap and major page faults. Two signatures: + +- **The log itself goes silent** for seconds and `majflt` jumps by thousands: the whole + process was stopped while the kernel paged it back in from the SD-card swap. That is + memory, not CPU — find what grew (`rss`, `swap`, the map's `memo=` bytes). +- **Pings of 0.3–1 s with the main thread somewhere cheap** — a `glob`, a `stat`, a small + read: the GIL convoy. Each syscall hands the GIL back and waits up to 5 ms to retake it + while a worker thread (a raster, a tile decode) holds it, so a loop doing hundreds of small + reads takes hundreds of times longer. Anything that walks the filesystem belongs in + `asyncio.to_thread`, however cheap it looks idle. + +The map persists its view, so pin it before every run or two runs start in different places: +`INSERT OR REPLACE INTO app_state(key, value) VALUES ('map_view', '{"lat": 45.52, "lon": +-73.62, "zoom": 10}')` into `~/.meshterm/meshterm.db`, with the venv's Python (the image's +own has no `sqlite3`). And `expect` needles must be ASCII: `/dev/vcs1` holds font glyph +indices, so `·` never matches — `km across` finds the map's title. + ## Traps that cost real time - **cProfile lies on this CPU.** Its per-call overhead (~1.9×) wrecks a path made of tens of diff --git a/.claude/skills/profile-picocalc/scripts/drive_console.py b/.claude/skills/profile-picocalc/scripts/drive_console.py index 283033d..f3f0b63 100644 --- a/.claude/skills/profile-picocalc/scripts/drive_console.py +++ b/.claude/skills/profile-picocalc/scripts/drive_console.py @@ -15,6 +15,8 @@ Script lines: KEY [repeat] e.g. "down 5", "enter", "esc", "text:c" sleep SECONDS let the app settle (a screen opening, a radio connect) label: NAME start a new measurement group shot NAME dump the console text right now + burst KEY N MS N presses MS apart without waiting for the app, then + time how long it takes to catch up # comments and blank lines are ignored Keys: up down left right enter esc tab backspace pgup pgdn home end space f1..f10, @@ -75,6 +77,11 @@ QUIET_S = 0.045 #: Give up on a keystroke that never produces output (a key the screen ignores). TIMEOUT_S = 6.0 +#: After a ``burst``, the app has caught up once it has written nothing for this long. +#: Longer than a repaint gap, because a burst's tail is background work landing (a tile, a +#: raster) rather than one frame; shorter than the 2 s header tick, which would never end. +BURST_QUIET_S = 1.5 + def set_winsize(fd, rows, cols): fcntl.ioctl(fd, termios.TIOCSWINSZ, struct.pack("HHHH", rows, cols, 0, 0)) @@ -243,6 +250,47 @@ def main(): f"{(found - base) * 1000:8.1f} {'':>8} {'':>8} {'':>7}" f" <- {needle}") continue + if line.startswith("burst "): + # Keys at a fixed rate, *not* waiting for the app: a held key or a fast thumb. + # The per-key clock below answers "how long does one key cost"; this answers + # "how long until the app has caught up with everything it was sent", which is + # the freeze a reader actually feels. Reports the catch-up (last key sent to + # the app going quiet for `BURST_QUIET_S`) and the longest silence in between. + _, name, count, every_ms = line.split() + seq = KEYS.get(name) or (name.split(":", 1)[1] if name.startswith("text:") else None) + if seq is None: + print(f" ?? unknown key {name!r}", file=sys.stderr) + continue + while drain(timeout=quiet_s)[0]: + pass + every = int(every_ms) / 1000.0 + t_begin = time.perf_counter() + last_out = t_begin + longest = 0.0 + for i in range(int(count)): + os.write(fd, seq.encode()) + last_key[0] = time.perf_counter() + until = t_begin + (i + 1) * every + while (left := until - time.perf_counter()) > 0: + n, first, last, _ = drain(quiet=left, timeout=left) + if first is not None: + longest = max(longest, first - last_out) + last_out = last + t_sent = time.perf_counter() + while True: + n, first, last, _ = drain(quiet=BURST_QUIET_S, timeout=BURST_QUIET_S) + if first is None or time.perf_counter() - t_sent > 120: + break + longest = max(longest, first - last_out) + last_out = last + catch_up = (last_out - t_sent) * 1000 + rows_out.append({"label": label, "key": f"burst:{name}x{count}@{every_ms}", + "n": int(count), "catch_up": catch_up, + "longest_gap": longest * 1000}) + print(f"{label:<20} {'burst':<10} {int(count):3d} " + f"sent {(t_sent - t_begin) * 1000:7.0f} catch-up {catch_up:8.0f} " + f"longest gap {longest * 1000:7.0f} <- {name} every {every_ms} ms") + continue m = re.match(r"^(\S+?)(?:\s+(\d+))?$", line) name, count = m.group(1), int(m.group(2) or 1) if name.startswith("text:"): diff --git a/.claude/skills/profile-picocalc/scripts/run_watchdog.sh b/.claude/skills/profile-picocalc/scripts/run_watchdog.sh new file mode 100755 index 0000000..7d015e0 --- /dev/null +++ b/.claude/skills/profile-picocalc/scripts/run_watchdog.sh @@ -0,0 +1,11 @@ +#!/bin/sh +# Hand this to drive_console.py as --exe to run MeshTerm under the freeze watchdog. +# It runs MeshTerm through watchdog.py, which appends events to $WATCHDOG_LOG +# (default ~/tmp/watchdog.log): event-loop pings, stack samples of every thread +# while the loop is stuck, RSS/swap/major faults, and map tile and raster timing. +# +# The checkout is $MESHTERM_REPO, or ~/MeshTerm -- never a hardcoded /home/, +# since this runs as whatever user the device deployed under. +REPO="${MESHTERM_REPO:-$HOME/MeshTerm}" +cd "$REPO" || exit 1 +exec "$REPO/.venv/bin/python" "$REPO/watchdog.py" "$@" diff --git a/.claude/skills/profile-picocalc/scripts/watchdog.py b/.claude/skills/profile-picocalc/scripts/watchdog.py new file mode 100644 index 0000000..8ea66b2 --- /dev/null +++ b/.claude/skills/profile-picocalc/scripts/watchdog.py @@ -0,0 +1,209 @@ +# SPDX-License-Identifier: Apache-2.0 +"""Run the real MeshTerm with a freeze watchdog: what stopped the app, not just how long. + +The per-key clock (drive_console.py) says a key took four seconds; this says why. A thread +outside the event loop pings it every 50 ms, and while a ping goes unanswered it samples +every thread's stack — so a stall shows whether the loop was busy itself or waiting its +turn for the GIL behind a worker. Alongside: the process's RSS, swap and major page +faults twice a second, which is how a *whole-process* freeze shows up (the log itself goes +silent, and majflt jumps by thousands: the kernel is paging the interpreter back in from +the SD-card swap), and timing for the map's tile loads and rasters. + +Writes ~/tmp/watchdog.log (override with $WATCHDOG_LOG). Events, one per line, all with +seconds since start: + + ping lag_ms event-loop latency of a call_soon_threadsafe ping + stall lag_ms thread=... stack a stack sample of every thread while the loop is stuck + mem rss_mb swap_mb majflt cpu_ms threads queue pending tiles drawing wanted memo + tile op ms key thread one stage of BasemapSource.load_tile + raster ms coarse key one render_ground pass + key action a dispatched key +""" + +from __future__ import annotations + +import os +import sys +import threading +import time +import traceback + +LOG = os.environ.get("WATCHDOG_LOG") or os.path.expanduser("~/tmp/watchdog.log") +T0 = time.monotonic() +_fh = open(LOG, "a", buffering=1) +_lock = threading.Lock() +_state = {"loop": None, "screen": None, "source": None} + + +def emit(kind, *parts): + line = f"{time.monotonic() - T0:9.3f} {kind} " + " ".join(str(p) for p in parts) + with _lock: + _fh.write(line + "\n") + + +def _proc(): + try: + with open("/proc/self/status") as fh: + st = {k: v.strip() for k, v in (ln.split(":", 1) for ln in fh if ":" in ln)} + rss = int(st.get("VmRSS", "0 kB").split()[0]) / 1024 + swap = int(st.get("VmSwap", "0 kB").split()[0]) / 1024 + thr = int(st.get("Threads", "0")) + with open("/proc/self/stat") as fh: + f = fh.read().rsplit(")", 1)[1].split() + majflt = int(f[9]) + cpu_ms = (int(f[11]) + int(f[12])) * 1000 / os.sysconf("SC_CLK_TCK") + return rss, swap, majflt, cpu_ms, thr + except Exception: # noqa: BLE001 + return 0, 0, 0, 0, 0 + + +def _short_stack(frame, depth=7): + out = [] + while frame is not None and len(out) < depth: + co = frame.f_code + fn = co.co_filename + mod = fn.rsplit("/", 2) + out.append(f"{mod[-1]}:{frame.f_lineno}:{co.co_name}") + frame = frame.f_back + return " < ".join(out) + + +def watchdog(): + pending = None # (sent_at) of the outstanding ping + last_stall_sample = 0.0 + last_mem = 0.0 + names = {} + while True: + time.sleep(0.05) + now = time.monotonic() + loop = _state["loop"] + if loop is None: + continue + if pending is None: + sent = now + + def pong(sent=sent): + nonlocal pending + lag = (time.monotonic() - sent) * 1000 + if lag > 60: + emit("ping", f"{lag:.0f}") + pending = None + + pending = sent + try: + loop.call_soon_threadsafe(pong) + except RuntimeError: + return + elif now - pending > 0.25 and now - last_stall_sample > 0.25: + last_stall_sample = now + for t in threading.enumerate(): + names[t.ident] = t.name + frames = sys._current_frames() + for ident, fr in frames.items(): + if ident == threading.get_ident(): + continue + emit("stall", f"{(now - pending) * 1000:.0f}", + f"thread={names.get(ident, ident)}", _short_stack(fr)) + if now - last_mem > 0.5: + last_mem = now + rss, swap, majflt, cpu, thr = _proc() + scr = _state["screen"] + src = _state["source"] + q = "-" + try: + ex = loop._default_executor + if ex is not None: + q = f"{ex._work_queue.qsize()}/{len(ex._threads)}" + except Exception: # noqa: BLE001 + pass + if scr is not None: + info = (f"pending={len(scr._pending)} tiles={len(scr._tiles)} " + f"drawing={'y' if scr._drawing else 'n'} " + f"wanted={'y' if scr._wanted else 'n'} spec={'y' if scr._speculating else 'n'}") + else: + info = "-" + memo = (f"{len(src._memo)}/{getattr(src, '_memo_bytes', 0) / 1048576:.1f}MB" if src is not None else "-") + emit("mem", f"rss={rss:.1f} swap={swap:.1f} majflt={majflt} cpu={cpu:.0f}", + f"thr={thr} q={q} {info} memo={memo}") + + +def install(): + from meshterm.services import basemap + from meshterm.ui import map_screen + from meshterm.ui.tui.session import TuiSession + + def timed(cls, name, label): + orig = getattr(cls, name) + + def wrapper(self, *a, **k): + t = time.perf_counter() + try: + return orig(self, *a, **k) + finally: + _state["source"] = self + key = a[1] if name == "_decode" else "/".join(str(x) for x in a[:3]) + emit("tile", label, f"{(time.perf_counter() - t) * 1000:.0f}", + key, threading.current_thread().name) + + setattr(cls, name, wrapper) + + timed(basemap.BasemapSource, "load_tile", "load") + timed(basemap.BasemapSource, "_read_decoded", "sidecar") + timed(basemap.BasemapSource, "_decode", "decode") + timed(basemap.BasemapSource, "_fetch_tile", "fetch") + timed(basemap.BasemapSource, "_write_decoded", "write") + + orig_rg = map_screen.render_ground + + def render_ground(vp, tiles, markers, *a, **k): + t = time.perf_counter() + try: + return orig_rg(vp, tiles, markers, *a, **k) + finally: + emit("raster", f"{(time.perf_counter() - t) * 1000:.0f}", + f"coarse={k.get('coarse', False)}", f"z{vp.zoom}", f"tiles={len(tiles)}", + threading.current_thread().name) + + map_screen.render_ground = render_ground + + orig_init = map_screen.MapScreen.__init__ + + def init(self, *a, **k): + orig_init(self, *a, **k) + import asyncio + + _state["screen"] = self + _state["loop"] = asyncio.get_running_loop() + emit("map", "open") + + map_screen.MapScreen.__init__ = init + + orig_dispatch = TuiSession._dispatch + + def dispatch(self, action, data=""): + if _state["loop"] is None: # the first key: ping the loop from here on, map or not + import asyncio + + _state["loop"] = asyncio.get_running_loop() + emit("key", action if action != "text" else f"text:{data}") + return orig_dispatch(self, action, data) + + TuiSession._dispatch = dispatch + + threading.Thread(target=watchdog, name="watchdog", daemon=True).start() + + +def main(): + emit("start", repr(sys.argv)) + try: + install() + except Exception: # noqa: BLE001 + emit("install-failed", traceback.format_exc().replace("\n", " | ")) + from meshterm.cli import main as cli_main + + sys.argv = ["meshterm"] + sys.argv[1:] + cli_main() + + +if __name__ == "__main__": + main() diff --git a/.claude/skills/profile-picocalc/tours/map_burst.txt b/.claude/skills/profile-picocalc/tours/map_burst.txt new file mode 100644 index 0000000..0e1c7a0 --- /dev/null +++ b/.claude/skills/profile-picocalc/tours/map_burst.txt @@ -0,0 +1,32 @@ +# A thumb faster than the map: pans and zooms sent at a fixed rate, not waiting for the +# app (`burst`), from a fixed view. Pin the view first (see SKILL.md) or runs differ. +label: connect +enter +sleep 25 +shot menu +text:m +text:a +text:p +shot filtered +label: open-map +enter +expect km across +sleep 15 +shot map-open + +label: pan-burst +burst right 12 100 +shot after-right +burst down 12 100 +burst left 12 100 +burst up 12 100 +shot after-pans + +label: zoom-burst +burst pgdn 3 150 +burst right 8 100 +burst pgup 4 150 +burst left 8 100 +sleep 5 +shot end +esc