feat(display): report a scrolling screen held by its plugin's update() (#758)

While a plugin's update() runs it holds the plugin's lock and its frames are skipped -- on a scroller, a frozen strip -- with nothing logged. The high-FPS loop now times each run of skipped frames (report_hold=True); one of 250 ms or more logs 'Display of X held N ms by its update()' (rate-limited per plugin) and is recorded as a 'display hold' busy skip, which never touches the circuit breaker. The 1 Hz loop is left out: one skipped frame there measures the loop interval on a screen that did not visibly freeze (seen on ledpi as ~1000 ms reports on clock-simple and switch-mode football).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

CHANGELOG.md

@@ -19,6 +19,18 @@ accepts both, but the store flags the old spelling as deprecated
 
 ## Unreleased
 
+### A scrolling screen held by its plugin's update() is reported
+
+- While a plugin's `update()` runs it holds the plugin's lock, and that
+  plugin's frames are skipped: on a scroller, a frozen strip, with nothing
+  logged (and a freeze of 5 s or more is a gap, not a freeze, to the frame
+  stats). The high-FPS loop now times each run of skipped frames; one of
+  250 ms or more logs `Display of <plugin> held N ms by its update()`
+  (rate-limited per plugin) when it ends, and is recorded on the plugin's
+  health as a `display hold` busy skip, which never counts toward the
+  circuit breaker. The 1 Hz loop is left out: its frames are a second apart,
+  so one skipped frame there measures nothing and freezes nothing visible.
+
 ### Fixed
 
 - The web preview and `/api/v3/display/current` no longer stay black for a
@@ -57,18 +69,6 @@ soccer-scoreboard 2.39.2, alternating runs: **~450 requests per start, peak
   spends one doomed 400 per window at every start (eleven at once from a
   soccer board); the range is still retried `RANGE_RETRY_SECONDS` in.
 
-### Fetch stats: bytes on the wire, not just decoded
-
-`GET /api/v3/plugins/fetch-stats` reported only `bytes`, the decoded body
-size, and that read as the download volume. ESPN gzips every scoreboard, so
-it overstated what crossed the network about 14x: a college football
-Saturday's scoreboard is 865 KB decoded and 63 KB on the wire, and ledpi's
-"643 MB in 6 hours" of football was ~47 MB of actual traffic. Every counter
-set (totals, per plugin, per host) now has `wire_bytes` too, read from
-urllib3's count of the raw bytes it took off the socket. A response with no
-urllib3 response behind it is counted at its decoded size. `bytes` keeps its
-meaning.
-
 ### Cheap per-frame and per-fetch savings
 
 - `BaseOddsManager.get_odds()` no longer pretty-prints every odds response

src/common/fetch_service.py

