From 6031e70525392be600f5a368ccb7bf5209171c14 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 3 Sep 2026 21:41:33 -0400 Subject: [PATCH] fix(scroll): report the frame-time tail, and stop the row-major blit Two problems, both found by looking at the panel rather than the metric. The frame-stats line reported ONE instantaneous frame every 5 seconds -- about 1 frame in 500 -- printed beside a 100-frame average. Both hide exactly the fault they are used to chase: a 2ms duplicate and a 21ms double-wait average to precisely 10ms, so a ticker stalling on half its frames still reports a healthy "Avg FPS: 100.0". That reading cost several rounds of chasing the wrong layer. The line now aggregates every frame since the last log and reports median, p95, max, min, and explicit stall and skip rates (past 1.5x the median missed a refresh; under half never reached the panel, because dirty tracking skipped the swap so the frame never waited on vsync). On the hardware this now reads: leaderboard 100.0 fps over 501 frames | median 10.00ms p95 10.05ms max 10.34ms | stalls 0 (0.0%) skips 0 (0.0%) The binding rebuild's blit patch becomes opt-in (RGB_PATCH_BLIT=1, default off). Reordering that loop to row-major changes what a torn frame looks like: column-major tearing shows as a vertical seam, row-major as a horizontal split between the panel's upper and lower halves. On a 1/32 scan panel that reads as a one-pixel fold across the middle of every panel, which is what was reported on hardware and what went away when the blit was reverted. All of the measured gain comes from the SwapOnVSync change, so the risky half is simply not worth taking; the header says so. Also fixes --install resolving its paths against $HOME, which is /root under sudo, so it looked in /root/rgbmatrix-nogil-build and died with "no built module found" on a machine where the build had just succeeded. It now resolves SUDO_USER's home. Both build paths are verified on the Pi: default yields one GIL-release site, RGB_PATCH_BLIT=1 yields two. Co-Authored-By: Claude Opus 5 --- scripts/build_rgbmatrix_nogil.sh | 181 ++++++++++++++++++------------- src/common/scroll_helper.py | 41 +++++-- 2 files changed, 142 insertions(+), 80 deletions(-) diff --git a/scripts/build_rgbmatrix_nogil.sh b/scripts/build_rgbmatrix_nogil.sh index 959a6c4d..c38e550a 100644 --- a/scripts/build_rgbmatrix_nogil.sh +++ b/scripts/build_rgbmatrix_nogil.sh @@ -15,11 +15,17 @@ # Measured on a Pi 4 driving a 2x128x64 chain at limit_refresh_rate_hz=100: # # before ~44 fps average, 14-17% of frames 41-53ms -# after 100 fps locked, no stalls observed +# after 100 fps, median 10.00ms, p95 10.05ms, 0% stalls # -# This script also releases the GIL across the per-pixel blit -# (SetPixelsPillow) and walks the Pillow buffer row-major instead of -# column-major so each row is contiguous. +# The per-pixel blit (SetPixelsPillow) can also release the GIL and walk the +# Pillow buffer row-major, but that is OFF by default and you almost certainly +# want to leave it that way. Row-major changes what a partially-written frame +# looks like: column-major tearing shows as a vertical seam, row-major tearing +# shows as a horizontal split between the panel's upper and lower halves. On a +# 1/32 scan panel that reads as a one-pixel "fold" across the middle of every +# panel -- reported on hardware, and it went away when the blit was reverted. +# Enable with RGB_PATCH_BLIT=1 only if you have measured that you need it; +# essentially all of the gain above comes from the SwapOnVSync change alone. # # SAFETY # ------ @@ -35,10 +41,19 @@ # set -uo pipefail -SRC_TREE="${RGB_SRC_TREE:-$HOME/LEDMatrix/rpi-rgb-led-matrix-master}" -BUILD_DIR="${RGB_BUILD_DIR:-$HOME/rgbmatrix-nogil-build}" -VENV="${RGB_CYTHON_VENV:-$HOME/.cache/ledmatrix-cython}" -BACKUP="${RGB_BACKUP:-$HOME/rgbmatrix-core.so.ORIGINAL}" +# Resolve the invoking user's home, not root's. --install runs under sudo, +# where $HOME is /root, so every default path below pointed somewhere the +# build had never written and the install died with "no built module found". +if [ -n "${SUDO_USER:-}" ]; then + OWNER_HOME="$(getent passwd "$SUDO_USER" | cut -d: -f6)" +fi +OWNER_HOME="${OWNER_HOME:-$HOME}" + +SRC_TREE="${RGB_SRC_TREE:-$OWNER_HOME/LEDMatrix/rpi-rgb-led-matrix-master}" +BUILD_DIR="${RGB_BUILD_DIR:-$OWNER_HOME/rgbmatrix-nogil-build}" +VENV="${RGB_CYTHON_VENV:-$OWNER_HOME/.cache/ledmatrix-cython}" +BACKUP="${RGB_BACKUP:-$OWNER_HOME/rgbmatrix-core.so.ORIGINAL}" +PATCH_BLIT="${RGB_PATCH_BLIT:-0}" die() { echo "FATAL: $*" >&2; exit 1; } @@ -51,7 +66,7 @@ abi_so() { } do_rollback() { - local dst; dst="$(py_site)" || die "rgbmatrix not importable" + local dst; dst="$(py_site)" [ -n "$dst" ] || die "could not locate the installed rgbmatrix package" [ -f "$BACKUP" ] || die "no backup at $BACKUP" systemctl stop ledmatrix 2>/dev/null @@ -115,83 +130,100 @@ rm -rf "$BUILD_DIR" cp -r "$SRC_TREE" "$BUILD_DIR" || die "copy failed" echo "==> patching the bindings to release the GIL" -python3 - "$BUILD_DIR" <<'PYEOF' || die "patch failed" -import io, sys -base = sys.argv[1] + "/bindings/python/rgbmatrix/" +python3 - "$BUILD_DIR" "$PATCH_BLIT" <<'PYEOF' || die "patch failed" +import io +import sys +base = sys.argv[1] + "/bindings/python/rgbmatrix/" +patch_blit = len(sys.argv) > 2 and sys.argv[2] == "1" + +# --- declare SwapOnVSync as nogil --------------------------------------- p = base + "cppinc.pxd" s = io.open(p, encoding="utf-8").read() -old = " FrameCanvas *SwapOnVSync(FrameCanvas*, uint8_t)\n" -new = " FrameCanvas *SwapOnVSync(FrameCanvas*, uint8_t) nogil\n" -if old in s: - io.open(p, "w", encoding="utf-8", newline="\n").write(s.replace(old, new, 1)) +OLD_DECL = " FrameCanvas *SwapOnVSync(FrameCanvas*, uint8_t)\n" +NEW_DECL = " FrameCanvas *SwapOnVSync(FrameCanvas*, uint8_t) nogil\n" +if OLD_DECL in s: + io.open(p, "w", encoding="utf-8", newline="\n").write(s.replace(OLD_DECL, NEW_DECL, 1)) print(" cppinc.pxd: SwapOnVSync declared nogil") -elif new in s: +elif NEW_DECL in s: print(" cppinc.pxd: already nogil") else: sys.exit("could not find the SwapOnVSync declaration") +# --- release the GIL across the vsync wait ------------------------------ p = base + "core.pyx" s = io.open(p, encoding="utf-8").read() -old = """ def SwapOnVSync(self, FrameCanvas newFrame, uint8_t framerate_fraction = 1): - return __createFrameCanvas(self.__matrix.SwapOnVSync(newFrame.__canvas, framerate_fraction)) -""" -new = """ def SwapOnVSync(self, FrameCanvas newFrame, uint8_t framerate_fraction = 1): - # Blocks until the panel's next vertical sync. Holding the GIL across - # that wait starves every other Python thread for most of each frame. - cdef cppinc.RGBMatrix* matrix = self.__matrix - cdef cppinc.FrameCanvas* frame = newFrame.__canvas - cdef uint8_t fraction = framerate_fraction - cdef cppinc.FrameCanvas* swapped - with nogil: - swapped = matrix.SwapOnVSync(frame, fraction) - return __createFrameCanvas(swapped) -""" -if old in s: - s = s.replace(old, new, 1) +OLD_SWAP = ( + " def SwapOnVSync(self, FrameCanvas newFrame, uint8_t framerate_fraction = 1):\n" + " return __createFrameCanvas(" + "self.__matrix.SwapOnVSync(newFrame.__canvas, framerate_fraction))\n" +) +NEW_SWAP = ( + " def SwapOnVSync(self, FrameCanvas newFrame, uint8_t framerate_fraction = 1):\n" + " # Blocks until the panel's next vertical sync. Holding the GIL\n" + " # across that wait starves every other Python thread for most of\n" + " # each frame. Pointers are hoisted into C locals so the blocking\n" + " # call itself needs no Python state.\n" + " cdef cppinc.RGBMatrix* matrix = self.__matrix\n" + " cdef cppinc.FrameCanvas* frame = newFrame.__canvas\n" + " cdef uint8_t fraction = framerate_fraction\n" + " cdef cppinc.FrameCanvas* swapped\n" + " with nogil:\n" + " swapped = matrix.SwapOnVSync(frame, fraction)\n" + " return __createFrameCanvas(swapped)\n" +) +if OLD_SWAP in s: + s = s.replace(OLD_SWAP, NEW_SWAP, 1) print(" core.pyx: SwapOnVSync releases the GIL") -elif "with nogil:\n swapped = matrix.SwapOnVSync" in s: +elif "swapped = matrix.SwapOnVSync(frame, fraction)" in s: print(" core.pyx: SwapOnVSync already patched") else: sys.exit("could not find the SwapOnVSync body") -old = """ buffer = get_pillow_buffer(image_capsule) - - for col in range(max(0, -xstart), min(width, frame_width - xstart)): - for row in range(max(0, -ystart), min(height, frame_height - ystart)): - pixel = buffer[row][col] - r = (pixel ) & 0xFF - g = (pixel >> 8) & 0xFF - b = (pixel >> 16) & 0xFF - my_canvas.SetPixel(xstart+col, ystart+row, r, g, b) -""" -new = """ buffer = get_pillow_buffer(image_capsule) - - # Bounds hoisted so the blit needs no Python state and can run without - # the GIL: it touches only a C buffer and a C++ canvas. Row-major order - # walks each row contiguously; col-outer re-strided the whole buffer. - cdef int col_start = max(0, -xstart) - cdef int col_end = min(width, frame_width - xstart) - cdef int row_start = max(0, -ystart) - cdef int row_end = min(height, frame_height - ystart) - - with nogil: - for row in range(row_start, row_end): - for col in range(col_start, col_end): - pixel = buffer[row][col] - r = (pixel ) & 0xFF - g = (pixel >> 8) & 0xFF - b = (pixel >> 16) & 0xFF - my_canvas.SetPixel(xstart+col, ystart+row, r, g, b) -""" -if old in s: - s = s.replace(old, new, 1) - print(" core.pyx: pixel blit releases the GIL, row-major") -elif "with nogil:\n for row in range(row_start, row_end):" in s: - print(" core.pyx: blit already patched") +# --- optional: release the GIL across the blit -------------------------- +OLD_BLIT = ( + " buffer = get_pillow_buffer(image_capsule)\n" + "\n" + " for col in range(max(0, -xstart), min(width, frame_width - xstart)):\n" + " for row in range(max(0, -ystart), min(height, frame_height - ystart)):\n" + " pixel = buffer[row][col]\n" + " r = (pixel ) & 0xFF\n" + " g = (pixel >> 8) & 0xFF\n" + " b = (pixel >> 16) & 0xFF\n" + " my_canvas.SetPixel(xstart+col, ystart+row, r, g, b)\n" +) +NEW_BLIT = ( + " buffer = get_pillow_buffer(image_capsule)\n" + "\n" + " # Bounds hoisted so the blit needs no Python state and can run\n" + " # without the GIL: it touches only a C buffer and a C++ canvas.\n" + " # NOTE: row-major order makes a torn frame show as a horizontal\n" + " # split across the panel's halves. See the header before enabling.\n" + " cdef int col_start = max(0, -xstart)\n" + " cdef int col_end = min(width, frame_width - xstart)\n" + " cdef int row_start = max(0, -ystart)\n" + " cdef int row_end = min(height, frame_height - ystart)\n" + "\n" + " with nogil:\n" + " for row in range(row_start, row_end):\n" + " for col in range(col_start, col_end):\n" + " pixel = buffer[row][col]\n" + " r = (pixel ) & 0xFF\n" + " g = (pixel >> 8) & 0xFF\n" + " b = (pixel >> 16) & 0xFF\n" + " my_canvas.SetPixel(xstart+col, ystart+row, r, g, b)\n" +) +if patch_blit: + if OLD_BLIT in s: + s = s.replace(OLD_BLIT, NEW_BLIT, 1) + print(" core.pyx: pixel blit releases the GIL, row-major") + elif "for row in range(row_start, row_end):" in s: + print(" core.pyx: blit already patched") + else: + sys.exit("could not find the SetPixelsPillow loop") else: - sys.exit("could not find the SetPixelsPillow loop") + print(" core.pyx: blit left unpatched (RGB_PATCH_BLIT=1 to enable)") io.open(p, "w", encoding="utf-8", newline="\n").write(s) PYEOF @@ -231,12 +263,15 @@ echo "==> compiling the extension" SO="$(abi_so)"; [ -n "$SO" ] || die "no .so produced" # Verify the GIL really is released before anyone installs this. -PAIRS=$(grep -c "PyEval_SaveThread\|Py_UNBLOCK_THREADS" "$BUILD_DIR/bindings/python/rgbmatrix/core.cpp") -[ "$PAIRS" -ge 2 ] || die "generated C++ has only $PAIRS GIL releases, expected >= 2" +EXPECTED=1; [ "$PATCH_BLIT" = "1" ] && EXPECTED=2 +PAIRS=$(grep -c "PyEval_SaveThread\|Py_UNBLOCK_THREADS" \ + "$BUILD_DIR/bindings/python/rgbmatrix/core.cpp") +[ "$PAIRS" -ge "$EXPECTED" ] \ + || die "generated C++ has $PAIRS GIL-release sites, expected >= $EXPECTED" echo echo "BUILT: $SO" -echo " ($PAIRS GIL-release sites in the generated C++)" +echo " ($PAIRS GIL-release site(s) in the generated C++)" echo -echo "Install with: sudo bash $0 --install" +echo "Install with: sudo bash $0 --install" echo "Roll back with: sudo bash $0 --rollback" diff --git a/src/common/scroll_helper.py b/src/common/scroll_helper.py index 5b34cfe0..34ba3dd1 100644 --- a/src/common/scroll_helper.py +++ b/src/common/scroll_helper.py @@ -116,6 +116,9 @@ class ScrollHelper: self.last_frame_time = time.time() self.last_fps_log_time = time.time() self.frame_times = [] + # Every frame time since the last stats line, so the 5s summary can + # report the tail rather than one arbitrary sample. Cleared on log. + self._window: list = [] # Scrolling state management self.is_scrolling = False @@ -1040,18 +1043,42 @@ class ScrollHelper: # Keep only last 100 frames for average if len(self.frame_times) > 100: self.frame_times.pop(0) + + # Every frame since the last log, not just the last 100 and not just + # the one that happens to land on the 5s boundary. The old line + # reported a single instantaneous sample -- roughly 1 frame in 500 -- + # which cannot see a stall that hits 1% of frames, and reported it + # next to an average that hides the same stall by construction (a 2ms + # duplicate and a 21ms double-wait mean exactly 10ms). Chasing scroll + # judder needs the tail, so keep the window and report percentiles. + self._window.append(frame_time) # Log FPS every 5 seconds to avoid spam if current_time - self.last_fps_log_time >= 5.0: - avg_frame_time = sum(self.frame_times) / len(self.frame_times) - avg_fps = 1.0 / avg_frame_time if avg_frame_time > 0 else 0 - instant_fps = 1.0 / frame_time if frame_time > 0 else 0 - - self.logger.info(f"Scroll frame stats - Avg FPS: {avg_fps:.1f}, " - f"Current FPS: {instant_fps:.1f}, " - f"Frame time: {frame_time*1000:.2f}ms") + window = sorted(self._window) if self._window else [frame_time] + n = len(window) + median = window[n // 2] + p95 = window[min(n - 1, int(n * 0.95))] + worst = window[-1] + best = window[0] + mean = sum(window) / n + # Anything past 1.5x the median missed a panel refresh; anything + # under half of it never reached the panel at all (dirty tracking + # skipped the swap, so the frame did not wait for vsync). + stalls = sum(1 for f in window if f > median * 1.5) + skips = sum(1 for f in window if f < median * 0.5) + + self.logger.info( + "Scroll frame stats - %.1f fps over %d frames | " + "median %.2fms p95 %.2fms max %.2fms min %.2fms | " + "stalls %d (%.1f%%) skips %d (%.1f%%)", + (1.0 / mean) if mean > 0 else 0.0, n, + median * 1000, p95 * 1000, worst * 1000, best * 1000, + stalls, 100.0 * stalls / n, skips, 100.0 * skips / n, + ) self.last_fps_log_time = current_time self.frame_count = 0 + self._window = [] self.last_frame_time = current_time self.frame_count += 1