diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 67788396..a35d642c 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -334,7 +334,7 @@ service's user. | line | what it tells you | |---|---| | **Late frames** | Frames presented one or more refreshes after they were due: the panel showed the previous frame again, a visible hitch. **The pass/fail number**, 0.1% by default (`--max-late-pct`). Only intervals between two scrolling frames count, and a frame held for `frame_hold` refreshes is due `frame_hold` refreshes after the last. | -| **Freezes** | Gaps of 250 ms or more inside a scroll: recomposes, plugin handovers, blocking calls on the render thread. Reported but not failed on, because some are handovers between plugins rather than faults. | +| **Freezes** | Gaps of 250 ms or more inside a scroll: recomposes, plugin handovers, blocking calls on the render thread. Reported but not failed on, because some are handovers between plugins rather than faults. A gap still counts when the display's scroll state went missing across it (it expires after 2 s, and plugins clear it from their own `display()`), as long as the scroll carries on straight after. | | **blit** | Copying the frame into the matrix canvas (`SetImage`). It grows with width × height × `pwm_bits`: ~5.5 ms at 512×64 with 8 bits on a Pi 4. It is the biggest fixed cost, and it sets the refresh rates a rig can hold one pixel per refresh at. | | **wait** | Time blocked in `SwapOnVSync`, i.e. the slack left in each refresh. A p50 near zero means the rig has no headroom and anything extra lands a frame late. | | **work** | Everything else between two frames: drawing, scrolling, and waiting for the GIL. A wide gap between its p50 and p99 is another thread getting in the way. | diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index 2c151f3a..9a39290b 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -19,6 +19,19 @@ Only intervals between two consecutive *scrolling* frames count: a static screen that changes once a second has no timing to get wrong, and the first frame of a scroll has no predecessor worth measuring against. +"Scrolling" is DisplayManager's scroll state when the frame is presented, and +that state can go missing in the middle of a scroll. It expires after 2s +without scroll activity, which a long enough stall outlasts, and any thread can +clear it: plugins call ``set_scrolling_state(False)`` from their own +``display()``, and Vegas captures some of those on the render thread between +two of its frames. The frame after that is recorded as static, and the interval +it ends -- the stall, or the capture -- would vanish from the report. So a +single static frame between two scrolling ones, with the scroll picking up +again within ``RESUME_SECONDS``, is treated as a frame of the scroll: both of +its intervals count. A second static frame in a row means the scroll really +ended. (On hdpi on 2026-09-24 the watchdog logged a 1.9s stall that the soak +report did not have; this is how.) + A frame held for ``hold`` refreshes should arrive ``hold`` refresh periods after the one before it. One that arrives a whole refresh or more after that is **late**: the panel showed the previous frame again, which on a moving strip is @@ -94,12 +107,16 @@ BUCKET_COUNT = 256 #: See the module docstring. FREEZE_SECONDS = 0.25 -#: Two frames that are both "scrolling" can be at most DisplayManager's -#: scroll_inactivity_threshold (2s) apart: after that the second is recorded -#: as static. This used to be 1s, which silently dropped every 1-2s stall -#: inside a scroll. It is now only a sanity bound. +#: Intervals this long are not frames of one scroll. This used to be 1s, +#: which silently dropped every 1-2s stall inside a scroll. It is now only a +#: sanity bound. GAP_SECONDS = 5.0 +#: A frame recorded as static between two scrolling frames is a frame of the +#: scroll whose state went missing, if the scroll resumes within this long. +#: See "What is counted". +RESUME_SECONDS = 1.0 + #: Buckets for freeze length, as cumulative counters a soak can difference. FREEZE_BUCKETS = ((0.5, "<0.5s"), (1.0, "0.5-1s"), (2.0, "1-2s"), (float("inf"), "2s+")) @@ -232,6 +249,9 @@ class FrameTimingRecorder: self._pending: List[Tuple[float, float, float, int]] = [] self._static_frames = 0 self._previous: Optional[Tuple[float, bool, int]] = None + # The interval ended by a static frame that followed a scrolling one, + # until the next frame shows whether the scroll went on. + self._unsure: Optional[Tuple[float, float, float, int]] = None self._last_flush: Optional[float] = None self._queue: "queue.SimpleQueue" = queue.SimpleQueue() self._worker: Optional[threading.Thread] = None @@ -284,13 +304,28 @@ class FrameTimingRecorder: self.last_frame = (presented_at, scrolling, threading.get_ident()) if not scrolling: self._static_frames += 1 + # The scroll ended, or its state went missing for this frame: the + # next frame says which. Its hold may have been dropped with the + # state, so the interval is due at the scroll's own. + self._unsure = None + if previous is not None and previous[1]: + self._unsure = (presented_at - previous[0], blit, wait, previous[2]) elif self.watchdog is None and self.scrolling_now is not None \ and os.environ.get("LEDMATRIX_STALL_WATCHDOG", "1") != "0": self.watchdog = StallWatchdog(self, **watchdog_settings()) self.watchdog.start() - elif previous is not None and previous[1]: + elif previous is not None: interval = presented_at - previous[0] - if interval < GAP_SECONDS: + unsure, self._unsure = self._unsure, None + if previous[1]: + if interval < GAP_SECONDS: + self._pending.append((interval, blit, wait, hold)) + elif unsure is not None and interval < RESUME_SECONDS: + # One static frame between two scrolling ones: the scroll never + # stopped, only its state did. Both intervals were motion. + self._static_frames -= 1 + if unsure[0] < GAP_SECONDS: + self._pending.append(unsure) self._pending.append((interval, blit, wait, hold)) if self._last_flush is None: diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index c2f27b62..f3238212 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -121,6 +121,72 @@ def test_a_stall_between_one_and_two_seconds_is_not_lost(tmp_path): assert _aggregate(r)["freezes"] == 1 +def test_a_stall_whose_scroll_state_went_missing_still_counts(tmp_path): + # hdpi, 14:48: the watchdog logged a 1.9s stall the soak never reported. + # A plugin captured between two Vegas frames cleared the scroll state, so + # the frame that ended the stall was recorded as static and its interval + # dropped. Vegas set the state again right after, as it does every frame. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + t += 1.911 + r.record(0.002, 0.004, 1, False, t) # state missing: "static" + _feed(r, [PERIOD] * 100, start=t + PERIOD) # the scroll carries on + totals = _aggregate(r) + assert totals["freezes"] == 1 + assert totals["freeze_by"]["1-2s"] == 1 + assert totals["static_frames"] == 0 + # 100 before, the step back into the scroll, 100 after: all but the freeze. + assert totals["scroll_frames"] == 100 + 1 + 100 + + +def test_a_frame_with_its_scroll_state_missing_is_still_timed(tmp_path): + # No stall at all -- the state was cleared and the frame went out on + # time. Nothing is late and no interval is lost. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + r.record(0.002, 0.004, 1, False, t + PERIOD) + _feed(r, [PERIOD] * 100, start=t + 2 * PERIOD) + totals = _aggregate(r) + assert totals["scroll_frames"] == 202 + assert totals["late_frames"] == totals["freezes"] == totals["static_frames"] == 0 + + +def test_a_scroll_that_really_ended_is_not_a_freeze(tmp_path): + # Two static frames in a row, then a new scroll: the gaps between them + # were a static screen, not a stall. + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + t = _feed(r, [0.5], scrolling=False, start=t + 0.3) + _feed(r, [PERIOD] * 100, start=t + 0.4) + totals = _aggregate(r) + assert totals["freezes"] == 0 + assert totals["static_frames"] == 2 + assert totals["scroll_frames"] == 200 + + +def test_one_static_frame_then_a_scroll_much_later_is_a_new_scroll(tmp_path): + r = _recorder(tmp_path) + t = _feed(r, [PERIOD] * 100) + r.record(0.002, 0.004, 1, False, t + 0.3) + _feed(r, [PERIOD] * 100, start=t + 0.3 + frame_timing.RESUME_SECONDS + 0.1) + totals = _aggregate(r) + assert totals["freezes"] == 0 + assert totals["static_frames"] == 1 + assert totals["scroll_frames"] == 200 + + +def test_a_missing_state_interval_is_due_at_the_scrolls_own_hold(tmp_path): + # Clearing the state drops the hold to 1 as well, so the "static" frame + # reports hold 1. Its interval is still due two refreshes after the last. + r = _recorder(tmp_path) + t = _feed(r, [2 * PERIOD] * 100, hold=2) + r.record(0.002, 0.004, 1, False, t + 2 * PERIOD) + _feed(r, [2 * PERIOD] * 100, hold=2, start=t + 4 * PERIOD) + totals = _aggregate(r) + assert totals["late_frames"] == totals["early_frames"] == 0 + assert totals["scroll_frames"] == 202 + + def test_early_frames_are_counted(tmp_path): # Hold 2 on a 100Hz panel: frames are due every 20ms. A swap that returns # after 10ms did not wait out the hold.