@@ -59,10 +59,7 @@ says how old with ``cache_max_age`` (``fetch_get(..., cache_max_age=ttl)``;
 Identical means what the validator store keys on: URL, query, effective
 headers and, for a session with cookies or auth, the session.
 
-**Counters.** Requests, merged requests, bytes (``bytes`` decoded, as the
+**Counters.** Requests, merged requests, bytes, 304s, errors, HTTP errors,
-caller reads them; ``wire_bytes`` as they crossed the network, which is
-what a metered connection pays for -- ESPN gzips, so the two differ ~14x),
-304s, errors, HTTP errors,
 adapter retries, throttled requests and seconds waited, plus requests
 answered without the network: ``memo_hits`` (the response cache) and
 ``cache_hits`` / ``legacy_cache_hits`` (a shared ESPN scoreboard cache entry,
@@ -204,7 +201,6 @@ _COUNTER_FIELDS = (
     "throttled",     # requests that waited for a host budget
     "overruns",      # requests that went after max_wait_seconds anyway
     "bytes",         # decoded response body bytes received
-    "wire_bytes",    # body bytes as they came off the socket (still compressed)
     "wait_seconds",  # time spent waiting for host budgets
     "memo_hits",     # answered from the response cache (max-age); nothing sent
     "cache_hits",    # scoreboard fetches answered from a shared ESPN cache entry
@@ -620,30 +616,6 @@ def _body_of(response: Any) -> Optional[bytes]:
     return content if isinstance(content, bytes) else None
 
 
-def _wire_bytes_of(response: Any, body: Optional[bytes]) -> int:
-    """How many body bytes came off the socket for ``response``: the
-    compressed size when the server sent gzip, which ESPN does for every
-    scoreboard (63 KB on the wire for an 865 KB college football Saturday).
-
-    urllib3's ``HTTPResponse.tell()`` counts the raw bytes read before
-    decoding. A response without one (a test double, an adapter that is not
-    urllib3) or one whose body was not read is counted at its decoded size,
-    or as 0, so the counter never claims less than it can prove.
-    """
-    if body is None:
-        return 0
-    raw = getattr(response, "raw", None)
-    tell = getattr(raw, "tell", None)
-    if callable(tell):
-        try:
-            read = tell()
-        except Exception:
-            read = None
-        if isinstance(read, int) and not isinstance(read, bool) and read > 0:
-            return read
-    return len(body)
-
-
 def _retries_of(response: Any) -> int:
     raw = getattr(response, "raw", None)
     retries = getattr(raw, "retries", None)
@@ -1145,7 +1117,6 @@ class FetchService:
                         http_errors=int(status is not None and status >= 400),
                         retries=_retries_of(response),
                         bytes=len(body) if body is not None else 0,
-                        wire_bytes=_wire_bytes_of(response, body),
                         throttled=int(waited > 0), overruns=int(overrun),
                         wait_seconds=waited)
         except Exception:

src/display_controller.py

@@ -1164,6 +1164,55 @@ class DisplayController:
         except Exception:  # pylint: disable=broad-except
             logger.exception("Error running scheduled plugin updates")
 
+    #: A run of frames skipped because a plugin's update() held its lock is
+    #: reported once it has lasted this long.
+    DISPLAY_HOLD_REPORT_SECONDS = 0.25
+
+    #: (plugin_id, monotonic start) of the current run of skipped frames.
+    _display_hold: Optional[Tuple[str, float]] = None
+
+    def _note_display_hold(self, plugin_id: str, held: bool) -> None:
+        """Report how long a plugin's update() kept its display() from drawing.
+
+        While update() runs on the worker it holds the plugin's lock, and every
+        frame of that plugin's screen is skipped: the panel keeps showing the
+        last frame, which on a scroller is a frozen strip. Nothing said so --
+        the frames are not failures, and a scroll freeze of 5 s or more is a
+        gap to the frame stats, not a freeze. This times each such run and,
+        when it ends after DISPLAY_HOLD_REPORT_SECONDS or more, logs it
+        (rate-limited per plugin) and records it on the plugin's health as a
+        busy skip, which never touches the circuit breaker. Only frames of the
+        high-FPS loop are timed (see _display_once's ``report_hold``).
+        """
+        # The clock is read only when a run starts or ends: on a frame that
+        # draws with no run open, this is one attribute check.
+        current = self._display_hold
+        if held:
+            if current is None or current[0] != plugin_id:
+                self._display_hold = (plugin_id, time.monotonic())
+            return
+        if current is None:
+            return
+        self._display_hold = None
+        if current[0] != plugin_id:
+            return
+        seconds = time.monotonic() - current[1]
+        if seconds < self.DISPLAY_HOLD_REPORT_SECONDS:
+            return
+        pm = self.plugin_manager
+        warn = getattr(pm, '_warn_rate_limited', None)
+        if warn is not None:
+            warn(f"display-hold:{plugin_id}",
+                 "Display of %s held %.0f ms by its update()",
+                 plugin_id, seconds * 1000.0)
+        tracker = getattr(pm, 'health_tracker', None)
+        record = getattr(tracker, 'record_busy_skip', None)
+        if record is not None:
+            try:
+                record(plugin_id, "display hold", seconds)
+            except Exception:  # pylint: disable=broad-except
+                logger.debug("Could not record a display hold", exc_info=True)
+
     @contextmanager
     def _display_lock_or_skip(self, plugin_id):
         """Try-lock guard keeping a plugin's display() off its in-flight update().
@@ -1189,7 +1238,7 @@ class DisplayController:
             lock.release()
 
     def _display_once(self, plugin, mode: str, accepts_display_mode: bool,
-                      force_clear: bool = False):
+                      force_clear: bool = False, report_hold: bool = False):
         """Call ``plugin.display()`` directly for one frame of a render loop.
 
         Frames after a screen's first dispatch come through here rather than
@@ -1205,6 +1254,12 @@ class DisplayController:
                 ``display_mode`` so plugins with several modes stay on it.
             accepts_display_mode: Whether display() takes ``display_mode``.
             force_clear: Passed through to display().
+            report_hold: Time runs of frames skipped because update() holds
+                the plugin's lock (see _note_display_hold). Only the high-FPS
+                loop asks: its frames are ~8 ms apart, so a run measures the
+                hold, and a held scroller is a frozen strip. The 1 Hz loop's
+                frames are a second apart, so one skipped frame there would
+                read as a 1 s hold of a screen that did not visibly change.
 
         Each call is timed (two monotonic reads) and handed to
         PluginManager.note_display_duration, which logs and records slow
@@ -1219,6 +1274,12 @@ class DisplayController:
         display_watchdog.watchdog.beat()
         plugin_id = getattr(plugin, 'plugin_id', None)
         with self._display_lock_or_skip(plugin_id) as can_display:
+            if report_hold and plugin_id:
+                self._note_display_hold(plugin_id, held=not can_display)
+            elif can_display and self._display_hold is not None:
+                # A drawn frame outside the high-FPS loop: whatever run was
+                # open is over, unreported.
+                self._display_hold = None
             if not can_display:
                 return True
             started = time.monotonic()
@@ -3987,7 +4048,8 @@ class DisplayController:
                             _frame_start = time.perf_counter()
                             try:
                                 result = self._display_once(
-                                    manager_to_display, active_mode, _accepts_display_mode)
+                                    manager_to_display, active_mode, _accepts_display_mode,
+                                    report_hold=True)
                                 if isinstance(result, bool) and not result:
                                     logger.debug("Display returned False, breaking early")
                                     break

test/test_display_hold_report.py

@@ -0,0 +1,142 @@
+"""The report of a scrolling screen held by its plugin's update().
+
+While a plugin's update() runs it holds the plugin's lock, and its screen's
+frames are skipped -- on a scroller, a frozen strip -- with nothing logged.
+_note_display_hold times each such run and reports one of
+DISPLAY_HOLD_REPORT_SECONDS or more.
+"""
+
+import threading
+import types
+from unittest.mock import MagicMock
+
+import pytest
+
+
+class _Clock:
+    """display_controller's clock: moves only when run() sleeps or a test says."""
+
+    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)
+
+
+@pytest.fixture
+def clock(monkeypatch):
+    c = _Clock()
+    monkeypatch.setattr("src.display_controller.time", c.module())
+    return c
+
+
+class _Locks:
+    """get_plugin_lock for one plugin, whose lock the test can hold."""
+
+    def __init__(self):
+        self.lock = threading.Lock()
+
+    def __call__(self, plugin_id):
+        return self.lock
+
+
+@pytest.fixture
+def held(test_display_controller):
+    c = test_display_controller
+    locks = _Locks()
+    c.plugin_manager.get_plugin_lock = locks
+    c.plugin_manager._warn_rate_limited = MagicMock()
+    c.plugin_manager.health_tracker = MagicMock()
+    c._display_hold = None
+    return c, locks.lock
+
+
+def _plugin(plugin_id):
+    p = MagicMock()
+    p.plugin_id = plugin_id
+    p.display.return_value = True
+    return p
+
+
+class TestTheDisplayHoldReport:
+    def test_a_long_hold_is_reported_when_it_ends(self, held, clock):
+        c, lock = held
+        ticker = _plugin("ticker")
+        lock.acquire()                         # update() running
+        assert c._display_once(ticker, "ticker", False, report_hold=True) is True
+        clock.t += 0.2
+        assert c._display_once(ticker, "ticker", False, report_hold=True) is True
+        assert ticker.display.call_count == 0
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        clock.t += 0.2
+        lock.release()                         # update() done
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        assert ticker.display.call_count == 1
+        key, message, plugin_id, ms = c.plugin_manager._warn_rate_limited.call_args[0]
+        assert key == "display-hold:ticker" and plugin_id == "ticker"
+        assert "held" in message and ms == pytest.approx(400.0)
+        c.plugin_manager.health_tracker.record_busy_skip.assert_called_once_with(
+            "ticker", "display hold", pytest.approx(0.4))
+
+    def test_a_short_hold_is_not(self, held, clock):
+        c, lock = held
+        ticker = _plugin("ticker")
+        lock.acquire()
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        clock.t += 0.1
+        lock.release()
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        c.plugin_manager.health_tracker.record_busy_skip.assert_not_called()
+
+    def test_a_hold_that_ends_on_another_plugins_screen_is_not_blamed_on_it(
+            self, held, clock):
+        c, lock = held
+        lock.acquire()
+        c._display_once(_plugin("ticker"), "ticker", False, report_hold=True)
+        clock.t += 1.0
+        lock.release()
+        c._display_once(_plugin("clock"), "clock", False, report_hold=True)
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        assert c._display_hold is None
+
+    def test_frames_that_draw_report_nothing(self, held, clock):
+        c, _lock = held
+        ticker = _plugin("ticker")
+        for _ in range(5):
+            c._display_once(ticker, "ticker", False, report_hold=True)
+            clock.t += 0.5
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+
+    def test_the_1hz_loop_reports_no_holds(self, held, clock):
+        # A static screen's frames are a second apart: one skipped frame is
+        # not a measured hold, and nothing on the panel froze. (On ledpi the
+        # first version reported every such skip as "held 1000 ms".)
+        c, lock = held
+        board = _plugin("board")
+        lock.acquire()
+        c._display_once(board, "board", False)
+        clock.t += 1.0
+        lock.release()
+        c._display_once(board, "board", False)
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        c.plugin_manager.health_tracker.record_busy_skip.assert_not_called()
+
+    def test_a_run_left_open_is_dropped_by_a_1hz_frame(self, held, clock):
+        c, lock = held
+        ticker = _plugin("ticker")
+        lock.acquire()
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        lock.release()
+        c._display_once(ticker, "ticker", False)        # the 1 Hz loop draws
+        assert c._display_hold is None
+        clock.t += 5.0
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        c.plugin_manager._warn_rate_limited.assert_not_called()

