diff --git a/CHANGELOG.md b/CHANGELOG.md index 03dff2f8..02d153d1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -122,6 +122,37 @@ policies are unchanged. until the next minute, because the once-a-minute schedule check had already run that minute and the session had overridden its answer. +### Scroller-to-static handovers + +- A static plugin screen that follows a scroller no longer starts with the + scroller's leftovers. Nothing ended the scroll state at a handover; it + expired 2 s after the last scroll frame. So on a panel with scan-order + compensation the static screen's first frame went out with the lagging + rows (the bottom half on a 96x48 panel) taken from the ticker's last + frame: for the whole second it stays up after a scroll at one frame per + refresh, and for its first refresh after a slower, held one. The display + controller now calls the new + `DisplayManager.end_scroll_for_static_screen()` just before such a + screen's first `display()`, so the frames that call draws go out as + drawn, in one swap each, and `set_scrolling_state(False)` once it + returns. The scroll state and its frame hold stay until then, so the + handover is still timed, against the scroller's own pacing: late-frame + counts are unchanged. +- The phantom ~1 s freeze when a static plugin screen follows a scroller is + no longer recorded: the 1 Hz loop's second frame was timed as a frame of the old + scroll, in the soak's freezes and as a `Render stall` in the log. On ledpi + that was 17 of 31 `Render stall over` lines (2026-09-15 to 10-01). +- A screen's first frame is tagged `handover` in the frame stats, every + turn's, also when the rotation comes back to the same mode. A gap of + 250 ms or more before it is counted in the new `handover_freezes` + (additive; the schema version is unchanged), not in `freezes` / + `freeze_by`, and `frame_soak.py` prints it as "Handover gaps": a + scroller rebuilding its content at the start of a turn shows up there. + **Freeze counts from soaks before and after this change are not + comparable.** A stall dump taken while that first `display()` is still + drawing says `in a handover gap` instead of `mid-scroll`, and the call + runs on a thread named `display-`. + ## 3.8.0 Live Vegas elements: plugin content that keeps changing while it scrolls diff --git a/docs/RUN_LOOP_REDESIGN.md b/docs/RUN_LOOP_REDESIGN.md index 668d7d93..dafe195a 100644 --- a/docs/RUN_LOOP_REDESIGN.md +++ b/docs/RUN_LOOP_REDESIGN.md @@ -232,7 +232,11 @@ its prefetch inline. Verify with a Vegas soak on ledpi, A/B. Plugins declare `frame_policy` (STATIC, PERIODIC(hz), ANIMATED(fps), SCROLL). `_needs_high_fps` becomes the mapping for legacy plugins (`needs_high_fps`, the `static-image` special case, `enable_scrolling`), -and its per-screen INFO line drops to DEBUG. +and its per-screen INFO line drops to DEBUG. It is already read twice per +screen: once quietly before the first frame, so `_dispatch_first_frame` can +end the previous scroll for a screen that runs the 1 Hz loop +(`_start_screen_handover`), and once after it to pick the loop. A declared +policy answers both. ## How each stage is verified diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 3baa8ad7..84761abd 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -341,12 +341,13 @@ 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. A gap still counts when the display's scroll state went missing for one frame across it, as long as scrolling resumes within 1 s: both of that frame's intervals count. Two static frames in a row end the scroll. (The state expires after 2 s without scroll activity, and plugins can clear it from their own `display()`.) The late and early rates are over frames judged against a known refresh period, which the recorder adopts once two windows in a row agree on it. | +| **Freezes** | Gaps of 250 ms or more inside a scroll: recomposes, plugin handovers the display controller does not tag (see *Handover gaps*), 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 for one frame across it, as long as scrolling resumes within 1 s: both of that frame's intervals count. Two static frames in a row end the scroll. (The state expires after 2 s without scroll activity, and plugins can clear it from their own `display()`.) The late and early rates are over frames judged against a known refresh period, which the recorder adopts once two windows in a row agree on it. Handovers to a static screen no longer show up here: the display controller ends the scroll state after a static screen's first frame, where it used to linger for 2 s and turn the 1 Hz loop's second frame into a ~1 s "freeze" (17 of 31 `Render stall over` lines on ledpi, 2026-09-15 to 10-01). **Freeze counts from before and after that change are not comparable.** | +| **Handover gaps** | Gaps of 250 ms or more from a scroll's last frame to the next screen's first: the next plugin drawing, not a scroll stalling. The display controller tags that first frame `handover`, and these gaps are counted here instead of under Freezes (`handover_freezes` in the stats; the `handover` row under *after work* counts the same ones in its freezes column). Every turn's first frame is tagged, also when the rotation comes back to the same mode (a one-mode rotation, a pinned on-demand mode, live priority holding a screen), so a scroller rebuilding its content at the start of a turn is counted here; measure work on that rebuild with this line, not Freezes. Missing from stats written by an older service, whose freezes include them. | | **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. | | **Binding** | `STOCK` means the rgbmatrix binding holds the GIL through the vsync wait, which starves every other thread. See *Rebuilding the binding*. | -| **after work** | Frames presented straight after tagged render-thread work, with their own late rate: `extend` and `compose` (Vegas building its strip), `patch` (live elements, once they land). A kind whose late rate sits well above the overall one is the work making frames late. Shown only when something tagged its work. | +| **after work** | Frames presented straight after tagged render-thread work, with their own late rate: `extend` and `compose` (Vegas building its strip), `patch` (live elements, once they land), `handover` (a new screen's first frame). A kind whose late rate sits well above the overall one is the work making frames late. Shown only when something tagged its work. | The refresh rate is estimated from the frames themselves (swaps that block on vsync can only land on refresh boundaries). Cross-check it with @@ -360,10 +361,13 @@ A/B two of them. A live-API workload drifts over time. The soak says how often; the service's log says why. A scroll that presents no frame for 250 ms logs `Render stall:` with the stack of the render thread and the top of every other thread's, and whether the whole interpreter was blocked -(C code holding the GIL) rather than one thread. To see what is behind the -shorter hitches, run the service with `LEDMATRIX_STALL_WATCHDOG_MS=30`, which -dumps at three refreshes late instead: its extra polling costs a little GIL -time of its own, so do that on a diagnostic run, not a soak you are grading. +(C code holding the GIL) rather than one thread. A stall while the next +screen's first `display()` is still drawing says `in a handover gap` instead of +`mid-scroll`; that call runs on a thread named `display-`. To see +what is behind the shorter hitches, run the service with +`LEDMATRIX_STALL_WATCHDOG_MS=30`, which dumps at three refreshes late instead: +its extra polling costs a little GIL time of its own, so do that on a +diagnostic run, not a soak you are grading. `LEDMATRIX_STALL_WATCHDOG=0` turns it off. ### Results: hdpi, 2026-09-24 @@ -540,6 +544,31 @@ for the rest, so it steps one refresh after the rest rather than one frame. That costs a second blit inside the refresh after the first swap, so it is skipped when a blit takes more than half a refresh. +A plugin screen that runs the 1 Hz loop after a scroll is not composed: the +display controller calls `DisplayManager.end_scroll_for_static_screen()` before +its first `display()`, so the frames that call presents go out as drawn, in one +swap each, instead of with the lagging half taken from the scroller's last +frame. + +Other screens that follow a scroll still are, while the scroll state lasts (it +expires 2 s after the scroller's last frame). Their first frame takes its +lagging half from the scroller's last frame: for one refresh after a held +scroll, and after a scroll at one frame per refresh until the next frame +replaces it. They are: + +- the blank shown when the schedule turns the panel off. It is redrawn once a + minute while the panel is off, so half of the scroller's last frame can stay + lit for up to 60 s; +- the WiFi status message, until the next pass half a second later; +- a screen that runs the high-FPS loop without scrolling (an older + `static-image`, which is forced into it), until its next frame. + +The frame stats still time those two as frames of the old scroll: a WiFi +notice that preempts a scroller records up to three 0.5-1 s freezes, and the +schedule-off blank a `Render stall ... mid-scroll`. Ending the scroll state +before the schedule-off blank and the WiFi message is a follow-up, the +schedule-off blank first. + Checked on hdpi (4×128×64 on one chain, rotated 180, 2026-09-24) before it was written: `scan_mode: 1` (interlaced) made the step vanish but turned moving edges grainy, and halving the speed halved it, so it is the scan and not a torn diff --git a/scripts/frame_soak.py b/scripts/frame_soak.py index 1d347567..90082311 100644 --- a/scripts/frame_soak.py +++ b/scripts/frame_soak.py @@ -27,9 +27,16 @@ What the numbers mean late frames frames that reached the panel one or more refreshes after they were due -- the panel showed the previous frame again, which on a moving strip is a visible hitch. This is the pass/fail number. -freezes gaps of 250ms+ inside a scroll: recomposes, plugin handovers, +freezes gaps of 250ms+ inside a scroll: recomposes, plugin handovers + the display controller does not tag (see handover gaps), blocking calls on the render thread. Reported, not failed on, since some are handovers between plugins rather than faults. +handover gaps the same length of gap where the display controller had just + started a screen's turn (also the same mode's again): its + first display() drawing. Counted here instead of under + freezes. Stats from a service older than this count have no + such line, and their freezes include these, so do not + compare freeze counts across that change. blit copying the frame into the matrix canvas (rgbmatrix SetImage). Grows with width x height x pwm_bits. wait blocked in SwapOnVSync, i.e. slack before the refresh. @@ -185,6 +192,9 @@ def build_report(before, after, preview: bool) -> Dict[str, Any]: "freezes": totals["freezes"], "freezes_per_hour": round(totals["freezes"] / hours, 1) if hours else None, "freeze_seconds": round(totals["freeze_seconds"], 2), + # None from a service that predates the count: its handovers are + # among the freezes above. + "handover_freezes": totals.get("handover_freezes"), "worst_interval_ms": (round(totals["worst_interval_ms"], 1) if totals["worst_interval_ms"] else None), "timing_ms": {name: percentiles(h, bucket_ms) @@ -240,6 +250,9 @@ def print_report(report: Dict[str, Any], limit: float) -> None: if report["freezes"]: print(" by length: " + ", ".join( f"{k}: {v}" for k, v in report["freeze_by"].items())) + if report.get("handover_freezes") is not None: + print(f"Handover gaps {report['handover_freezes']}" + " >=250ms before a new screen's first frame; not in the freezes") print() print(f"{'ms':<18}{'p50':>8}{'p95':>8}{'p99':>8}{'max':>8}") for name in ("blit", "wait", "work", "interval_per_hold"): diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index dea2fd94..a7d37dd5 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -38,12 +38,20 @@ after the one before it. One that arrives a whole refresh or more after that is a visible hitch. ``missed_refreshes`` sums how many refreshes late. An interval of ``FREEZE_SECONDS`` or more is a **freeze** instead -- a -recompose, a plugin handover, a blocking call on the render thread. Those are -counted separately, both because they are a different fault and because -folding a single 400ms handover into the late count as "40 missed refreshes" -would drown the jitter the late count exists to measure. ``freeze_by`` splits -them by length. Intervals of ``GAP_SECONDS`` or more are ignored as not being -frames of one scroll at all. +recompose, a plugin handover nobody tagged (see below), a blocking call on the +render thread. Those are counted separately, both because they are a different +fault and because folding a single 400ms handover into the late count as "40 +missed refreshes" would drown the jitter the late count exists to measure. +``freeze_by`` splits them by length. Intervals of ``GAP_SECONDS`` or more are +ignored as not being frames of one scroll at all. + +One kind of freeze is not a scroll stalling at all: the gap from one screen's +last frame to the next screen's first, while the next screen draws. The +display controller tags that frame ``handover`` (see "Operations") at the +start of every turn, the same mode's again included, and a tagged freeze is +counted in ``handover_freezes`` instead of ``freezes`` and ``freeze_by``. +Stats written before that field existed have handovers among their freezes, +so freeze counts from before and after it are not comparable. A frame that arrives a whole refresh or more *early* means the swap did not wait for the panel: the emulator, the fallback display, or a hold that was not @@ -77,6 +85,12 @@ the work landed in. ``op_frames`` counts timed frames per kind, freeze instead, and ``op_bytes`` what the work moved. A kind whose late rate sits well above the overall one is the work to look at. +``handover`` (:data:`HANDOVER_OP`) is noted off the render thread: the display +controller notes it just before it starts a screen's first ``display()``, +which presents from a thread of its own, and drops the note again with +:meth:`FrameTimingRecorder.drop_op` once that call returns, so a first +``display()`` that drew nothing cannot leave the tag for an unrelated frame. + Stall watchdog -------------- Counting a freeze says that it happened, not why. ``StallWatchdog`` watches the @@ -133,6 +147,11 @@ RESUME_SECONDS = 1.0 FREEZE_BUCKETS = ((0.5, "<0.5s"), (1.0, "0.5-1s"), (2.0, "1-2s"), (float("inf"), "2s+")) +#: The op the display controller notes before a screen's first frame. A +#: freeze it ends is a handover, counted apart from the freezes; see +#: "What is counted". +HANDOVER_OP = "handover" + #: A window may lower the refresh-period estimate by at most this fraction. MAX_REFRESH_DROP = 0.2 @@ -302,6 +321,10 @@ class FrameTimingRecorder: "freezes": 0, "freeze_seconds": 0.0, "freeze_by": {label: 0 for _, label in FREEZE_BUCKETS}, + # Freezes that ended a screen handover rather than stalled a + # scroll: in neither of the two above. Additive; see "What is + # counted". + "handover_freezes": 0, "worst_interval_ms": 0.0, # Per kind of noted render-thread work; see "Operations". "op_frames": {}, @@ -337,7 +360,8 @@ class FrameTimingRecorder: Render thread only, like :meth:`record`, which consumes the tag: the interval the next frame ends is the one this work landed in. Several - notes before one frame accumulate, per kind. See "Operations". + notes before one frame accumulate, per kind. See "Operations" (and + :data:`HANDOVER_OP`, the one note made from another thread). :param kind: a short name for the work, e.g. ``"extend"``, ``"patch"``. :param nbytes: how much the work moved, summed into ``op_bytes``. @@ -347,6 +371,21 @@ class FrameTimingRecorder: ops = self._ops = {} ops[kind] = ops.get(kind, 0) + int(nbytes) + def drop_op(self, kind: str) -> None: + """Forget a note of ``kind`` that no frame has carried yet. + + For work that may present nothing: the display controller notes a + handover before a screen's first ``display()`` and drops it once that + returns. When the call drew a frame, the frame already took the tag + and this does nothing; when it drew nothing (no content), the tag + would otherwise land on whatever frame came next -- seconds or minutes + later, and nothing to do with the handover. Other kinds noted for the + same frame are kept. + """ + ops = self._ops + if ops is not None: + ops.pop(kind, None) + def record(self, blit: float, wait: float, hold: int, scrolling: bool, presented_at: float) -> None: """One frame reached the panel. @@ -467,13 +506,19 @@ class FrameTimingRecorder: for kind, nbytes in ops.items(): _bump(totals["op_bytes"], kind, nbytes) if interval >= FREEZE_SECONDS: + for kind in ops or (): + _bump(totals["op_freezes"], kind) + if ops and HANDOVER_OP in ops: + # The next screen drawing its first frame, not a scroll + # that stalled: counted apart, so the freezes keep + # meaning the second. See "What is counted". + totals["handover_freezes"] += 1 + continue totals["freezes"] += 1 totals["freeze_seconds"] += interval label = next(name for limit, name in FREEZE_BUCKETS if interval < limit) totals["freeze_by"][label] += 1 - for kind in ops or (): - _bump(totals["op_freezes"], kind) continue totals["scroll_frames"] += 1 for name, value in (("blit", blit), ("wait", wait), @@ -647,11 +692,19 @@ class StallWatchdog: return stall_from, dumped def describe(self, ident: int, age: float, late: float) -> str: - """The stack dump: the stalled thread in full, the rest in brief.""" + """The stack dump: the stalled thread in full, the rest in brief. + + A stall while a ``handover`` note is still waiting for its frame is + the next screen's first ``display()`` taking its time, not a scroll + that stopped, and is labelled a handover gap. + """ names = {t.ident: t.name for t in threading.enumerate()} frames = sys._current_frames() + pending = getattr(self.recorder, "_ops", None) + where = ("in a handover gap" if pending and HANDOVER_OP in pending + else "mid-scroll") lines = [ - f"Render stall: no frame for {age * 1000.0:.0f}ms mid-scroll " + f"Render stall: no frame for {age * 1000.0:.0f}ms {where} " f"(watchdog woke {late * 1000.0:.0f}ms late" + ("; the interpreter itself was blocked" if late >= age / 2 else "") + ")", diff --git a/src/display_controller.py b/src/display_controller.py index fec82702..a22ec555 100644 --- a/src/display_controller.py +++ b/src/display_controller.py @@ -42,6 +42,7 @@ from src.cache_manager import CacheManager from src.font_manager import FontManager from src.logging_config import get_logger from src.exceptions import PluginError +from src.common.frame_timing import HANDOVER_OP from src.common.sync_manager import DisplaySyncManager, SyncRole from src.ipc.server import ControlServer, start_control_server from src.vegas_mode.render_pipeline import SYNC_SEND_INTERVAL @@ -2571,6 +2572,70 @@ class DisplayController: logger.debug(f"Found plugin manager for mode {mode}: {type(plugin_instance).__name__}") return plugin_instance + def _start_screen_handover(self, plugin, active_mode: str) -> bool: + """Before a screen's first dispatch: if the screen is static, keep + the last scroll's leftovers off its first frame. + + Nothing else ends a scroll when the rotation moves on: the state + expires 2 s after the scroller's last frame. Left to that, a static + screen's first frame -- up for a whole second -- went out, on a panel + with scan-order compensation, with rows taken from the scroller's + last frame (after a held scroll, for its first refresh); and its + second frame, 1 s later, was still "mid-scroll", so the frame-timing + soak counted a 1-2 s freeze and the stall watchdog logged a "Render + stall" at every scroller-to-static handover. See + DisplayManager.end_scroll_for_static_screen. + + Returns whether the screen is static, for _finish_screen_handover. + False when that cannot be told, which leaves the scroll state as it + was before this existed. + """ + try: + static_screen = not self._needs_high_fps(plugin, active_mode, log=False) + except Exception: # pylint: disable=broad-except + # A plugin property raising. The FPS check after the dispatch is + # where that is reported; here it only means "leave it alone". + logger.debug("Could not tell whether %s is static before its first frame", + active_mode, exc_info=True) + return False + if static_screen: + end_scroll = getattr(self.display_manager, 'end_scroll_for_static_screen', None) + if end_scroll is not None: + end_scroll() + return static_screen + + def _note_screen_handover(self) -> None: + """Tag the frame the first dispatch is about to present. + + The gap from the last screen's final frame to it is the next screen + drawing, not a scroll freezing: frame_timing counts it apart from + the freezes, and the stall watchdog labels it a handover gap. + """ + recorder = getattr(self.display_manager, 'frame_timing', None) + note = getattr(recorder, 'note_op', None) + if note is not None: + note(HANDOVER_OP) + + def _finish_screen_handover(self, static_screen: bool) -> None: + """After a screen's first dispatch, whatever it returned. + + Drops the handover tag if no frame took it (a screen with nothing to + show), so it cannot land on an unrelated frame later. For a static + screen, also ends the previous scroll now, whether or not it showed + anything: its first frame has gone out, and with the state left set + its next one -- a second later in the 1 Hz loop -- would be timed as + a frame of the old scroll. + """ + dm = self.display_manager + recorder = getattr(dm, 'frame_timing', None) + drop = getattr(recorder, 'drop_op', None) + if drop is not None: + drop(HANDOVER_OP) + if static_screen: + set_scrolling_state = getattr(dm, 'set_scrolling_state', None) + if set_scrolling_state is not None: + set_scrolling_state(False) + def _dispatch_first_frame(self, plugin, active_mode: str) -> Tuple[bool, bool, bool]: """Draw the first frame of a screen through the PluginExecutor. @@ -2592,6 +2657,10 @@ class DisplayController: display_failed_due_to_exception = False _accepts_display_mode = False plugin_id = getattr(plugin, 'plugin_id', active_mode) + # Decided before the first frame rather than at run()'s FPS check + # after it, by when that frame has gone out with the last scroll's + # rows. See _start_screen_handover. + static_screen = self._start_screen_handover(plugin, active_mode) try: logger.debug(f"Calling display() for {active_mode} with force_clear={self.force_change}") if plugin_id not in self._plugin_accepts_display_mode: @@ -2606,6 +2675,10 @@ class DisplayController: display_hung = False # Set when display() raised inside the executor. display_error: Optional[Exception] = None + if can_display: + # Only when display() will run: a busy plugin + # presents nothing for the tag to land on. + self._note_screen_handover() if display_lock is None: # Only when plugin loading failed part-way. @@ -2729,6 +2802,10 @@ class DisplayController: self.force_change = True display_result = False display_failed_due_to_exception = True + # Whatever the dispatch did -- drew, had nothing to show, raised + # inside the executor or out here -- and after the health record, + # before the 1 Hz loop or the next mode. + self._finish_screen_handover(static_screen) return display_result, display_failed_due_to_exception, _accepts_display_mode def _skip_failed_plugin_modes(self, active_mode: str) -> bool: @@ -2878,7 +2955,7 @@ class DisplayController: return None return min_duration, max_duration - def _needs_high_fps(self, plugin, active_mode: str) -> bool: + def _needs_high_fps(self, plugin, active_mode: str, log: bool = True) -> bool: """Whether a screen runs the high-FPS (8 ms) loop or the 1 s one. In precedence order: @@ -2889,29 +2966,36 @@ class DisplayController: the attribute keep the historical forced high-FPS (GIF support). 3. Otherwise scrolling plugins get high FPS. + + ``log=False`` for the look taken before a screen's first dispatch + (see _start_screen_handover): the FPS check after it logs the + decision, and once per screen is enough. """ plugin_id = getattr(plugin, 'plugin_id', None) declared = getattr(plugin, 'needs_high_fps', None) if declared is not None: needs_high_fps = bool(declared) - logger.debug( - "[DisplayController] FPS check for %s (plugin=%s) - " - "plugin declares needs_high_fps=%s", - active_mode, plugin_id, needs_high_fps) + if log: + logger.debug( + "[DisplayController] FPS check for %s (plugin=%s) - " + "plugin declares needs_high_fps=%s", + active_mode, plugin_id, needs_high_fps) elif plugin_id == 'static-image': needs_high_fps = True - logger.debug("FPS check - static-image plugin: forcing high-FPS mode for GIF support") + if log: + logger.debug("FPS check - static-image plugin: forcing high-FPS mode for GIF support") else: has_enable_scrolling = hasattr(plugin, 'enable_scrolling') enable_scrolling_value = getattr(plugin, 'enable_scrolling', False) needs_high_fps = has_enable_scrolling and enable_scrolling_value - logger.info( - "FPS check for %s - has_enable_scrolling: %s, enable_scrolling_value: %s, needs_high_fps: %s", - active_mode, - has_enable_scrolling, - enable_scrolling_value, - needs_high_fps, - ) + if log: + logger.info( + "FPS check for %s - has_enable_scrolling: %s, enable_scrolling_value: %s, needs_high_fps: %s", + active_mode, + has_enable_scrolling, + enable_scrolling_value, + needs_high_fps, + ) return needs_high_fps def _advance_after_screen(self, active_mode: Optional[str]) -> None: @@ -3194,6 +3278,9 @@ class DisplayController: continue min_duration, max_duration = bounds + # High-FPS decision; see _needs_high_fps for the order. + # Read again here, after the first dispatch, as it always + # was: a plugin may settle it in that display() call. needs_high_fps = self._needs_high_fps(manager_to_display, active_mode) target_duration = max_duration diff --git a/src/display_manager.py b/src/display_manager.py index c3d13675..215792e1 100644 --- a/src/display_manager.py +++ b/src/display_manager.py @@ -344,6 +344,10 @@ class DisplayManager: # advances a whole pixel every Nth refresh instead of every one. # See src/common/scroll_config.py and scripts/scroll_speeds.py. self._frame_hold = 1 + # True while a static screen draws its first frame after a scroll, + # whose state is left set until then: those frames go out without + # scan-order compensation. See end_scroll_for_static_screen(). + self._static_handover = False # A src.common.render_gate.RenderGate while Vegas runs with # vegas_scroll.prefetch_gate on: opened around each swap so the @@ -1060,11 +1064,15 @@ class DisplayManager: rows catch up, so those rows step a refresh after the rest. The split needs a second blit inside the refresh that follows the first swap, so it is skipped when a blit is too slow to fit. A static screen goes out - as it is, and drops the history. + as it is, and drops the history. So does a static screen's first frame + after a scroll, while the scroll state is still set (see + end_scroll_for_static_screen): one segment, held for the scroll's + hold, with no rows from the scroller's frames. """ hold = self._frame_hold bands = getattr(self, '_scan_lag_bands', None) - if not bands or not self.is_currently_scrolling(): + if (not bands or not self.is_currently_scrolling() + or self._static_handover): if bands: self._scan_history.clear() return [(image, hold)] @@ -1524,6 +1532,9 @@ class DisplayManager: # A plugin captured for Vegas calls this from its own display(); # it must not change the live scroll's state or frame hold. return + # A scroll starting or ending also ends a static screen's handover; + # see end_scroll_for_static_screen. + self._static_handover = False current_time = time.time() # Scrolling callers set this every frame; log transitions only. changed = self._scrolling_state['is_scrolling'] != is_scrolling @@ -1536,6 +1547,46 @@ class DisplayManager: if changed: logger.debug("Scrolling state set to: %s", is_scrolling) + def end_scroll_for_static_screen(self) -> None: + """Ready the panel for a static screen's first frame after a scroll. + + The display controller calls this just before it dispatches the first + frame of a screen that runs its 1 Hz loop, and + ``set_scrolling_state(False)`` once that dispatch returns. Nothing + else ends a scroll at a handover: the state belongs to the screen + before, and would only expire 2 s after its last frame. + + Until then, the frames that dispatch presents go out as drawn, not + scan-order composed: each as one segment, held for the scroll's hold. + With the state still "scrolling", ``_scan_segments`` would take their + lagging rows from the frame before: for the first, the scroller's last + frame -- the bottom half of the old ticker under the new screen on a + 96x48 panel. At hold 1 that frame stays up for a whole second; at a + longer hold its first refresh flashes the old rows. For a second frame + in the same call, the rows would come from the first. Dirty tracking + compares frames as drawn, so once the scroll is over it skips every + identical 1 Hz redraw of such a frame, and nothing would replace it. + + The rest of that scroll is left on purpose, until the controller ends + it: + + * the scroll state, so the gap from the scroller's last frame to this + screen's first is still timed by the frame-timing recorder and + watched by the stall watchdog, which is where a slow first + ``display()`` shows up; + * its frame hold. On a frame that stays up for a second it only moves + the swap to the scroll's next hold boundary, and it is the pacing + that gap is due at: judged at hold 1, a handover that kept the + scroller's own schedule would count as frames late. + + The next ``set_scrolling_state()`` call, whoever makes it, ends this. + One attribute store, so no lock: ``update_display`` reads it once per + frame, under its own, and the history is dropped there. + """ + if self._writes_suppressed(): + return # a thread drawing off-screen cannot end the live scroll + self._static_handover = True + def is_currently_scrolling(self) -> bool: """Check if the display is currently in a scrolling state.""" current_time = time.time() diff --git a/src/plugin_system/plugin_executor.py b/src/plugin_system/plugin_executor.py index 7c811f6f..b8cfed15 100644 --- a/src/plugin_system/plugin_executor.py +++ b/src/plugin_system/plugin_executor.py @@ -59,7 +59,8 @@ class PluginExecutor: self, operation: Callable[[], Any], timeout: Optional[float] = None, - plugin_id: Optional[str] = None + plugin_id: Optional[str] = None, + thread_name: Optional[str] = None ) -> Any: """ Execute a plugin operation with timeout. @@ -68,6 +69,8 @@ class PluginExecutor: operation: Function to execute timeout: Timeout in seconds (None = use default) plugin_id: Optional plugin ID for logging + thread_name: Name for the thread the operation runs on (None + keeps Python's default). Stack dumps list threads by name. Returns: Result of operation @@ -93,7 +96,7 @@ class PluginExecutor: result_container['exception'] = e result_container['completed'] = True - thread = Thread(target=target, daemon=True) + thread = Thread(target=target, daemon=True, name=thread_name) thread.start() thread.join(timeout=timeout) @@ -223,18 +226,24 @@ class PluginExecutor: 'display_mode' in inspect.signature(plugin.display).parameters) has_display_mode = accepts_display_mode + # Named for the plugin: this thread presents a screen's first + # frame, so the frame-timing stall watchdog's stack dumps name it. + thread_name = f"display-{plugin_id}" + # Capture the return value from the plugin's display() method if has_display_mode and display_mode: result = self.execute_with_timeout( lambda: plugin.display(display_mode=display_mode, force_clear=force_clear), timeout=timeout, - plugin_id=plugin_id + plugin_id=plugin_id, + thread_name=thread_name ) else: result = self.execute_with_timeout( lambda: plugin.display(force_clear=force_clear), timeout=timeout, - plugin_id=plugin_id + plugin_id=plugin_id, + thread_name=thread_name ) duration = time.monotonic() - start_time diff --git a/test/test_frame_ops.py b/test/test_frame_ops.py index d3e255be..0fc3f622 100644 --- a/test/test_frame_ops.py +++ b/test/test_frame_ops.py @@ -11,6 +11,7 @@ import sys from pathlib import Path import numpy as np +import pytest from PIL import Image sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) @@ -141,6 +142,95 @@ def test_aggregate_still_takes_frames_without_ops(tmp_path): assert r.totals["op_frames"] == {} +# -- screen handovers --------------------------------------------------------- +# The display controller tags a screen's first frame "handover". A freeze that +# frame ends is the next plugin drawing, not a scroll that stalled. + + +def test_a_handover_freeze_is_not_a_freeze(tmp_path): + r = _recorder(tmp_path) + _frame(r, 100.0) + r.note_op("handover") + _frame(r, 101.4) # 1.4s to draw the next screen + r.note_op("extend", 10) + _frame(r, 101.8) # a real one, for contrast + totals = _totals(r) + assert totals["handover_freezes"] == 1 + assert totals["freezes"] == 1 + assert totals["freeze_by"] == {"<0.5s": 1, "0.5-1s": 0, "1-2s": 0, "2s+": 0} + assert totals["freeze_seconds"] == pytest.approx(0.4) + # Still on the "after work" table, with its freezes column. + assert totals["op_freezes"] == {"handover": 1, "extend": 1} + + +def test_a_quick_handover_is_an_ordinary_timed_frame(tmp_path): + r = _recorder(tmp_path) + _frame(r, 100.0) + r.note_op("handover") + _frame(r, 100.0 + 4 * PERIOD) + totals = _totals(r) + assert totals["handover_freezes"] == totals["freezes"] == 0 + assert totals["op_frames"] == {"handover": 1} + assert totals["late_op_frames"] == {"handover": 1} + + +def test_a_dropped_note_tags_nothing(tmp_path): + # The first display() drew nothing: the tag must not wait for whatever + # frame comes next, here a stall a minute later. + r = _recorder(tmp_path) + _frame(r, 100.0) + r.note_op("handover") + r.drop_op("handover") + _frame(r, 101.0) + totals = _totals(r) + assert totals["handover_freezes"] == 0 + assert totals["freezes"] == 1 + assert totals["op_freezes"] == {} + + +def test_dropping_a_note_keeps_other_kinds_and_is_harmless_when_none(tmp_path): + r = _recorder(tmp_path) + r.drop_op("handover") # nothing noted: nothing to do + _frame(r, 100.0) + r.note_op("handover") + r.note_op("patch", 5) + r.drop_op("handover") + _frame(r, 100.0 + PERIOD) + r.drop_op("handover") # already carried by a frame + totals = _totals(r) + assert totals["op_frames"] == {"patch": 1} + + +def test_the_soak_report_prints_handover_gaps(tmp_path, capsys): + r = _recorder(tmp_path) + before = json.loads(json.dumps(r.snapshot())) + _frame(r, 100.0) + r.note_op("handover") + _frame(r, 100.5) + report = _report(r, before) + assert report["handover_freezes"] == 1 + assert report["freezes"] == 0 + frame_soak.print_report(report, 0.1) + assert "Handover gaps 1" in capsys.readouterr().out + + +def test_a_report_from_an_older_recorder_has_no_handover_line(tmp_path, capsys): + # Stats written before the count existed: diffed and printed without it. + r = _recorder(tmp_path) + before = json.loads(json.dumps(r.snapshot())) + _frame(r, 100.0) + _frame(r, 100.0 + PERIOD) + r.drain() + after = json.loads(json.dumps(r.snapshot())) + after["updated"] = before["updated"] + 10.0 + for stats in (before, after): + del stats["totals"]["handover_freezes"] + report = frame_soak.build_report(before, after, preview=False) + assert report["handover_freezes"] is None + frame_soak.print_report(report, 0.1) + assert "Handover gaps" not in capsys.readouterr().out + + # -- the soak report ---------------------------------------------------------- diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index e3ffae68..91714d2c 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -421,6 +421,31 @@ def test_watchdog_names_what_the_stalled_thread_is_waiting_on(): assert "render_loop_waiting_on_a_lock" in text +def test_watchdog_labels_a_stall_before_a_new_screens_first_frame(caplog): + # The display controller noted a handover and the next screen's first + # display() is still drawing: not a scroll that stopped. + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0) + rec.last_frame = (10.0, True, 1) + rec._ops = {frame_timing.HANDOVER_OP: 0} + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + dog.check(10.4, 0.0, None, False) + message = caplog.records[0].getMessage() + assert message.startswith("Render stall: no frame for 400ms in a handover gap") + assert "mid-scroll" not in message + + +def test_watchdog_says_mid_scroll_when_nothing_is_handing_over(caplog): + rec = _FakeRecorder() + dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=0.0) + rec.last_frame = (10.0, True, 1) + rec._ops = {"extend": 100} # other work pending is not a handover + with caplog.at_level("WARNING", logger="src.common.frame_timing"): + dog.check(10.4, 0.0, None, False) + assert caplog.records[0].getMessage().startswith( + "Render stall: no frame for 400ms mid-scroll") + + def test_watchdog_rate_limits_its_dumps(caplog): rec = _FakeRecorder() dog = frame_timing.StallWatchdog(rec, threshold=0.25, log_interval=30.0) diff --git a/test/test_handover_scroll_state.py b/test/test_handover_scroll_state.py new file mode 100644 index 00000000..b70b47a5 --- /dev/null +++ b/test/test_handover_scroll_state.py @@ -0,0 +1,590 @@ +"""Scroller-to-static handovers: the scroll state ends with the scroller. + +Nothing ended the scroll state when the rotation moved from a scroller to a +static screen; it expired 2 s after the scroller's last frame. Two things +followed, both seen on ledpi (Pi 4, 96x48, scan-order compensation on): + +* the static screen's first frame -- on the panel for a whole second -- went + out with rows 24-47 taken from the ticker's last frame; +* the 1 Hz loop's second frame, a second later, was timed as a frame of the + old scroll: a 1-2 s "freeze" in every soak and a "Render stall" in the log + at every such handover (17 of 31 "Render stall over" lines). + +The display controller now calls ``end_scroll_for_static_screen()`` just before +a static screen's first dispatch and ``set_scrolling_state(False)`` once it +returns, and tags that first frame ``handover`` for the frame-timing stats. +""" + +import os +import sys +import types +from unittest.mock import MagicMock + +os.environ.setdefault("EMULATOR", "true") + +import pytest + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..")) + +from src.common.frame_timing import FrameTimingRecorder # noqa: E402 + +PERIOD = 0.010 # a 100 Hz panel + + +@pytest.fixture +def dm(tmp_path): + """A real DisplayManager on the emulator, sized like ledpi's panel.""" + from src.display_manager import DisplayManager + DisplayManager._instance = None + DisplayManager._initialized = False + manager = DisplayManager({"display": { + "hardware": {"rows": 48, "cols": 96, "chain_length": 1, "parallel": 1}, + "runtime": {"gpio_slowdown": 0}}}, suppress_test_pattern=True) + # Not the fixed path the web UI reads, which every pytest run shares. + manager._snapshot_path = str(tmp_path / "led_matrix_preview.png") + if manager.matrix is None: + pytest.fail("DisplayManager fell back to matrix=None; see the " + "'Failed to initialize RGB Matrix' log line above.") + presented = [] + + # update_display alternates between two canvases; watch both. + for canvas in (manager.offscreen_canvas, manager.current_canvas): + def capture(image, *args, _real=canvas.SetImage, **kwargs): + presented.append(image.copy()) + return _real(image, *args, **kwargs) + canvas.SetImage = capture + manager._presented = presented + yield manager + manager.set_scrolling_state(False) + DisplayManager._instance = None + DisplayManager._initialized = False + + +def _push(dm, colour): + dm.draw.rectangle([0, 0, dm.width - 1, dm.height - 1], fill=colour) + dm.update_display() + return dm._presented[-1] + + +def _watch_swaps(dm): + """The refreshes each SwapOnVSync from here on holds its frame for.""" + holds = [] + real = dm.matrix.SwapOnVSync + + def swap(canvas, *args, **kwargs): + holds.append(args[0] if args else kwargs.get("framerate_fraction", 1)) + return real(canvas, *args, **kwargs) + dm.matrix.SwapOnVSync = swap + return holds + + +# -- the first static frame --------------------------------------------------- + + +class TestTheFirstStaticFrame: + def test_it_does_not_show_the_tickers_lagging_rows(self, dm): + dm._scan_lag_bands = [(24, 48, 1)] # ledpi: rows 24-47 a refresh behind + dm.set_scrolling_state(True, 1) # a ticker at one frame per refresh + _push(dm, (255, 0, 0)) # its last frame + dm.end_scroll_for_static_screen() # the controller, before the dispatch + shown = _push(dm, (0, 0, 0)) # the static screen's first frame + assert shown.getpixel((10, 10)) == (0, 0, 0) + assert shown.getpixel((10, 30)) == (0, 0, 0) + + def test_without_it_the_tickers_rows_are_shown(self, dm): + # What happened before: the frame that stays up for a second is half + # the old ticker. (Proves the test above can see the leak.) + dm._scan_lag_bands = [(24, 48, 1)] + dm.set_scrolling_state(True, 1) + _push(dm, (255, 0, 0)) + shown = _push(dm, (0, 0, 0)) + assert shown.getpixel((10, 30)) == (255, 0, 0) + + def test_after_a_held_scroll_it_is_one_plain_swap(self, dm): + # Scan-order compensation covers held frames too: mid-scroll, a frame + # held 2 refreshes goes out as two swaps, the first with the lagging + # rows from the frame before. The static screen's first frame is one + # swap, as drawn, held for the scroll's own 2 refreshes. + dm._scan_lag_bands = [(24, 48, 1)] + dm.set_scrolling_state(True, 2) # a crisp scroll: 1 px every 2 refreshes + _push(dm, (255, 0, 0)) # its last frame + holds = _watch_swaps(dm) + before = len(dm._presented) + dm._last_blit_seconds = 0.0 # fast enough to split, as on ledpi + dm.end_scroll_for_static_screen() + _push(dm, (0, 0, 0)) + assert len(dm._presented) - before == 1 + assert dm._presented[-1].getpixel((10, 30)) == (0, 0, 0) + assert holds == [2] + assert len(dm._scan_history) == 0 # nothing of the ticker kept + + def test_without_it_a_held_scroll_flashes_the_tickers_rows(self, dm): + # What happens without the call: the frame's first refresh shows the + # ticker's rows. (Proves the test above can see the leak.) + dm._scan_lag_bands = [(24, 48, 1)] + dm.set_scrolling_state(True, 2) + _push(dm, (255, 0, 0)) + holds = _watch_swaps(dm) + before = len(dm._presented) + dm._last_blit_seconds = 0.0 + _push(dm, (0, 0, 0)) + first, second = dm._presented[before:] + assert first.getpixel((10, 30)) == (255, 0, 0) + assert second.getpixel((10, 30)) == (0, 0, 0) + assert holds == [1, 1] + + def test_it_is_timed_like_any_frame_of_the_scroll(self, dm, monkeypatch): + # One record, at the scroll's hold and still "scrolling": the gap to + # it is judged against the scroller's pacing (see TestTheSoak). + dm._scan_lag_bands = [(24, 48, 1)] + dm.set_scrolling_state(True, 3) + _push(dm, (255, 0, 0)) + records = [] + real = dm.frame_timing.record + + def record(*args, **kwargs): + records.append(args) + return real(*args, **kwargs) + monkeypatch.setattr(dm.frame_timing, "record", record) + dm.end_scroll_for_static_screen() + _push(dm, (0, 0, 0)) + [(_blit, _wait, hold, scrolling, _at)] = records + assert (hold, scrolling) == (3, True) + + def test_nor_its_own_first_frame_under_its_second(self, dm): + # A first display() that pushes two frames: a clear, then the screen. + # Composed, the second would show the first's rows -- and once the + # scroll is over, dirty tracking (which compares frames as drawn, not + # as composed) skips every identical 1 Hz redraw, so that half-black + # frame would stay up for the whole turn. + dm._scan_lag_bands = [(24, 48, 1)] + dm.set_scrolling_state(True, 1) + _push(dm, (255, 0, 0)) # the ticker's last frame + dm.end_scroll_for_static_screen() + _push(dm, (0, 0, 0)) # the static screen clears... + shown = _push(dm, (0, 0, 255)) # ...then draws + assert shown.getpixel((10, 30)) == (0, 0, 255) + dm.set_scrolling_state(False) # the controller, after the dispatch + pushed = len(dm._presented) + _push(dm, (0, 0, 255)) # the 1 Hz redraw: skipped + assert len(dm._presented) == pushed + + def test_the_next_scroll_is_compensated_again(self, dm): + dm._scan_lag_bands = [(24, 48, 1)] + dm.set_scrolling_state(True, 1) + _push(dm, (255, 0, 0)) + dm.end_scroll_for_static_screen() + _push(dm, (0, 0, 0)) + dm.set_scrolling_state(False) + dm.set_scrolling_state(True, 1) # the next ticker + _push(dm, (0, 255, 0)) + assert _push(dm, (0, 0, 255)).getpixel((10, 30)) == (0, 255, 0) + + def test_it_keeps_the_scroll_state_and_its_hold(self, dm): + dm.set_scrolling_state(True, 5) # e.g. 2px every 5 refreshes + dm.end_scroll_for_static_screen() + # Both stay until the controller ends the scroll: the gap to the first + # static frame is timed and watched, and due at the scroll's own + # pacing (see TestTheSoak). + assert dm.is_currently_scrolling() + assert dm._frame_hold == 5 + dm.set_scrolling_state(False) + assert dm._frame_hold == 1 + + def test_a_thread_drawing_off_screen_cannot_end_the_live_scroll(self, dm): + dm._scan_lag_bands = [(24, 48, 1)] + dm.set_scrolling_state(True, 1) + _push(dm, (255, 0, 0)) + with dm.offscreen(): + dm.end_scroll_for_static_screen() + # Still the ticker's scroll: its next frame is composed as usual. + assert _push(dm, (0, 0, 0)).getpixel((10, 30)) == (255, 0, 0) + + +# -- what the frame-timing soak records ------------------------------------- + + +class _FakeTime: + """display_manager's clock, moved by hand.""" + + def __init__(self, t): + self.t = t + + def time(self): + return self.t + + perf_counter = monotonic = time + + +def _handover(dm, monkeypatch, tmp_path, controller_calls, first_frame_after=0.040, + hold=1): + """A scroll, then a static screen, presented through update_display. + + The scroll presents a frame every ``hold`` refreshes. The static screen's + frames land 40 ms, 1.065 s and 2.09 s after the scroller's last frame: a + handover, then the 1 Hz loop. With ``controller_calls`` the display + manager is driven the way DisplayController.run() drives it at that + handover. + """ + clock = _FakeTime(1000.0) + monkeypatch.setattr("src.display_manager.time", clock) + recorder = FrameTimingRecorder(path=str(tmp_path / "stats.json"), + flush_interval=1e9, refresh_hz=100.0) + monkeypatch.setattr(dm, "frame_timing", recorder) + + for i in range(200): + dm.set_scrolling_state(True, hold) + dm.draw.rectangle([0, 0, 4, 4], fill=(i % 256, 0, 0)) + dm.update_display() + clock.t += hold * PERIOD + last_scroll_frame = clock.t - hold * PERIOD + + if controller_calls: + dm.end_scroll_for_static_screen() + recorder.note_op("handover") + for n, offset in enumerate((first_frame_after, 1.065, 2.090)): + clock.t = last_scroll_frame + offset + # Each static frame differs, as a clock's does, so none is skipped. + dm.draw.rectangle([0, 0, dm.width - 1, dm.height - 1], fill=(0, 0, 40 + n)) + dm.update_display() + if controller_calls and n == 0: + recorder.drop_op("handover") + dm.set_scrolling_state(False) + recorder.drain() + return recorder.totals + + +class TestTheSoak: + def test_a_handover_to_a_static_screen_is_not_a_freeze(self, dm, monkeypatch, tmp_path): + totals = _handover(dm, monkeypatch, tmp_path, controller_calls=True) + assert totals["freezes"] == 0 + assert totals["freeze_by"]["1-2s"] == 0 + assert totals["handover_freezes"] == 0 + # The handover interval itself is still timed, and carries its tag. + assert totals["op_frames"] == {"handover": 1} + assert totals["static_frames"] == 2 + + def test_a_handover_on_the_scrollers_schedule_is_not_late(self, dm, monkeypatch, + tmp_path): + # A scroll held 3 refreshes a frame, and a static screen whose first + # frame lands 3 refreshes after its last one: on time, as it always + # was. Judged at hold 1 it would be 2 refreshes late, and the soak's + # pass/fail late count would grow with every such handover. + totals = _handover(dm, monkeypatch, tmp_path, controller_calls=True, + first_frame_after=3 * PERIOD, hold=3) + assert totals["op_frames"] == {"handover": 1} + assert totals["late_op_frames"] == {} + assert totals["late_frames"] == totals["missed_refreshes"] == 0 + + def test_left_to_expire_it_was_one(self, dm, monkeypatch, tmp_path): + # The old behaviour, for contrast: the 1 Hz loop's second frame was + # still "scrolling" and ended a 1.025 s interval. + totals = _handover(dm, monkeypatch, tmp_path, controller_calls=False) + assert totals["freezes"] == 1 + assert totals["freeze_by"]["1-2s"] == 1 + + def test_a_slow_first_frame_is_a_handover_gap_not_a_freeze(self, dm, monkeypatch, + tmp_path): + # The next screen took 400 ms to draw its first frame. + totals = _handover(dm, monkeypatch, tmp_path, controller_calls=True, + first_frame_after=0.400) + assert totals["handover_freezes"] == 1 + assert totals["freezes"] == 0 + assert totals["freeze_seconds"] == 0.0 + assert totals["freeze_by"] == {"<0.5s": 0, "0.5-1s": 0, "1-2s": 0, "2s+": 0} + assert totals["op_freezes"] == {"handover": 1} + + +# -- DisplayController.run() --------------------------------------------------- + + +class _Clock: + """display_controller's clock: moves only when run() sleeps.""" + + def __init__(self, start=10_000.0): + self.t = start + + def now(self): + return self.t + + def sleep(self, seconds): + self.t += max(seconds, 0.0005) + + def module(self): + return types.SimpleNamespace(time=self.now, monotonic=self.now, + perf_counter=self.now, sleep=self.sleep) + + +class _Screen: + """A plugin mode that records each display() call into ``events``.""" + + def __init__(self, plugin_id, events, needs_high_fps, scrolls=False, + results=(), stop_after=None): + self.plugin_id = plugin_id + self.needs_high_fps = needs_high_fps + self._events = events + self._scrolls = scrolls + self._results = iter(results) + self._stop_after = stop_after + self.display_manager = None + self.calls = 0 + + def display(self, force_clear=False): + self.calls += 1 + if self._stop_after is not None and self.calls > self._stop_after: + raise KeyboardInterrupt # ends run(); it catches this and cleans up + self._events.append(("display", self.plugin_id)) + if self._scrolls: + # What a ticker does every frame. + self.display_manager.set_scrolling_state(True, 2) + return next(self._results, True) + + +@pytest.fixture +def controller(test_display_controller, monkeypatch): + c = test_display_controller + clock = _Clock() + monkeypatch.setattr("src.display_controller.time", clock.module()) + c._refresh_config_cache({"display": {"hardware": {"brightness": 90}}}) + c.current_brightness = 90 + c.is_display_active = True + c._check_wifi_status_message = MagicMock(return_value=None) + c._cleanup_expired_wifi_status = MagicMock() + c.cache_manager.get = MagicMock(return_value=None) # no on-demand request + c.plugin_manager.plugin_executor.execute_display.side_effect = ( + lambda target, plugin_id, force_clear=False, display_mode=None, **kw: + target.display(force_clear=force_clear)) + + events = [] + dm = c.display_manager + dm.end_scroll_for_static_screen = MagicMock( + side_effect=lambda: events.append("end_scroll")) + dm.set_scrolling_state = MagicMock( + side_effect=lambda state, *a, **k: events.append(("scrolling", state))) + dm.frame_timing.note_op = MagicMock( + side_effect=lambda kind, nbytes=0: events.append(("note", kind))) + dm.frame_timing.drop_op = MagicMock( + side_effect=lambda kind: events.append(("drop", kind))) + c.events = events + return c + + +def _rotation(c, screens, durations): + c.plugin_modes.clear() + c.mode_to_plugin_id.clear() + c.plugin_display_modes.clear() + for screen in screens: + screen.display_manager = c.display_manager + c.plugin_modes[screen.plugin_id] = screen + c.mode_to_plugin_id[screen.plugin_id] = screen.plugin_id + c.plugin_display_modes[screen.plugin_id] = [screen.plugin_id] + c.available_modes = [screen.plugin_id for screen in screens] + c.current_mode_index = 0 + c.current_display_mode = c.available_modes[0] + c.config.setdefault("display", {})["display_durations"] = durations + + +def _turn(events, plugin_id): + """The events from plugin_id's first display() to the next screen's.""" + first = events.index(("display", plugin_id)) + end = next((i for i in range(first + 1, len(events)) + if events[i][0] == "display" and events[i][1] != plugin_id), + len(events)) + return first, events[first:end] + + +class TestRunLoop: + def test_a_static_screen_ends_the_scroll_around_its_first_dispatch(self, controller): + c = controller + ticker = _Screen("ticker", c.events, needs_high_fps=True, scrolls=True) + clock = _Screen("clock", c.events, needs_high_fps=False, stop_after=3) + _rotation(c, [ticker, clock], {"ticker": 1, "clock": 30}) + + c.run() + + events = c.events + first, turn = _turn(events, "clock") + # Before the first dispatch: the panel is readied, then the frame tagged. + assert events[first - 2:first] == ["end_scroll", ("note", "handover")] + # After it, before the 1 Hz loop's next frame: the tag dropped if no + # frame took it, and the scroll ended. + second = turn.index(("display", "clock"), 1) + assert turn[1:second] == [("drop", "handover"), ("scrolling", False)] + + def test_a_scroller_keeps_its_state(self, controller): + c = controller + ticker = _Screen("ticker", c.events, needs_high_fps=True, scrolls=True, + stop_after=50) + _rotation(c, [ticker], {"ticker": 60}) + + c.run() + + assert "end_scroll" not in c.events + assert ("scrolling", False) not in c.events + # The first frame is still tagged: a slow scroller-to-scroller + # handover is a handover gap, not a freeze. + first = c.events.index(("display", "ticker")) + assert c.events[first - 1] == ("note", "handover") + + def test_screens_that_declare_nothing_are_told_apart_by_enable_scrolling( + self, controller): + # Most plugins declare no needs_high_fps (the odds, stocks and news + # tickers, the scoreboards): enable_scrolling decides. It now also + # decides whether the scroll is ended before the first dispatch, so a + # ticker read as static would lose its pacing every turn. + c = controller + ticker = _Screen("ticker", c.events, needs_high_fps=None, scrolls=True) + ticker.enable_scrolling = True + board = _Screen("board", c.events, needs_high_fps=None, stop_after=1) + board.enable_scrolling = False + _rotation(c, [ticker, board], {"ticker": 1, "board": 30}) + + c.run() + + events = c.events + first, turn = _turn(events, "board") + assert "end_scroll" not in events[:first - 2] + assert ("scrolling", False) not in events[:first - 2] + assert events[first - 2:first] == ["end_scroll", ("note", "handover")] + assert turn[1:3] == [("drop", "handover"), ("scrolling", False)] + + def test_an_old_static_image_is_still_a_high_fps_screen(self, controller): + # static-image versions from before needs_high_fps declare nothing and + # are forced to the high-FPS loop for their GIFs: not a static screen. + c = controller + image = _Screen("static-image", c.events, needs_high_fps=None, stop_after=5) + _rotation(c, [image], {"static-image": 60}) + + c.run() + + assert ("display", "static-image") in c.events + assert "end_scroll" not in c.events + assert ("scrolling", False) not in c.events + + def test_a_static_screen_whose_display_raises_still_ends_the_scroll(self, controller): + class Raising(_Screen): + def display(self, force_clear=False): + self._events.append(("display", self.plugin_id)) + raise RuntimeError("plugin bug") + + c = controller + ticker = _Screen("ticker", c.events, needs_high_fps=True, scrolls=True) + broken = Raising("broken", c.events, needs_high_fps=False) + clock = _Screen("clock", c.events, needs_high_fps=False, stop_after=1) + _rotation(c, [ticker, broken, clock], {"ticker": 1, "broken": 30, "clock": 30}) + + c.run() + + first, turn = _turn(c.events, "broken") + assert c.events[first - 2:first] == ["end_scroll", ("note", "handover")] + assert turn[1:3] == [("drop", "handover"), ("scrolling", False)] + + def test_a_raise_inside_the_executor_is_a_failure_and_still_ends_the_scroll( + self, controller): + # The real executor, with raise_errors: a display() that raises comes + # back as a PluginError, which the breaker records as a failure (not + # a success). The handover is finished after that record, and only + # touches the display manager. + import threading + from src.plugin_system.plugin_executor import PluginExecutor + + class Raising(_Screen): + def display(self, force_clear=False): + self._events.append(("display", self.plugin_id)) + raise RuntimeError("plugin bug") + + c = controller + pm = c.plugin_manager + pm.plugin_executor = PluginExecutor(default_timeout=5.0) + locks = {} + pm.get_plugin_lock = lambda pid: locks.setdefault(pid, threading.Lock()) + tracker = MagicMock() + tracker.should_skip_plugin.return_value = False + tracker.record_failure.side_effect = ( + lambda pid, exc=None: c.events.append(("failure", pid, str(exc)))) + tracker.record_success.side_effect = ( + lambda pid: c.events.append(("success", pid))) + pm.health_tracker = tracker + ticker = _Screen("ticker", c.events, needs_high_fps=True, scrolls=True) + broken = Raising("broken", c.events, needs_high_fps=False) + clock = _Screen("clock", c.events, needs_high_fps=False, stop_after=1) + _rotation(c, [ticker, broken, clock], {"ticker": 1, "broken": 30, "clock": 30}) + + c.run() + + first, turn = _turn(c.events, "broken") + assert c.events[first - 2:first] == ["end_scroll", ("note", "handover")] + assert turn[1:4] == [("failure", "broken", "plugin bug"), + ("drop", "handover"), ("scrolling", False)] + assert ("success", "broken") not in c.events + assert tracker.record_failure.call_count == 1 + + def test_every_turn_starts_with_a_handover_even_of_the_same_mode(self, controller): + # A one-mode rotation (or a mode kept on by live priority) comes back + # to itself, and that turn's first frame is a first display() too: + # a scroller rebuilding its content there is a handover gap, not a + # freeze. See "Handover gaps" in docs/SCROLL_PERFORMANCE.md. + c = controller + ticker = _Screen("ticker", c.events, needs_high_fps=True, scrolls=True, + stop_after=200) + _rotation(c, [ticker], {"ticker": 1}) + + c.run() + + notes = [i for i, event in enumerate(c.events) if event == ("note", "handover")] + assert len(notes) == 2 + assert all(c.events[i + 1] == ("display", "ticker") for i in notes) + + def test_a_static_screen_with_nothing_to_show_still_ends_the_scroll(self, controller): + c = controller + ticker = _Screen("ticker", c.events, needs_high_fps=True, scrolls=True) + empty = _Screen("empty", c.events, needs_high_fps=False, results=[False]) + clock = _Screen("clock", c.events, needs_high_fps=False, stop_after=1) + _rotation(c, [ticker, empty, clock], {"ticker": 1, "empty": 30, "clock": 30}) + + c.run() + + first, turn = _turn(c.events, "empty") + assert c.events[first - 2:first] == ["end_scroll", ("note", "handover")] + assert turn[1:3] == [("drop", "handover"), ("scrolling", False)] + + def test_a_busy_plugin_is_not_tagged(self, controller): + # update() holds the plugin's lock, so its first dispatch is skipped + # and presents nothing: no tag to leave lying around. + c = controller + clock = _Screen("clock", c.events, needs_high_fps=False) + _rotation(c, [clock], {"clock": 3}) + busy = MagicMock() + busy.acquire.return_value = False + c.plugin_manager.get_plugin_lock.return_value = busy + c._sleep_with_plugin_updates = MagicMock(side_effect=KeyboardInterrupt) + stop = MagicMock(side_effect=[None, None, None, KeyboardInterrupt]) + c._tick_plugin_updates = stop + + c.run() + + assert ("note", "handover") not in c.events + assert c.events[:3] == ["end_scroll", ("drop", "handover"), ("scrolling", False)] + + def test_a_plugin_whose_fps_flag_raises_does_not_stop_the_display(self, controller): + class Broken(_Screen): + @property + def needs_high_fps(self): + raise RuntimeError("plugin bug") + + @needs_high_fps.setter + def needs_high_fps(self, value): + pass + + c = controller + broken = Broken("broken", c.events, needs_high_fps=None, results=[False]) + clock = _Screen("clock", c.events, needs_high_fps=False, stop_after=1) + _rotation(c, [broken, clock], {"broken": 30, "clock": 30}) + + c.run() + + assert ("display", "broken") in c.events + assert ("display", "clock") in c.events # the loop went on + # Undecidable, so the broken screen's turn left the scroll state alone. + _, turn = _turn(c.events, "broken") + assert ("scrolling", False) not in turn diff --git a/test/test_plugin_system.py b/test/test_plugin_system.py index 6d48cd86..555f5891 100644 --- a/test/test_plugin_system.py +++ b/test/test_plugin_system.py @@ -141,6 +141,27 @@ class TestPluginExecutor: assert result is True mock_plugin.display.assert_called_once() + def test_execute_display_runs_on_a_thread_named_for_the_plugin(self): + """A screen's first frame is presented from this thread, so stack + dumps (the frame-timing stall watchdog's) should name the plugin.""" + import threading + from src.plugin_system.plugin_executor import PluginExecutor + executor = PluginExecutor() + seen = [] + + class Plugin: + def display(self, display_mode=None, force_clear=False): + seen.append((threading.current_thread().name, display_mode)) + return True + + # Both ways display() is called: without a mode, and with one (most + # multi-mode plugins, the scoreboards among them). + assert executor.execute_display(Plugin(), "clock-simple") is True + assert executor.execute_display(Plugin(), "clock-simple", + display_mode="clock") is True + assert seen == [("display-clock-simple", None), + ("display-clock-simple", "clock")] + def test_execute_display_exception(self): """Test display execution with exception.""" from src.plugin_system.plugin_executor import PluginExecutor