Board diagnosis: the helper wasn’t the bottleneck, prepare() was

Follow-up to README.md in this same directory, after the coordinator ran the landed perf/instant-theme-swap work (master b3183866, plus the later d87728a4 preview-race fix) on the reserved board, system 766yhn3l.... This file is a host + code-reading diagnosis of that board run (the board run itself is the coordinator’s own, not repeated here) plus the fix and instrumentation this worktree (perf/instant-swap-board, base master at d87728a4 or later) adds. No board access from this worktree; nothing here is a new board measurement.

The board numbers (coordinator’s own run, timed directly with the

installed k230-theme, shell user, chooser closed)

journalctl -u theme-helper --since -3min showed no entries. /run/shell/theme-helper.sock existed, owned by shell. Before the daemon existed at all, activate took 2.8-3.5 s — so the daemon made this worse, not better.

Root cause (found by reading the actual code path, confirmed by a host measurement)

theme_activate.py’s prepare() is called by every preview/activate, daemon-served or not. It used to check whether the destination generation already existed only at the very end — after:

1. hashing the whole theme source tree (source_digest, reading every background image’s full bytes) and the whole omarchy-theme-tools tree,
2. staging: copying every background image and config file into a scratch directory (checked_copy, a second full read-and-write of the same bytes source_digest just read),
3. invoking the external omarchy-theme-color --all helper (a bash script that itself spawns several awk subprocesses per call for colour mixing),
4. invoking omarchy-theme-set-templates (another bash script, which itself re-invokes omarchy-theme-color --all again internally, then runs sed -f <script> per template file),
5. (only for a new generation) building the wallpaper cache.

For an already-prepared generation, none of steps 2-5 do anything useful — the exact same output already exists on disk — but all of it ran anyway, every single call, and was thrown away the moment the (previously last-checked) destination.exists() test finally ran. This is real, subprocess-spawning, disk-I/O work, unrelated to Python interpreter start-up (which theme-helper.service already correctly eliminated), so removing the interpreter cost alone could never have fixed it — consistent with the board showing the daemon reachable yet the numbers not improving.

theme_client.py compounded this. Its --helper-timeout-s default was 0.3 s, sized for “how long should Python start-up take”, not “how long can a real prepare() legitimately take”. Since a real preview/activate routinely took several seconds (per above), the client’s socket read timed out on an already-working daemon reply almost every time, abandoned it, and fell back to the full in-process path — paying the wasted 0.3 s and the ~1.2 s import chain and prepare()’s cost a second time. This fully explains the board’s activate number landing above the pre-daemon baseline: 0.3 + 1.2 + ~2.7 (prepare) ≈ 4.2 s, matching the observed 4.18-4.26 s almost exactly.

journalctl -u theme-helper showing nothing was not a sign of failure — neither theme_helperd.py nor theme_catalog.py printed anything on success or failure. There was nothing to see, not evidence the daemon wasn’t being used.

The fix

