Part of Inside One Frame

Inside One Frame, Part A: The Raspberry Pi

By Spencer and Claude. Claude did the writing; the material is Spencer's engineering notes, measurements, and repositories. Nothing here has been independently fact-checked, so accuracy is not guaranteed — read it as a lab notebook, not a datasheet.

At 60 frames per second, the controller gets 16.7 milliseconds to turn an effect into packets for every pole. We built a flight recorder that reconstructs the PoleFX-owned work inside a frame, used it to separate rendering, composition, preview, and output time, then redesigned the capture path when the observer started disturbing the system it measured.

For years, the PoleFX Raspberry Pi could tell us that a frame was slow, but not why. Its dormant timing flag used a wall clock and printed only after a loop crossed 20 milliseconds. Everything from rendered pixels through geometry, gamma, packet encoding, and UDP output was mostly one opaque block.

At 60 fps, that block shares a 16.7 ms period with video or pattern rendering, effects, audio, and a different output path for every logical pole. FPS alone does not say which part moved, especially on a paced system. Part A started with one narrower question:

Can we preserve the structure of every frame cheaply enough to leave the instrument on, without asking the render process to format or export its own trace?

The answer is provisionally yes. The old debug path is gone; frames at or above 20 ms now produce a rate-limited slow-frame log with frame id, device count, duration, and deadline overrun. That restores the warning light. The ring supplies the missing map.

The ownership boundary matters: only the engine writes, only complete frames become visible, and trace formatting stays in another process.

One writer, one reader

The render engine and Flask server are separate OS processes. Making the engine serialize a trace for Flask would put the observer in the hot path, so the prototype uses a fixed-record mmap at /tmp/polefx-frame-profiler.bin. The engine is the only writer; Flask opens it read-only.

Each record is 48 bytes: monotonic timestamps, frame and stage ids, device and protocol ids, flags, an auxiliary value, and a commit sequence. The 131,072 record ring occupies a little over 6 MiB. At the measured 3,558 records per second, it retains about 36.8 seconds, enough for a conservative 30-second export.

The render thread does no JSON conversion or percentile work. Flask provides a bounded Chrome Trace JSON download for Perfetto, a cheaper percentile summary, and a raw-ring endpoint for moving conversion off the Pi.

Publishing only complete frames

A reader can race a writer as a ring slot wraps. The writer therefore invalidates the slot, writes its payload, and publishes the expected ordinal last. The reader checks that value before and after copying.

That is a store-ordering argument, not a proof. Nothing on either side emits a memory barrier, and the eight-byte commit word sits at offset 36 of a 48-byte record, so it is never eight-byte aligned and a single-copy atomic store is not architecturally guaranteed on the Pi's ARM cores. We have not stressed the protocol against a deliberate torn write. What the design does buy is direction: a record failing either check is dropped and counted, never returned.

Valid individual records can still form half a frame. Frame events remain private as a batch until the engine commits every child and writes frame_complete last. A sequence-locked header then publishes the visible position. Readers also reject changed writer generations and conservatively discard the oldest framed id after wrap. One missing frame is cheaper than one convincing lie.

What the trace names

A busy frame_due root contains source rendering, effects, audio, and one device root per logical output. Device children cover background, overlay, text, geometry, brightness, calibration, preview, and the wire path.

The wire names are intentionally strict: wire_prepare covers gamma, remapping, mirroring, and flattening; wire_encode ends before the first socket write; wire_send covers destination fan-out.

Instrumented children covered 97.13% of aggregate frame time and 95.50% of aggregate device time. The worst whole frame still cleared the target at 95.44%, but one device root covered only 87.70%, so the claim is not that every sample cleared 95%.

This is a trace of code we instrumented, not a reconstruction of all Pi or Linux activity. A long wire_send measures wall time around our socket boundary; it cannot distinguish kernel work, blocking, or preemption. Those questions still belong to OS tools, packet capture, and the logic analyzer.

Where one frame actually goes

The chart below is now rendered from the archived trace data in the page. Pick a preview state and a percentile, hover or focus any bar for exact timing, and replay the frame to watch the execution cursor cross the recorded spans.

This is the closest view we currently have to “what the Pi did during this frame,” but the wording matters. It includes every span the PoleFX engine currently records, not every Python function, Linux process, scheduler decision, interrupt, or kernel socket operation. Time between our spans is visible as a gap on the common clock, but its owner is not yet known.

A truly all-process swimlane needs a second synchronized layer: a sampling profiler for Python/native stacks plus an OS scheduler trace. That is the next instrumentation step. The engine trace should remain the semantic backbone because it knows what a “source,” “device,” and “wire send” mean; the system trace can explain the otherwise anonymous gaps.

The live workload was Rainbow Melt at 60 fps with three active logical devices, one each using BigPacket, sACN, and DDP. The clean 30-second summary contained 1,800 frames and zero deadline misses. Whole-frame p50/p95/p99/max was 5.115/5.576/6.993/10.947 ms.

The exact-final-build baseline also contained one 22.936 ms frame in 1,800, dominated by an 18.380 ms wire_send. It occurred before the trace drain, so the exporter cannot explain it. We kept both the zero-miss clean capture and this later outlier. One event is not a root cause, but it is a timestamped place to begin.

The ordinary percentiles barely moved, while one socket send created the only missed deadline. The two endpoint exports cover independently moving 30-second windows, so this comparison uses their archived summaries rather than pretending the adjacent trace file contains that exact outlier.

