13.3 seconds from finger to picture
For a couple of weeks I had a desk panel that worked and a nagging feeling that it didn’t.
You tap a card on the glass, and some number of seconds later the picture changes. I could not have told you how many seconds, because I had never measured it. I had only ever felt it, and a felt number is worth nothing. So I filmed one tap — thirty seconds of phone video — and lined the video up against the server’s journal.
13.3 seconds, finger to new picture.
Nothing failed to produce that number. No dropped link, no timeout, no reboot, no retry. It was just slow, in four places at once, and three of the four were not where I would have guessed.
The panel timestamps its own video
The trick that makes the rest of this possible: the panel draws a clock, so it timestamps the footage for me. The minute flips to 15:12 between video frame t=15.6 s and t=15.7 s, which puts t=0 at 15:11:44.35 UTC, give or take a tenth. Every frame of video now has a UTC time on it, and can be laid beside server log lines without me having to trust two clocks to agree.
| video t | UTC | what happened | source |
|---|---|---|---|
| 5.0–5.5 | 15:11:49.4–49.9 | finger on the glass | video |
| 7.25 | 15:11:51.60 | the server renders the new face and accepts the frame | server state |
| ~8.0 | ~15:11:52.4 | the transfer to the device opens | derived |
| 9.0–9.5 | 15:11:53.4–53.9 | the panel drops to its standalone clock | video |
| 10.88 | 15:11:55.23 | transfer done: 17 chunks, 32,224 bytes, slowest chunk 84 ms, flash commit 1,540 ms | journal |
| 18.8 | 15:12:03.15 | the new picture is drawn | video |
| 20.38 | 15:12:04.73 | the device finishes tidying up: 9,359 ms | journal |
Where the 13.3 seconds went
| phase | cost | share |
|---|---|---|
| the tap event, and rendering the new face (0.66 s of that is the drawing) | 1.75 s | 13% |
| the picture on the wire — 17 chunks, about 76 ms each | 1.29 s | 10% |
| the device writing the picture into flash | 1.54 s | 12% |
| the device compacting its flash once the old picture was dropped | ~7.9 s visible | 59% |
The network was innocent, and my own instrument is what said so
Two days before I filmed this I had written down my strongest hypothesis. The panel does not talk to the server directly: it dials a WebSocket URL that goes out to a CDN edge and comes back, even though the server it reaches is sitting on the same LAN as the panel. An absurd path for a 32 KB picture. Obviously the tunnel was the problem.
It was not. The wire is under 10% of the delay.
And the chunk phase is round-trip-bound rather than bandwidth-bound, which the numbers say plainly: about 76 ms per 1,920-byte chunk, and the slowest single chunk in the whole transfer was 84 ms. A spread that tight is latency, not congestion. 32 KB is nothing. Seventeen sequential acknowledgements across a wide-area round trip is everything. A bigger frame in the same session — a Hacker News front page, 33 chunks, 62,752 bytes — moved all of it in 4,477 ms.
I built the instrumentation specifically to convict the tunnel, and the instrumentation acquitted it. That is the entire reason to build the instrument rather than reason about the system in your head. My reasoning was confident, cheap and wrong.
The ten seconds that looked like a disconnection
Look again at the timeline: from 15:11:53.6 to 15:12:03.15, the panel is showing its standalone clock face. Nine and a half seconds of it.
I had been watching that happen for two days and reading it as the device losing the server and falling back to running alone. It is not. The flash compaction takes 9.36 seconds; the panel shows the clock for 9.55. They track almost exactly, offset by the round trip of the message that starts the work. The panel falls back to the clock for the duration of the device’s flash housekeeping, every time a picture is replaced.
The symptom was honest. My reading of it was not.
Why it is thirteen seconds, in one sentence
The pictures live in flash, and the eight megabytes of PSRAM are empty.
Every frame goes into a durable flash blob region: written there, and then compacted there when the old one dies. That is where 71% of the delay is — 1.54 s to commit plus a 7.9 s tidy-up — and it is a flash partition doing it, roughly four times every fifteen minutes, forever.
Meanwhile the firmware has a volatile PSRAM tier for exactly this. It is implemented, it is routed, the device advertises it in its capability word, and the resolver checks PSRAM before flash. The comment the firmware author left on it says it exists “so an atomic replacement can be rendered without ever spending partition endurance”. That is this workload, described precisely, by me, some months ago.
The host has never once asked for it. The flag that requests the volatile tier is hardcoded false, with a test pinning it there.
A decoded frame is 329,740 bytes. Free PSRAM reports 8,358,839. One picture is 4% of what has been sitting idle the whole time.
What I changed, and what I am not claiming
The interactive frame now goes to PSRAM, and the flash compaction is rate-limited and never runs in front of a picture. That takes two of the four phases out of the path between a finger and the pixels.
I am not going to tell you how fast it is now, because I have not measured it on the board. It is deployed and unverified, and the distance between “deployed” and “seen on the hardware” is the exact gap this post exists to close. The number goes in the follow-up, with the video.
One known limit while I am being honest about the new version: the volatile tier holds two slots — the displayed frame and one incoming replacement. Four picture cards do not fit in two slots, so tapping a second card inside the same refresh window can evict the first. Raising that is a protocol amendment and a new firmware image, so it is not a thing I get to do casually.
The thing I keep relearning: “it feels slow” is not a bug report, even when you are the person who built it. 13.3 seconds, and here is the breakdown is.