Skip to content

fix: report the frame rate each saver actually achieves - #271

Merged
BernardJen merged 1 commit into
mainfrom
fix/fps-instrumentation
Aug 21, 2026
Merged

fix: report the frame rate each saver actually achieves#271
BernardJen merged 1 commit into
mainfrom
fix/fps-instrumentation

Conversation

@BernardJen

Copy link
Copy Markdown
Contributor

The wall is laggy on the split-flap board and slow on some screensavers. Two hypotheses have
now been measured and both refuted, so this ships the measurement rather than a third guess.

What was ruled out

Hypothesis Verdict
Software-rendering fallback Refuted. The wall runs ANGLE (NVIDIA, NVIDIA RTX PRO 4000 Blackwell … Direct3D11), gpu_compositing enabled, float targets available, 6000×1200 @1x
The unconditional Art-Net frame readback Refuted as the cause. Real, but 4%: Mandelbrot at 6000×1200 went 29.8 → 28.5 fps

The readback test is worth a note — against Split Flap it showed no difference, because both
runs sit on the ~120 fps vsync cap and the test simply cannot see through it. That is exactly the
trap #225 flagged ("the ~120 readings are a vsync cap, not a measured ceiling"). Re-running
against a saver below the cap is what produced a usable number.

What remains unexplained is ~6 of 32 cores busy continuously on that machine, with 57 GB RAM
free and a healthy GPU.

The instrument

One property increment per frame, in a loop that already increments a counter. No readback, no
allocation, no timing call on the hot path — the thing being measured must not be changed by
measuring it.

Counters are per runtime and labelled from one level up. The 30 savers each call
createGLRuntime() inside their own create(), so the registry announces the name before
instantiating rather than threading a label through 30 files. The boards are labelled per side,
because in dual view they are separate runtimes and an aggregate would hide one being slower.

Verified in the state the wall is actually in — two boards and a live saver at once:

saver                        mean    min    max   last   n  size
Split Flap (left)            58.2   53.5   62.9   62.9   4  1182x2260
Split Flap (right)           58.2   53.5   62.9   62.9   4  1182x2260
Moire Interference           58.5   53.5   63.9   62.9   4  2582x2260

min/max are per interval, not per frame: a saver that averages 60 and drops to 8 for one
interval is the interesting case, and a mean alone hides it. Every row carries the resolution,
because every fps figure in this repo has been misread at least once for want of knowing what it
was taken at.

On disk

One file, overwritten, never appended — same discipline as the GPU report. Rows are per
saver, not per sample: 32 is the ceiling, main caps the file at 60 lines, and it measured
404 bytes after a minute with three runtimes live. Bounded by the number of savers, not by
uptime.

Counters are read every 15s (memory only) and written every 60s (the only part that touches disk).

Deliberately not included

The Art-Net readback fix, though it is measured and ready. Shipping it alongside would mean the
wall's first numbers are already post-fix, making its real cost on that hardware unmeasurable.
Instrument, then fix, then compare.

Tests

11 new, 618 → 629, on the folding and formatting — a wrong number here sends the next round of
diagnosis somewhere useless. Includes the bound that matters: 50 sample rounds still produce one
row.

The counter itself lives in the GL frame loop and needs a real context, so it is covered by the
end-to-end run above rather than by a unit test.

What to do with it

Once this is on the wall, fps-report.txt sits beside gpu-report.txt in its userData. If the
boards read 12 fps there against 58 here, that is the answer. If they read 58, the lag is not in
the render loop and the next place to look is the capture path — which the ~6 cores already hint
at.

The wall is laggy on the split-flap board and slow on some screensavers, and after
the GPU report ruled out the obvious cause there was still no way to see the frame
rate it was achieving. Two hypotheses have now been measured and refuted:

  software rendering fallback   refuted -- the wall runs ANGLE on an
                                RTX PRO 4000 Blackwell over D3D11, with
                                gpu_compositing enabled and float targets
                                available
  the unconditional Art-Net     refuted as the cause -- real, but 4%.
  frame readback                Measured against Mandelbrot at 6000x1200:
                                29.8 -> 28.5 fps. Invisible against Split Flap
                                because both runs sit on the ~120 fps vsync cap,
                                which is the trap #225 warned about

What is left unexplained is ~6 of 32 cores busy continuously on that machine, with
57 GB of RAM free and a healthy GPU. Guessing a third time is not worth it, so this
adds the measurement instead.