test/test_fetch_service.py

@@ -576,42 +576,6 @@ class TestCounters:
         assert snap["hosts"]["site.api.espn.com"]["requests"] == 1
         assert snap["totals"]["bytes"] == 3 * len(b'{"ok": 1}')
 
-    def test_wire_bytes_are_the_compressed_size(self, service):
-        # Built the way requests builds a real response: a urllib3
-        # HTTPResponse carrying a gzip body, decoded when .content is read.
-        import gzip
-        import io
-
-        from requests.adapters import HTTPAdapter
-        from urllib3.response import HTTPResponse
-
-        decoded = json.dumps({"events": [{"id": str(i), "name": "x" * 200}
-                                         for i in range(50)]}).encode()
-        wire = gzip.compress(decoded)
-
-        def handler(url, kwargs):
-            raw = HTTPResponse(body=io.BytesIO(wire), status=200,
-                               headers={"Content-Encoding": "gzip",
-                                        "Content-Type": "application/json"},
-                               preload_content=False, decode_content=True)
-            request = requests.Request("GET", url).prepare()
-            response = HTTPAdapter().build_response(request, raw)
-            response.content  # what Session.get does for a non-streamed call
-            return response
-
-        response = service.get(FakeSession(handler), "https://site.api.espn.com/x")
-        assert response.content == decoded
-        totals = _counters(service)
-        assert totals["bytes"] == len(decoded)
-        assert totals["wire_bytes"] == len(wire) < len(decoded)
-
-    def test_wire_bytes_fall_back_to_the_decoded_size(self, service):
-        # No urllib3 response behind it (a test double, another adapter):
-        # count what is known rather than nothing.
-        service.get(FakeSession(), "https://api.test/x")
-        totals = _counters(service)
-        assert totals["wire_bytes"] == totals["bytes"] == len(b'{"ok": 1}')
-
     def test_errors_and_http_errors(self, service):
         def handler(url, kwargs):
             if url.endswith("/down"):