• tools/theme_activate.py: prepare() now computes the generation’s content-addressed identity (two digests already computed first, plus a cheap background-name directory listing — no asset bytes copied, no external helper spawned) and checks for an existing destination before any staging/external-helper/wallpaper-cache work. A cache hit returns the on-disk report.json, patched only for the one field that is genuinely request-specific (a since-removed remembered background choice), never rewriting the shared, immutable generation. Host-measured on this machine: a repeat prepare() for the same generation dropped from 240-370 ms (cache miss, external helpers included) to 1.5-2.7 ms (cache hit) — see tests.test_omarchy_theme_activation’s own captured THEME_TIMING lines.
• tools/theme_client.py: DEFAULT_TIMEOUT_S raised from 0.3 to 10.0 — comfortably above every board number seen so far (including the slow, pre-fix ones), so a legitimate daemon reply is never abandoned in favour of the strictly worse fallback path.
• tools/theme_timing.py (new): a tiny Stopwatch/log() helper, wired into theme_activate.prepare(), theme_transaction.exchange(), theme_catalog.handle(), theme_helperd.handle_line(), and theme_client.py, emitting one THEME_TIMING <component> <action> phase=Xms ... line per request via syslog — deliberately never print(..., file=sys.stdout/stderr), because theme_catalog.rs’s command_error() parses a failing CLI’s stderr as JSON byte-for-byte, and any stray text there turns a real error message into a generic “theme command failed”. journalctl captures syslog by default, tagged with the emitting process’s own systemd unit when it has one.
• nix/rust-shell-client/src/theme_catalog.rs: execute() now logs rust-shell <ms>ms theme-command <action> <id> duration=<ms>ms (the existing rust-shell <ms>ms <event> shape tools/theme-swap-jank.py already parses), timing the chooser’s own wait on the k230-theme subprocess — confirming (by inspection: nix/shell.nix’s shell-ui.service sets K230_THEME_COMMAND to the theme_client.py wrapper, the exact same binary the coordinator ran by hand) that the chooser path already goes through the daemon-aware client; no code change was needed there, only the timing.
• nix/handheld-theme-command.nix: added the missing install -m 0644 ... theme_timing.py line — every module above now imports it, and it was not being installed into the packaged libexec/handheld-theme/ directory, which would have made every k230-theme invocation on a freshly built system fail with ModuleNotFoundError the moment this change’s own instrumentation shipped. Caught here, before any board install, by rebuilding .#handheld-theme-command after adding the instrumentation and noticing the derivation’s own file list.

Test-suite proof (host only)

• python3 -m unittest tests.test_omarchy_theme_activation: 12 cases (2 new), including the two that assert checked_copy/invoke raise if called on a cache hit.
• python3 -m unittest tests.test_theme_helper_daemon: 6 cases (1 new), including a daemon reply mocked to take 0.6 s (past the old 0.3 s default, inside the new one) asserting the client never falls back.
• python3 -m unittest tests.test_theme_timing: 5 cases, asserting the log helper never touches stdout/stderr and never raises.
• python3 -m unittest tests.test_theme_catalog tests.test_omarchy_theme_transaction plus the full existing theme suite: unaffected (131 cases total across this worktree’s touched files, all passing).
• cargo test --offline (nix/rust-shell-client): 138 cases, all passing.
• nix build --no-link --print-out-paths --max-jobs 1 --cores 6 .#handheld-shell-rust .#handheld-theme-command .#handheld-theme-default .#card-shell: all four build for riscv64:
  • /nix/store/i1xa32amsa0r5zxlivwsmq91mldi2mqm-k230-shell-rust-riscv64-unknown-linux-gnu-0.1.0
  • /nix/store/rsmbxhf0j5xfg6lj76kfqm5a78bxx4wl-handheld-theme-command-0.1 (rebuilt after the theme_timing.py packaging fix below; the first build of this attr, before that fix, silently omitted the file — caught here by listing the derivation’s own installed files, not by a board failure)
  • /nix/store/m3vwvnnckr7m9mkcpnbhbhc0c4hz3p8i-handheld-theme-default-28ceaae7
  • /nix/store/fq1i1fmhqa4a35amc61nx2z0wbr2a5yz-k230-card-shell
• openspec validate the-shell-swaps-themes-without-a-python-stall --strict: valid.

QEMU smoke test of the actual packaged binary (not just host unit tests)

Built .#handheld-theme-command fresh from this worktree (/nix/store/rsmbxhf0j5xfg6lj76kfqm5a78bxx4wl-handheld-theme-command-0.1, a riscv64 package) and ran its bin/k230-theme wrapper under qemu-riscv64-static (via this host’s registered binfmt_misc handler, so the wrapper script runs exactly as it would from a board shell), no daemon socket present (fallback path, so this exercises theme_activate.prepare() and theme_timing’s real syslog calls in a real riscv64 interpreter, not this host’s own Python):

list --json:                 1.735 s
preview <id> --json (cold):  5.920 s
preview <id> --json (again): 1.799 s   -- byte-identical output to the cold run