The cost of leaving it on

An always-on profiler has to pay rent.

An alternating same-process microbenchmark used the same binary with the writer enabled and disabled. Each synthetic frame emitted 17 events:

The difference is 6.137 µs per event. Scaling that flat rate to the observed 27 framed events estimates 165.7 µs per production frame, about 0.99% of one core at 60 fps and inside the 0.2 ms budget. Including unframed housekeeping gives about 2.18% of one core overall. All of that is a straight-line extrapolation from a 17-event synthetic frame, so it assumes the per-event cost does not move with cache state, contention, or event mix.

This does not close A5. The whole-process CPU A/B was unusably unstable, so we ran a second, more realistic matrix on the current three-device fixture. The same ad2d91a binary was toggled through a volatile service setting in a seeded order: three profiler-enabled and three disabled 15-second arms with preview off, then the same matrix with the real browser preview streaming at 30 fps.

Every enabled arm contained exactly 900 complete frames and zero deadline misses. All 12 arms had zero BigPacket, DDP, or sACN wire anomalies. A separate 30-second steady preview capture contained 900 actual preview payloads across 1,799 frames, again with zero misses. Its frame_due p50/p95/p99/max was 5.021/7.149/7.868/10.470 ms.

These are stage-percentile comparisons from the same binary, not additive CPU accounting and not a claim that every difference is caused by preview alone.

The whole-service CPU comparison still cannot be used as an overhead number. Enabled measured 0.77 percentage point lower with preview off and 3.88 points lower with preview on. The profiler did not make CPU use negative; background work and scheduler variation were simply larger than the signal. The matrix is output-safety evidence for the current fixture across 90 seconds of profiler-enabled running, not a CPU-overhead claim and not a rare-event bound for a feature we would leave on across a fleet.

At this point in the investigation A5 remained open for one precise reason: PoleFX did not yet define the maximum supported logical-device count, so three devices could not honestly be labeled the required worst-supported case. The capacity sweep in the next installment closes that gate for a deliberately bounded production reference envelope.

The profiler interfered when we read it

Writing the ring was cheap enough. Draining it was the failure.

The first synchronous 30-second export took about 4.3 seconds. During its five-second drain window, frame p95 rose from 5.402 to 7.474 ms and p99 from 6.278 to 10.511 ms.

We moved conversion into a nice-19 child, streamed JSON with bounded memory, used SCHED_IDLE where available, and yielded every 16 records. Export time grew to 13–14 seconds. Three idle and three drain windows then measured:

p95 no longer regressed, but mean p99 rose 0.59 ms and mean maximum rose 0.71 ms. We had not pre-registered a tolerance that would let us dismiss those differences. That mitigation was better, but it did not pass the written rule.

The next move was architectural: stop turning the ring into Chrome JSON on the Pi. We froze an acceptance threshold first, with the margins written down before the code existed: drain median-of-arm p95 no more than 0.50 ms above idle, p99 no more than 1.00 ms, datagram rate within 0.1%, and the maximum recorded as diagnostic rather than pass/fail. Then we added a raw endpoint that copies the 6,295,552-byte ring, and moved record parsing, Chrome conversion, gzip, checksumming, and manifest generation to the Mac.

In a seeded 20-arm run after a 60-second warm-up, ten idle and ten raw-drain windows each contained 299 complete frames. Both groups had zero deadline misses:

The medians did not hide a separated population or a late-run drift. Idle and drain arms remain interleaved throughout the seeded order.

The first on-wire observer appeared to find five missing sACN packets during five drains. We retained that failed artifact and inspected the observer. It had blocked its own receive loop while downloading the ring. After moving the download to a background thread, a 60-second observation across 11 raw drains received all 21,600 BigPacket packets, all 21,600 DDP packets, and all 43,200 sACN packets with no packet-shape or sequence anomaly. Raw copies took 0.152–0.269 seconds.

That is the useful kind of failure: the first result was neither hidden nor misassigned to the Pi. A6 is now fully passed for the raw/off-Pi capture workflow. The on-Pi Chrome converter remains available, but it is not the qualified path.

A smaller side question: protocol encoding

The live fixture happened to contain BigPacket, sACN, and DDP. That made the trace useful for finding time, but it did not make the three complete device durations a controlled protocol comparison: they belonged to different devices, configurations, and positions in the frame.

We therefore ran one smaller control off to the side: the four real encoder paths received the same 8,640-byte frame in randomized blocks on the same Mac, with socket I/O excluded.

BigPacket is an internal PoleFX protocol created before we knew DDP existed. It remains in the live fixture for historical reasons. The controlled values above are Mac encoder microseconds, not Pi end-to-end timings. They explain packet construction, but they are a side result—not the story of the frame profiler.

Next: add the missing system layer

The capacity sweep in the next installment defines and tests the bounded production reference envelope. For frame visibility, the more interesting next step is to synchronize this semantic engine trace with process and scheduler data: Python/native stack samples, Flask activity, kernel scheduling, and the socket boundary.

Part B would add production-safe, owner-scoped ESP32 counters. Part C would add a bench-only trace of our own FreeRTOS task stages, runtime samples, and rare I2S anomalies, without pretending to reconstruct every context switch.

Part A makes a modest promise: when a frame is slow, we can now ask where our code spent the time. The raw capture path has passed its observer-effect gate. The profiler is useful, and the next view should explain who owned the gaps between its spans.