diff --git a/CHANGELOG.md b/CHANGELOG.md index 1ad4093b..64b0e654 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 @@ -57,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/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() 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"): diff --git a/test/test_on_demand_live_and_restore.py b/test/test_on_demand_live_and_restore.py index 1d2ec102..f5c62f3c 100644 --- a/test/test_on_demand_live_and_restore.py +++ b/test/test_on_demand_live_and_restore.py @@ -21,18 +21,6 @@ SPORTS_MODES = ['nfl_live', 'nfl_recent', 'nfl_upcoming', 'ncaa_fb_live', 'ncaa_fb_recent', 'ncaa_fb_upcoming'] -def _last_write(cache_manager, key): - """The last ``cache_manager.set(key, ...)`` call. - - Not simply the last ``set`` call: the controller's font-usage publisher - thread writes ``font_usage_snapshot`` to the same cache manager whenever - it wakes, so on a slow runner it can land after the write under test. - """ - writes = [c for c in cache_manager.set.call_args_list if c.args and c.args[0] == key] - assert writes, f"nothing was written to {key!r}" - return writes[-1] - - def _sports_plugin(has_live_content=False): plugin = MagicMock(spec=['display', 'has_live_content', 'has_live_priority', 'get_live_modes']) @@ -99,7 +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 = _last_write(football.cache_manager, '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' @@ -131,7 +122,10 @@ class TestARestoreWithNothingToResume: def test_it_is_reported_as_an_error(self, restored): assert restored.on_demand_status == 'error' assert restored.on_demand_last_error == 'restore-failed' - published = _last_write(restored.cache_manager, 'display_on_demand_state') + # The last on-demand state write, not the last write of any key: the + # font-usage publisher thread writes its own key at its own pace. + published = [c for c in restored.cache_manager.set.call_args_list + if c.args and c.args[0] == 'display_on_demand_state'][-1] assert published.args[1]['status'] == 'error' assert published.args[1]['error'] == 'restore-failed' diff --git a/test/web_interface/test_starlark_pixlet_routes.py b/test/web_interface/test_starlark_pixlet_routes.py index 4e97eb4e..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 @@ -1131,25 +1138,28 @@ class TestPixletEditorHostDefaultsButDoesNotOverride: class FakeProcess: pid = 424242 - real_popen = mod.subprocess.Popen - def fake_popen(cmd, *args, env=None, **kwargs): - # Only the editor launch is faked. Patching subprocess.Popen - # patches it for the whole request, and the captive-portal - # before_request hook runs `systemctl is-active hostapd` through - # subprocess.run whenever its 30s cache has expired -- which - # needs a real process (run() uses it as a context manager). - if str(script) not in cmd: - return real_popen(cmd, *args, env=env, **kwargs) - captured['env'] = env + if env is not None: + 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)