From 6b873ae6549bfee347ce5b74fd93b7eaba464eb0 Mon Sep 17 00:00:00 2001 From: Jean-Pierre Martineau Date: Sun, 4 Oct 2026 17:16:17 -0400 Subject: [PATCH] profile-picocalc can send keys faster than the app and see why it stops The tour driver timed each key and waited for it to finish, so it could never reproduce what a fast thumb does to the map. `burst KEY N MS` sends N presses MS apart without waiting, then reports how long the app took to catch up and the longest silence on the way. tours/map_burst.txt drives the map that way. scripts/watchdog.py (with run_watchdog.sh) runs the app with a thread outside the event loop that pings it every 50 ms. While a ping goes unanswered, it samples every thread's stack, and twice a second it logs RSS, swap and major page faults, alongside the map's tile loads and rasters. That is what told the map's two freezes apart: the whole process stopped while it was paged back in from the SD-card swap, and the event loop starved by a port walk waiting on the GIL. SKILL.md says how to read both signatures, why to pin the map's view before each run, and why an expect needle must be ASCII. Co-Authored-By: Claude Opus 5.5 (1M context) --- .claude/skills/profile-picocalc/SKILL.md | 34 ++- .../profile-picocalc/scripts/drive_console.py | 48 ++++ .../profile-picocalc/scripts/run_watchdog.sh | 11 + .../profile-picocalc/scripts/watchdog.py | 209 ++++++++++++++++++ .../profile-picocalc/tours/map_burst.txt | 32 +++ 5 files changed, 332 insertions(+), 2 deletions(-) create mode 100755 .claude/skills/profile-picocalc/scripts/run_watchdog.sh create mode 100644 .claude/skills/profile-picocalc/scripts/watchdog.py create mode 100644 .claude/skills/profile-picocalc/tours/map_burst.txt 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