Confirms, independent of the host unittest numbers above: theme_timing.py is correctly packaged (no ModuleNotFoundError), stdout carries nothing but the JSON result in both the cache-hit and cache-miss case (syslog never leaks into it, even where /dev/log may not exist in this qemu-user environment — theme_timing.log()’s own except Exception: pass holds), and the cache-hit preview matches list’s own baseline cost almost exactly (~1.7-1.8 s, all qemu-user-emulation + Python-start-up overhead, nothing left from staging/external-helper work), while the cache-miss preview pays for two additional emulated subprocess trees (omarchy-theme-color/omarchy-theme-set-templates, each themselves spawning several awk/sed children) at roughly 3x the cost. This is still qemu-user overhead dominating the absolute numbers, never the K230’s own in-order core — only the relative cache-hit-vs-miss comparison (and the packaging/stdout-cleanliness proof) is meaningful from this host.

Exact board commands for the coordinator

Confirm the daemon picked up the new build and is reachable:

systemctl status theme-helper --no-pager
ls -la /run/shell/theme-helper.sock

Repeat the exact timed sequence from the original report (same theme ids, so this lands on the same, already-prepared generation and exercises the new cache-hit fast path), as the shell user with the shell session’s own runtime dir and display:

sudo -u shell env XDG_RUNTIME_DIR=/run/shell WAYLAND_DISPLAY=<shell's own value> \
  bash -c 'time k230-theme list --json' >/tmp/list.json
sudo -u shell env XDG_RUNTIME_DIR=/run/shell WAYLAND_DISPLAY=<shell's own value> \
  bash -c 'time k230-theme preview --json <catppuccin-or-latte-id>' | tee /tmp/preview.json
GEN=$(python3 -c "import json,sys;print(json.load(open('/tmp/preview.json'))['generation'])")
sudo -u shell env XDG_RUNTIME_DIR=/run/shell WAYLAND_DISPLAY=<shell's own value> \
  bash -c "time k230-theme activate --json --expected-generation $GEN <same-id>"

Expected: preview/activate well under 500 ms each now that the generation is already prepared (task 4’s own target). Pull the new self-diagnosing timing from the journal right after:

# Every THEME_TIMING line from every process on the machine (client,
# daemon, and the two-phase exchange), regardless of which one emitted it:
journalctl -t k230-theme-timing --since "-5 min" --no-pager

# The daemon's own view specifically (same lines, scoped to its unit):
journalctl -u theme-helper --since "-5 min" --no-pager

Look for, per the coordinator’s own diagnostic questions:

• THEME_TIMING client <action> ... path=daemon outcome=ok — confirms the client actually used the daemon, not the fallback (path=fallback would mean it didn’t, with outcome/reason saying why).
• THEME_TIMING prepare <name> ... cache=hit with a total= of a few ms — confirms prepare() skipped staging/helper-invocation/wallpaper-cache entirely for the already-prepared theme. cache=miss (with omarchy_theme_color=/omarchy_theme_set_templates= phases) is expected and correct for a theme prepared for the first time; cache=race is the rare concurrent-preparer path.
• THEME_TIMING exchange <phase> endpoint=<...> generation=<...> ms=... — the Rust/deck ack round trip time, per phase per receiver.
• THEME_TIMING handle activate ... — the daemon’s own per-action breakdown (discover/prepare_entry/activate_generation/ keyboard_deferred_dispatch/total).
• THEME_TIMING keyboard_deferred activate ... state=applied|failed|superseded — confirms the deferred keyboard thread (task 3.3a) actually ran and finished, separately from handle()’s own (fast) return.

Then, separately, actually use the on-screen theme chooser (not just the raw CLI) to exercise the Rust catalog bridge end to end, and pull its own timing:

journalctl -u shell-ui --since "-5 min" --no-pager | grep 'theme-command'

Look for rust-shell <ms>ms theme-command <action> <id> duration=<ms>ms — the chooser’s own wait on each k230-theme call, which should now track the fast path=daemon/cache=hit numbers above rather than the multi-second numbers from before this fix.

None of the commands in this section have been run by this worktree; /dev/ttyACM0 was not opened.