## The instrument

One property increment per frame, in a loop that already increments a counter. No
readback, no allocation, no timing call on the hot path -- the thing being measured
must not be changed by measuring it.

Counters are keyed per runtime and labelled from one level up: the 30 savers each
call createGLRuntime() inside their own create(), so the registry announces the
name before instantiating, rather than threading a label through 30 files. The two
split-flap boards are labelled per side, because in dual view they are separate
runtimes and an aggregate would hide one being slower than the other.

Verified end to end in the state the wall is actually in -- two boards and a live
saver at once:

  Split Flap (left)     58.2  53.5  62.9   4  1182x2260
  Split Flap (right)    58.2  53.5  62.9   4  1182x2260
  Moire Interference    58.5  53.5  63.9   4  2582x2260

min and max are per interval, not per frame, because a saver that averages 60 and
drops to 8 for one interval is the interesting case and a mean alone hides it. Every
row carries the resolution: every fps figure in this repo has been misread at least
once for want of knowing what it was taken at (#225).

## On disk

**One file, overwritten, never appended** -- the same discipline as the GPU report.
Rows are per saver, not per sample: 30 savers plus two boards is the ceiling, main
caps the file at 60 lines, and the file measured 404 bytes after a minute with three
runtimes live. Bounded by the number of savers rather than by uptime, which is the
property that matters on a wall left running for months. Counters are read every 15s
and written every 60s; the read is memory-only, and only the write touches disk.

## Deliberately not included

The Art-Net readback fix, even though it is measured and ready. If it shipped
alongside this, the wall's first numbers would already be post-fix and its real cost
on that hardware would be unmeasurable. Instrument first, then fix, then compare.

11 new tests, 618 -> 629, covering the folding and formatting -- a wrong number here
would send the next round of diagnosis somewhere useless. The counter itself lives in
the GL frame loop and needs a context to exercise.
@BernardJen
BernardJen merged commit 9776d5d into main Aug 21, 2026
1 check passed
@BernardJen
BernardJen deleted the fix/fps-instrumentation branch August 21, 2026 13:56
BernardJen added a commit that referenced this pull request Aug 21, 2026
The videowall measured 1.4 fps on the split-flap board -- about 700ms a frame -- on
an RTX PRO 4000 Blackwell with gpu_compositing enabled, where the same board runs at
118.9 fps in a harness. The instrumentation added in #271 is what made that visible.

The cause is the Art-Net frame observer (#59), and it was wrong in two ways that
compounded.

**It was registered unconditionally at startup**, on the reasoning that "the observer
is a no-op while disabled". That is true of the observer and false of the readback:
gl-base reads the frame BEFORE calling anyone, so the wall paid the full cost with
`artnetEnabled: false` in its settings the entire time. Every stall fed a callback
that did nothing.

**The readback was never rate-limited.** The doc said observers were "expected to
rate-limit itself" -- impossible, because by the time an observer is called the
pixels have already been read. The Art-Net client sends at 1Hz while the readback ran
at frame rate, so 59 of every 60 were discarded.

Each notify is TILES_X*TILES_Y = 32 synchronous gl.readPixels. On a discrete GPU each
one is a pipeline stall plus a PCIe transfer; dual view runs two boards as two
runtimes, so 64 stalls per frame. 700ms / 64 is about 11ms each, which is what a
synchronous readback costs on that hardware.

**Why this was missed for so long, and why I refuted it once already.** I measured
this exact hypothesis yesterday and got 4% -- on Apple Silicon, where unified memory
makes readPixels close to a memcpy. The figure was correct for that machine and
worthless as a prediction for a discrete GPU. Measuring on the development machine
was the mistake, not the reasoning.

Two changes, both small:

- the observer is registered only while Art-Net is enabled, re-evaluated on every
  settings save so toggling without a restart still works -- the property the
  unconditional registration was protecting
- the readback is rate-limited in gl-base to 1Hz, so the feature is usable on a
  discrete GPU even when it IS enabled

9 new tests, 629 -> 638. Reverting the conditional registration fails 5; removing the
rate limit fails 1.

Not yet confirmed on the wall: the fix is expected to take the board from 1.4 fps back
towards its harness figure, and #271's report is how that gets verified rather than
assumed. The 1.4 fps baseline was deliberately captured before this change for exactly
that comparison.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant