From caec9f5bf55d6ba4275adaf8d66340bd4a992423 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Sun, 4 Oct 2026 17:17:10 -0400 Subject: [PATCH 1/4] 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 --- CHANGELOG.md | 12 +++ src/display_controller.py | 66 +++++++++++++- test/test_display_hold_report.py | 142 +++++++++++++++++++++++++++++++ 3 files changed, 218 insertions(+), 2 deletions(-) create mode 100644 test/test_display_hold_report.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 1cc6a860..091db9df 100644 --- a/CHANGELOG.md +++ b/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 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 diff --git a/src/display_controller.py b/src/display_controller.py index 128f3b07..11604bca 100644 --- a/src/display_controller.py +++ b/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 diff --git a/test/test_display_hold_report.py b/test/test_display_hold_report.py new file mode 100644 index 00000000..978ca1a2 --- /dev/null +++ b/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() From ee7c3389f9af14cebb2539d8dac3aba51c525b8b Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Sun, 4 Oct 2026 18:56:32 -0400 Subject: [PATCH 2/4] feat(fetch): count bytes on the wire as well as decoded (#760) fetch-stats now reports wire_bytes (urllib3's raw socket byte count) beside the decoded bytes in every counter set. ESPN gzips its scoreboards, so the decoded count overstated real traffic ~10-14x: ledpi measured football at 33.2 MB/h decoded vs 3.15 MB/h on the wire. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 12 ++++++++++++ src/common/fetch_service.py | 31 ++++++++++++++++++++++++++++++- test/test_fetch_service.py | 36 ++++++++++++++++++++++++++++++++++++ 3 files changed, 78 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 091db9df..5b9b9fde 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -69,6 +69,18 @@ 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 diff --git a/src/common/fetch_service.py b/src/common/fetch_service.py index c116776b..0f86e7cc 100644 --- a/src/common/fetch_service.py +++ b/src/common/fetch_service.py @@ -59,7 +59,10 @@ 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, 304s, errors, HTTP errors, +**Counters.** Requests, merged requests, bytes (``bytes`` decoded, as the +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, @@ -201,6 +204,7 @@ _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 @@ -616,6 +620,30 @@ 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) @@ -1117,6 +1145,7 @@ 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: diff --git a/test/test_fetch_service.py b/test/test_fetch_service.py index d2c17f4c..22a4231e 100644 --- a/test/test_fetch_service.py +++ b/test/test_fetch_service.py @@ -576,6 +576,42 @@ 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"): From d447cdd96575e5721226c929cca8c72a7ba76318 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Sun, 4 Oct 2026 19:14:21 -0400 Subject: [PATCH 3/4] test(starlark): stop the pixlet-editor route tests leaking a fake Popen into the captive-portal check (#761) TestPixletEditorHostDefaultsButDoesNotOverride patched Popen on the shared subprocess module. The app's before_request captive-portal hook runs subprocess.run (`with Popen(...) as p`) for `systemctl is-active hostapd` whenever its 30s AP-mode cache is cold, so on a Linux host with systemctl - the CI runner - the hook got the FakeProcess and the request 500'd with "'FakeProcess' object does not support the context manager protocol". Whether it happened depended on how long ago the previous request ran, hence the intermittency; Windows has no systemctl and never reached it. - Patch the starlark route module's own `subprocess` binding instead of the global Popen. - Pin is_ap_mode_active to False in this file's client fixture, so no request here shells out to systemctl/nmcli at all. Co-authored-by: Claude Opus 5.5 --- .../test_starlark_pixlet_routes.py | 22 +++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/test/web_interface/test_starlark_pixlet_routes.py b/test/web_interface/test_starlark_pixlet_routes.py index 43aaa06e..35673f93 100644 --- a/test/web_interface/test_starlark_pixlet_routes.py +++ b/test/web_interface/test_starlark_pixlet_routes.py @@ -26,8 +26,15 @@ import pytest @pytest.fixture -def client(): +def client(monkeypatch): + from web_interface import app as web_app from web_interface.app import app + # The captive-portal before_request hook shells out to systemctl/nmcli + # whenever its 30s cache is cold, so on a Linux host whether a request + # here runs subprocess depended on how long ago the previous one was -- + # and several tests below stub subprocess. Pin it: no test in this file + # is about AP mode. + monkeypatch.setattr(web_app, 'is_ap_mode_active', lambda: False) app.config['TESTING'] = True with app.test_client() as c: yield c @@ -1136,12 +1143,23 @@ class TestPixletEditorHostDefaultsButDoesNotOverride: captured['env'] = env return FakeProcess() + # Swap the route module's own ``subprocess`` binding, not the shared + # ``subprocess.Popen``: patching the attribute on the real module is + # process-wide, and the app's before_request hook (the captive-portal + # check) runs ``subprocess.run`` -- ``with Popen(...)`` -- whenever its + # 30s AP-mode cache is cold on a host with systemctl. On the Linux CI + # runner that handed it this FakeProcess and 500'd the request, but + # only when the previous request was more than 30s earlier. + fake_subprocess = types.ModuleType('subprocess') + fake_subprocess.__dict__.update(mod.subprocess.__dict__) + fake_subprocess.Popen = fake_popen + with patch.object(mod, '_validate_starlark_app_path', return_value=(app_dir, None)), \ patch.object(mod, '_PIXLET_EDITOR_SCRIPT', script), \ patch.object(mod, '_PIXLET_EDITOR_STATE', state_file), \ patch.object(mod, '_find_pixlet_binary', return_value='/usr/bin/pixlet'), \ - patch.object(mod.subprocess, 'Popen', side_effect=fake_popen), \ + patch.object(mod, 'subprocess', fake_subprocess), \ patch.dict(os.environ): if operator_host is None: os.environ.pop('PIXLET_EDITOR_HOST', None) From 378478124c48489d734a22d638fa7ffe602fd307 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Sun, 4 Oct 2026 19:27:51 -0400 Subject: [PATCH 4/4] test(on-demand): find the config write by key, not by position (#763) The font-usage publisher thread writes its own cache key at its own pace; the last set() call is not always the on-demand config. Same race #751 fixed for the restore-failed state test. Co-authored-by: Claude Opus 5.5 --- test/test_on_demand_live_and_restore.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/test/test_on_demand_live_and_restore.py b/test/test_on_demand_live_and_restore.py index ee74f0a5..f5c62f3c 100644 --- a/test/test_on_demand_live_and_restore.py +++ b/test/test_on_demand_live_and_restore.py @@ -87,8 +87,10 @@ class TestANamedLiveModeIsShown: def test_the_named_mode_survives_a_restart(self, football): football._activate_on_demand({'plugin_id': 'football-scoreboard', 'mode': 'ncaa_fb_live'}) - saved = football.cache_manager.set.call_args_list[-1] - assert saved.args[0] == 'display_on_demand_config' + # The last on-demand config write, not the last write of any key: the + # font-usage publisher thread writes its own key at its own pace. + saved = [c for c in football.cache_manager.set.call_args_list + if c.args and c.args[0] == 'display_on_demand_config'][-1] config = saved.args[1] assert config['named_mode'] == 'ncaa_fb_live'