From 18c08d3c152f056396a36c7f66c95900a47fd2bd Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 1 Oct 2026 22:36:10 -0400 Subject: [PATCH 1/6] perf(odds): stop serializing every odds response for a debug line get_odds() logged the raw ESPN body with an f-string around json.dumps(raw_data, indent=2), so every fetched response was pretty-printed and thrown away with DEBUG off. The json.dumps debug lines in _extract_espn_data had the same cost. Those are now guarded with isEnabledFor(DEBUG), and the other debug f-strings on the fetch path use %-style arguments. Same messages at DEBUG; nothing else changes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Uc5DAbSwGGUTm3MrCtpC2m --- src/base_odds_manager.py | 32 ++++++++++++++++++++------------ test/test_base_odds_manager.py | 18 ++++++++++++++++++ 2 files changed, 38 insertions(+), 12 deletions(-) diff --git a/src/base_odds_manager.py b/src/base_odds_manager.py index eaccb4cc0..918f90cc5 100644 --- a/src/base_odds_manager.py +++ b/src/base_odds_manager.py @@ -146,7 +146,7 @@ def get_odds(self, sport: str | None, league: str | None, event_id: str, if _is_no_odds_marker(cached_data): self.logger.debug("Cached no-odds marker for %s", cache_key) return None - self.logger.debug(f"Using cached odds from ESPN for {cache_key}") + self.logger.debug("Using cached odds from ESPN for %s", cache_key) return cached_data if time.monotonic() < self._skip_network_until: @@ -159,7 +159,7 @@ def get_odds(self, sport: str | None, league: str | None, event_id: str, self._skip_network_until - time.monotonic()) return None - self.logger.debug(f"Cache miss - fetching fresh odds from ESPN for {cache_key}") + self.logger.debug("Cache miss - fetching fresh odds from ESPN for %s", cache_key) try: # Map league names to ESPN API format @@ -173,7 +173,7 @@ def get_odds(self, sport: str | None, league: str | None, event_id: str, espn_league = league_mapping.get(league, league) url = f"{self.base_url}/{sport}/leagues/{espn_league}/events/{event_id}/competitions/{event_id}/odds" - self.logger.debug(f"Requesting odds from URL: {url}") + self.logger.debug("Requesting odds from URL: %s", url) response = fetch_get(self.session, url, timeout=self.request_timeout) response.raise_for_status() @@ -181,15 +181,19 @@ def get_odds(self, sport: str | None, league: str | None, event_id: str, self._skip_network_until = 0.0 # reachable again - self.logger.debug(f"Received raw odds data from ESPN: {json.dumps(raw_data, indent=2)}") + # Guarded, not just %-style: the json.dumps argument would still be + # built for every response with DEBUG off. + if self.logger.isEnabledFor(logging.DEBUG): + self.logger.debug("Received raw odds data from ESPN: %s", + json.dumps(raw_data, indent=2)) odds_data = self._extract_espn_data(raw_data) if odds_data: - self.logger.debug(f"Successfully extracted odds data: {odds_data}") + self.logger.debug("Successfully extracted odds data: %s", odds_data) self.cache_manager.set(cache_key, odds_data, ttl=interval) - self.logger.debug(f"Saved odds data to cache for {cache_key} with TTL {interval}s") + self.logger.debug("Saved odds data to cache for %s with TTL %ss", cache_key, interval) else: - self.logger.debug(f"No odds data available for {cache_key}") + self.logger.debug("No odds data available for %s", cache_key) # Cache the absence too, so the game is not re-requested # on every update until the interval passes. self.cache_manager.set(cache_key, {"no_odds": True}, ttl=interval) @@ -223,12 +227,12 @@ def _extract_espn_data(self, data: Dict[str, Any]) -> Optional[Dict[str, Any]]: Returns: Formatted odds data dictionary or None """ - self.logger.debug(f"Extracting ESPN odds data. Data keys: {list(data.keys())}") + self.logger.debug("Extracting ESPN odds data. Data keys: %s", list(data.keys())) if "items" in data and data["items"]: - self.logger.debug(f"Found {len(data['items'])} items in odds data") + self.logger.debug("Found %d items in odds data", len(data['items'])) item = data["items"][0] - self.logger.debug(f"First item keys: {list(item.keys())}") + self.logger.debug("First item keys: %s", list(item.keys())) # The ESPN API returns odds data directly in the item, not in a # providers array. ESPN sends explicit JSON nulls for absent @@ -251,13 +255,17 @@ def _extract_espn_data(self, data: Dict[str, Any]) -> Optional[Dict[str, Any]]: .get("pointSpread") or {}).get("value") } } - self.logger.debug(f"Returning extracted odds data: {json.dumps(extracted_data, indent=2)}") + if self.logger.isEnabledFor(logging.DEBUG): + self.logger.debug("Returning extracted odds data: %s", + json.dumps(extracted_data, indent=2)) return extracted_data # Check if this is a valid empty response or an unexpected structure if "count" in data and data["count"] == 0 and "items" in data and data["items"] == []: # This is a valid empty response - no odds available for this game - self.logger.debug(f"No odds available for this game. Response: {json.dumps(data, indent=2)}") + if self.logger.isEnabledFor(logging.DEBUG): + self.logger.debug("No odds available for this game. Response: %s", + json.dumps(data, indent=2)) return None else: # This is an unexpected response structure diff --git a/test/test_base_odds_manager.py b/test/test_base_odds_manager.py index f8e6adb75..34fd8bc2b 100644 --- a/test/test_base_odds_manager.py +++ b/test/test_base_odds_manager.py @@ -200,6 +200,24 @@ def test_routine_fetches_log_nothing_at_info( manager.get_odds('football', 'nfl', '401') # hit assert [r for r in caplog.records if r.levelno == logging.INFO] == [] + def test_debug_off_does_not_serialize_the_response( + self, manager, mock_get, caplog): + # json.dumps(indent=2) of every odds body ran even with DEBUG off. + with caplog.at_level(logging.INFO, logger=manager.logger.name), \ + patch('src.base_odds_manager.json.dumps') as dumps: + assert manager.get_odds('football', 'nfl', '401') == FULL_EXTRACTED + dumps.assert_not_called() + + def test_debug_on_still_logs_the_raw_response( + self, manager, mock_get, caplog): + with caplog.at_level(logging.DEBUG, logger=manager.logger.name): + manager.get_odds('football', 'nfl', '401') + messages = [r.getMessage() for r in caplog.records] + assert any(m.startswith('Received raw odds data from ESPN: {') + for m in messages), messages + assert any(m.startswith('Returning extracted odds data: {') + for m in messages), messages + # --------------------------------------------------------------------------- # _extract_espn_data From 25008daddf3f62a82e7de1c1c5f5aeba859aad01 Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 1 Oct 2026 22:38:21 -0400 Subject: [PATCH 2/6] perf(scroll): drop a redundant full-frame copy in the integer slice path _get_visible_portion_integer() ran np.ascontiguousarray() on the visible column slice and then tobytes(), copying the frame twice. tobytes() on the non-contiguous view already returns C-order bytes, so the first copy bought nothing. A test pins the bytes against the old expression. On a Pi 4 the bytes step at 512x64 went from ~45 us to ~21 us a frame (timeit, best of 5). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Uc5DAbSwGGUTm3MrCtpC2m --- src/common/scroll_helper.py | 9 ++++++--- test/test_scroll_helper.py | 16 ++++++++++++++++ 2 files changed, 22 insertions(+), 3 deletions(-) diff --git a/src/common/scroll_helper.py b/src/common/scroll_helper.py index a0f2bac87..d09c8b411 100644 --- a/src/common/scroll_helper.py +++ b/src/common/scroll_helper.py @@ -573,9 +573,12 @@ def _get_visible_portion_integer(self, start_x: int, end_x: int) -> Image.Image: img_w = self.cached_array.shape[1] if end_x <= img_w: - # Normal case: single contiguous slice (fastest path) - frame_array = np.ascontiguousarray(self.cached_array[:, start_x:end_x]) - return Image.frombytes('RGB', _size, frame_array.tobytes()) + # Normal case: single contiguous slice (fastest path). tobytes() + # on the column-slice view already returns C-order bytes, so + # ascontiguousarray() first only added a second full-frame copy. + return Image.frombytes( + 'RGB', _size, + self.cached_array[:, start_x:end_x].tobytes()) else: # Ensure frame buffer is allocated for all non-simple paths if self._frame_buffer is None or self._frame_buffer.shape != (self.display_height, self.display_width, 3): diff --git a/test/test_scroll_helper.py b/test/test_scroll_helper.py index a04eabfeb..80a53b949 100644 --- a/test/test_scroll_helper.py +++ b/test/test_scroll_helper.py @@ -6,6 +6,7 @@ reset_scroll, clear_cache, get_scroll_info. """ +import numpy as np import pytest import time from unittest.mock import patch @@ -172,6 +173,21 @@ def test_different_positions_give_different_images(self, helper): # Just verify both are valid PIL images with correct size assert img1.width == img2.width == DISPLAY_W + @pytest.mark.parametrize("start_x", [0, 1, 37, 200 - DISPLAY_W]) + def test_integer_slice_is_byte_identical_to_a_contiguous_copy( + self, helper, start_x): + # The integer path dropped np.ascontiguousarray() before tobytes(): + # a column slice of the strip is not C-contiguous, and tobytes() + # must still give the same C-order bytes the copy did. + rng = np.random.default_rng(start_x) + strip = rng.integers(0, 256, (DISPLAY_H, 200, 3), dtype=np.uint8) + helper.cached_array = strip + view = strip[:, start_x:start_x + DISPLAY_W] + assert not view.flags["C_CONTIGUOUS"] + frame = helper._get_visible_portion_integer(start_x, start_x + DISPLAY_W) + assert frame.tobytes() == np.ascontiguousarray(view).tobytes() + assert view.tobytes() == np.ascontiguousarray(view).tobytes() + # --------------------------------------------------------------------------- # reset_scroll / clear_cache From 09838a75a5ef53801246566d417a974ee84d467f Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 1 Oct 2026 22:39:29 -0400 Subject: [PATCH 3/6] perf(systemd): cap malloc arenas for the web interface too ledmatrix.service has set MALLOC_ARENA_MAX=2 since #476: glibc gives each allocating thread its own arena (up to 8 x CPU count) and never hands a grown one back. ledmatrix-web.service runs a threaded Flask server with the same exposure but had no cap. Both installers render the template with sed, so the line installs unchanged; on an existing install the startup drift check reports the unit as changed until install_service.sh or install_web_service.sh is re-run, as for any template change. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Uc5DAbSwGGUTm3MrCtpC2m --- systemd/ledmatrix-web.service | 5 +++++ test/test_systemd_malloc_arenas.py | 14 +++++++++----- 2 files changed, 14 insertions(+), 5 deletions(-) diff --git a/systemd/ledmatrix-web.service b/systemd/ledmatrix-web.service index 98178e71e..7ea9d335a 100644 --- a/systemd/ledmatrix-web.service +++ b/systemd/ledmatrix-web.service @@ -19,6 +19,11 @@ Type=simple User=__USER__ WorkingDirectory=__PROJECT_ROOT_DIR__ Environment=USE_THREADING=1 +# Cap glibc's malloc arenas, as ledmatrix.service does: each allocating thread +# can get its own arena, up to 8 x CPU count (24 on a 3-core Pi), and a grown +# arena is never handed back to the OS. This threaded Flask process would hold +# that memory the same way. See ledmatrix.service for the measurement. +Environment=MALLOC_ARENA_MAX=2 ExecStart=/usr/bin/python3 __PROJECT_ROOT_DIR__/scripts/utils/start_web_conditionally.py Restart=on-failure RestartSec=10 diff --git a/test/test_systemd_malloc_arenas.py b/test/test_systemd_malloc_arenas.py index bb4bc8f06..34802afda 100644 --- a/test/test_systemd_malloc_arenas.py +++ b/test/test_systemd_malloc_arenas.py @@ -30,6 +30,8 @@ import pytest UNIT = (Path(__file__).resolve().parent.parent / "systemd" / "ledmatrix.service") +#: The web interface is a threaded process too, so it carries the same cap. +WEB_UNIT = UNIT.parent / "ledmatrix-web.service" #: The value the unit is expected to carry. 2 is the usual choice for a #: threaded Python process; 1-4 all keep some of the saving, but only one of @@ -49,8 +51,9 @@ def test_the_unit_exists(): assert UNIT.is_file(), f"{UNIT} is missing" -def test_malloc_arena_max_is_capped(): - env = _environment(UNIT.read_text(encoding="utf-8")) +@pytest.mark.parametrize("unit", [UNIT, WEB_UNIT], ids=lambda p: p.name) +def test_malloc_arena_max_is_capped(unit): + env = _environment(unit.read_text(encoding="utf-8")) assert "MALLOC_ARENA_MAX" in env, ( "the display unit does not cap glibc arenas; on a 3-core Pi the default " "ceiling is 24 and a measured rig held 23 of them, 920 MB" @@ -69,9 +72,10 @@ def test_malloc_arena_max_is_capped(): ) -def test_the_reason_is_recorded_next_to_it(): +@pytest.mark.parametrize("unit", [UNIT, WEB_UNIT], ids=lambda p: p.name) +def test_the_reason_is_recorded_next_to_it(unit): """A bare tuning knob invites removal by whoever meets it next.""" - text = UNIT.read_text(encoding="utf-8") + text = unit.read_text(encoding="utf-8") index = text.index("Environment=MALLOC_ARENA_MAX") preamble = text[:index].splitlines()[-12:] comment = "\n".join(line for line in preamble if line.startswith("#")) @@ -82,7 +86,7 @@ def test_the_reason_is_recorded_next_to_it(): ) -@pytest.mark.parametrize("unit", ["ledmatrix.service"]) +@pytest.mark.parametrize("unit", ["ledmatrix.service", "ledmatrix-web.service"]) def test_the_unit_still_parses_as_ini(unit): """systemd will refuse a malformed unit, and the panel stays dark.""" import configparser From b38828aeef6f586c76bc1800302ad04e6d0eaf78 Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 1 Oct 2026 22:42:15 -0400 Subject: [PATCH 4/6] perf(fetch): parse core ESPN responses with response_json APIHelper.get/post, BaseOddsManager.get_odds, LogoDownloader's two team fetches and DynamicTeamResolver's rankings fetch called response.json(), the stdlib parser, while background_data_service and espn_dates already use src.common.json_body.response_json (orjson when installed, ~1.7x faster on a Pi 4, holding the GIL for less of the parse). response_json falls back to response.json() on anything orjson rejects, so a bad body still raises requests' JSONDecodeError, which every one of these call sites already catches; a test pins that with real requests.Response objects. Without orjson nothing changes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Uc5DAbSwGGUTm3MrCtpC2m --- src/base_odds_manager.py | 3 ++- src/common/api_helper.py | 5 +++-- src/dynamic_team_resolver.py | 3 ++- src/logo_downloader.py | 5 +++-- test/test_cache_stale_header.py | 21 +++++++++++++++++++++ 5 files changed, 31 insertions(+), 6 deletions(-) diff --git a/src/base_odds_manager.py b/src/base_odds_manager.py index 918f90cc5..a99845e0d 100644 --- a/src/base_odds_manager.py +++ b/src/base_odds_manager.py @@ -20,6 +20,7 @@ from src.common.api_helper import DEFAULT_HTTP_HEADERS from src.common.fetch_service import fetch_get, share_connection_pool +from src.common.json_body import response_json @@ -177,7 +178,7 @@ def get_odds(self, sport: str | None, league: str | None, event_id: str, response = fetch_get(self.session, url, timeout=self.request_timeout) response.raise_for_status() - raw_data = response.json() + raw_data = response_json(response) self._skip_network_until = 0.0 # reachable again diff --git a/src/common/api_helper.py b/src/common/api_helper.py index d9915f775..a0d73971e 100644 --- a/src/common/api_helper.py +++ b/src/common/api_helper.py @@ -12,6 +12,7 @@ from types import MappingProxyType from src.common.espn_dates import ESPN_MAX_LIMIT from src.common.fetch_service import fetch_get, fetch_post, share_connection_pool +from src.common.json_body import response_json from typing import TYPE_CHECKING, Any, Dict, Mapping, Optional, cast import requests @@ -143,7 +144,7 @@ def get(self, url: str, params: Optional[Dict] = None, response.raise_for_status() # Parse JSON response - data: Dict[Any, Any] = response.json() + data: Dict[Any, Any] = response_json(response) # Cache response if cache key provided if cache_key and self.cache_manager: @@ -271,7 +272,7 @@ def post(self, url: str, data: Optional[Dict] = None, ) response.raise_for_status() - return cast(Optional[Dict[Any, Any]], response.json()) + return cast(Optional[Dict[Any, Any]], response_json(response)) except requests.exceptions.RequestException as e: self.logger.error(f"POST request failed for {url}: {e}") diff --git a/src/dynamic_team_resolver.py b/src/dynamic_team_resolver.py index f7a06213d..c90c9a4f7 100644 --- a/src/dynamic_team_resolver.py +++ b/src/dynamic_team_resolver.py @@ -23,6 +23,7 @@ from typing import Any, Dict, List from src.common.api_helper import DEFAULT_HTTP_HEADERS +from src.common.json_body import response_json logger = logging.getLogger(__name__) @@ -157,7 +158,7 @@ def _fetch_ncaa_fb_rankings(self) -> Dict[str, int]: response = requests.get(rankings_url, headers=dict(DEFAULT_HTTP_HEADERS), timeout=self.request_timeout) response.raise_for_status() - data = response.json() + data = response_json(response) rankings = {} rankings_data = data.get('rankings', []) diff --git a/src/logo_downloader.py b/src/logo_downloader.py index b4f3f64e0..22ab83ab1 100644 --- a/src/logo_downloader.py +++ b/src/logo_downloader.py @@ -21,6 +21,7 @@ from requests.adapters import HTTPAdapter from urllib3.util.retry import Retry from src.common.api_helper import DEFAULT_HTTP_HEADERS +from src.common.json_body import response_json from src.common.logo_helper import MAX_LOGO_BYTES from src.common.permission_utils import ( ensure_directory_permissions, @@ -481,7 +482,7 @@ def fetch_teams_data(self, league: str) -> Optional[Dict]: logger.info(f"Fetching team data for {league} from ESPN API...") response = self.session.get(api_url, params={'limit':1000},headers=self.headers, timeout=self.request_timeout) response.raise_for_status() - data: Dict = response.json() + data: Dict = response_json(response) logger.info(f"Successfully fetched team data for {league}") return data @@ -505,7 +506,7 @@ def fetch_single_team(self, league: str, team_id: str) -> Optional[Dict]: logger.info(f"Fetching team data for team {team_id} in {league} from ESPN API...") response = self.session.get(f"{api_url}/{team_id}", headers=self.headers, timeout=self.request_timeout) response.raise_for_status() - data: Dict = response.json() + data: Dict = response_json(response) logger.info(f"Successfully fetched team data for {team_id} in {league}") return data diff --git a/test/test_cache_stale_header.py b/test/test_cache_stale_header.py index 026b982d1..e58f6a2f1 100644 --- a/test/test_cache_stale_header.py +++ b/test/test_cache_stale_header.py @@ -116,3 +116,24 @@ def test_response_json_prefers_orjson_and_falls_back(): assert json_body.response_json(response) == payload # A response object without bytes content (a test double) still works. assert json_body.response_json(SimpleNamespace(json=lambda: payload)) == payload + + +@pytest.mark.parametrize("body", [b"not json", b"", b'{"a": NaN}', b"\xef\xbb\xbf{}"]) +def test_response_json_raises_and_returns_what_requests_does(body): + # The core fetch paths (api_helper, base_odds_manager, logo_downloader, + # dynamic_team_resolver) catch requests' JSONDecodeError on a bad body, so + # response_json must raise exactly that, and parse whatever requests + # parses (NaN, which orjson rejects) to the same value. + import requests + + response = requests.models.Response() + response._content = body + response.status_code = 200 + response.headers["Content-Type"] = "application/json" + try: + expected = response.json() + except requests.exceptions.JSONDecodeError: + with pytest.raises(requests.exceptions.JSONDecodeError): + json_body.response_json(response) + else: + assert json.dumps(json_body.response_json(response)) == json.dumps(expected) From 1d5bc1078fe0c40c79c7853facf545719707f869 Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 1 Oct 2026 22:44:31 -0400 Subject: [PATCH 5/6] perf(scroll): log healthy scroll frame stats at DEBUG Every scroller logged a "Scroll frame stats" line at INFO every 5 s, so a healthy rig's journal was mostly these lines. As Vegas's FPS line already does, the line now goes to INFO only for a degraded window (fps below 0.9 of the rate the window was locked to, 1 / its median, or more than 1% of frames stalled), the window after one, and a 5-minute heartbeat per scroller; every window is still logged at DEBUG. The window, the stats and the line's text are unchanged. docs/SCROLL_PERFORMANCE.md says how to see every window. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Uc5DAbSwGGUTm3MrCtpC2m --- docs/SCROLL_PERFORMANCE.md | 16 +++++++-- src/common/scroll_helper.py | 50 ++++++++++++++++++++++++--- test/test_scroll_helper.py | 69 +++++++++++++++++++++++++++++++++++++ 3 files changed, 129 insertions(+), 6 deletions(-) diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 74ec58c4e..4c44865a8 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -246,8 +246,16 @@ mean exactly 10 ms, so a ticker stalling on half its frames still averages to a healthy 100 fps. The stats line reports the tail for that reason — read the percentiles, not the fps. -Every scroller emits one line every 5 seconds covering *every* frame in that -window, tagged with the plugin it came from: +Every scroller summarises each 5-second window, covering *every* frame in it, +in one line tagged with the plugin it came from. At the default log level the +line reaches the journal only when it is worth reading: a **degraded** window +(frame rate below 90% of the rate the window was locked to, i.e. 1 / its own +median -- the same 0.9 Vegas's `Vegas FPS` line uses -- or more than 1% of its +frames stalled), the first window after one (the recovery), and otherwise once +every 5 minutes per scroller as a heartbeat, so silence means stopped rather +than fine. Every window is logged at DEBUG: to see them all, run the display +with `-d` or `LEDMATRIX_DEBUG=true` (see +[CONFIG_DEBUGGING.md](CONFIG_DEBUGGING.md#enable-debug-logging)). ```bash journalctl -u ledmatrix --since "-10min" --no-pager | grep "Scroll frame stats" @@ -286,6 +294,10 @@ journalctl -u ledmatrix --since "-3h" --no-pager | grep "Scroll frame stats" \ | sort -k7 -rn ``` +At the default log level that ranks the windows the journal kept -- the +degraded ones, recoveries and heartbeats -- so it over-weights bad windows; +rank a debug run for an unbiased average, or soak the rig (below). + The `$2 < 1000` guard drops windows whose median is a whole second or more. Those are not frames. Until the idle-gap fix in `log_frame_rate()`, the first frame of every scroll was timed against the end of the *previous* scroll, so diff --git a/src/common/scroll_helper.py b/src/common/scroll_helper.py index d09c8b411..e4da770d1 100644 --- a/src/common/scroll_helper.py +++ b/src/common/scroll_helper.py @@ -28,6 +28,30 @@ # long over one frame, so a sample this large is an idle gap between scrolls. FPS_LOG_INTERVAL = 5.0 +# The stats line goes to INFO only when a window is worth an operator's +# attention, as Vegas's FPS line does (src/vegas_mode/coordinator.py): every +# 5s from every scroller was most of the journal on a healthy rig. A window is +# degraded when its frame rate falls below this fraction of the rate it was +# locked to (1 / its own median frame time; same 0.9 as Vegas) ... +STATS_HEALTHY_FRACTION = 0.9 +# ... or when more than this share of its frames stalled (past 1.5x the +# median). A 1% stall rate barely moves the mean, so the fps test alone would +# miss the judder this line exists to show. +STATS_DEGRADED_STALL_RATE = 0.01 +# A healthy scroller still logs at INFO this often, so silence in the journal +# means stopped rather than fine. Every window is still logged at DEBUG. +STATS_HEARTBEAT_INTERVAL = 300.0 + + +def frame_stats_degraded(stats: Dict[str, Any]) -> bool: + """Whether one frame_stats() window is worth logging at INFO.""" + n = stats["frames"] + if n == 0 or stats["median"] <= 0: + return False + locked_fps = 1.0 / stats["median"] + return (stats["fps"] < locked_fps * STATS_HEALTHY_FRACTION + or stats["stalls"] > n * STATS_DEGRADED_STALL_RATE) + def _rgb_pixels(item) -> np.ndarray: """An appended item's pixels as an RGB array, as pasting it would draw them.""" @@ -189,6 +213,11 @@ def __init__(self, display_width: int, display_height: int, # Every frame time since the last stats line, so the 5s summary can # report the tail rather than one arbitrary sample. Cleared on log. self._window: list = [] + # INFO-level stats bookkeeping (see STATS_HEARTBEAT_INTERVAL). Kept + # across reset_scroll(): a heartbeat per scroll start would bring the + # chatter back. 0.0 so the first window after start-up is at INFO. + self._stats_last_info_log = 0.0 + self._stats_was_degraded = False # Scrolling state management self.is_scrolling = False @@ -1210,10 +1239,23 @@ def log_frame_rate(self) -> None: # as an idle gap. There is nothing to report, and reporting the # gap itself is the bug above. if self._window: - self.logger.info( - "Scroll frame stats - %s", - format_frame_stats(self._window), - ) + # INFO when degraded, on the window that recovers from it, and + # as a slow heartbeat; DEBUG otherwise. + degraded = frame_stats_degraded(frame_stats(self._window)) + if (degraded or self._stats_was_degraded + or current_time - self._stats_last_info_log + >= STATS_HEARTBEAT_INTERVAL): + self.logger.info( + "Scroll frame stats - %s", + format_frame_stats(self._window), + ) + self._stats_last_info_log = current_time + elif self.logger.isEnabledFor(logging.DEBUG): + self.logger.debug( + "Scroll frame stats - %s", + format_frame_stats(self._window), + ) + self._stats_was_degraded = degraded self.last_fps_log_time = current_time self.frame_count = 0 self._window = [] diff --git a/test/test_scroll_helper.py b/test/test_scroll_helper.py index 80a53b949..dc607b98f 100644 --- a/test/test_scroll_helper.py +++ b/test/test_scroll_helper.py @@ -412,6 +412,75 @@ def test_log_frame_rate_emits_the_line_and_clears_the_window(self, helper): assert helper._window == [] +class TestFrameStatsLogLevel: + """The stats line is INFO only when a window is degraded, on the window + that recovers, and as a 5-minute heartbeat; every other window is DEBUG. + Every 5s from every scroller at INFO was most of a healthy rig's journal. + """ + + HEALTHY = [0.010] * 500 + # 10% of frames a whole refresh late: fps 90.9 against a locked 100. + SLOW = [0.010] * 450 + [0.020] * 50 + # 2% stalled: barely moves the mean, but it is the judder to see. + STALLING = [0.010] * 490 + [0.025] * 10 + + def _log_window(self, helper, window): + helper._window = list(window) + helper.last_frame_time = time.time() + helper.last_fps_log_time = 0.0 + with patch.object(helper.logger, "info") as info, \ + patch.object(helper.logger, "debug") as debug, \ + patch.object(helper.logger, "isEnabledFor", return_value=True): + helper.log_frame_rate() + return info, debug + + def test_degraded_predicate(self): + from src.common.scroll_helper import frame_stats_degraded + assert not frame_stats_degraded(frame_stats(self.HEALTHY)) + assert frame_stats_degraded(frame_stats(self.SLOW)) + assert frame_stats_degraded(frame_stats(self.STALLING)) + # One stall in 500 is a normal wobble, not degraded. + assert not frame_stats_degraded( + frame_stats([0.010] * 499 + [0.025])) + + def test_first_window_is_info_as_a_heartbeat(self, helper): + info, debug = self._log_window(helper, self.HEALTHY) + assert info.called and not debug.called + + def test_healthy_window_after_the_heartbeat_is_debug(self, helper): + helper._stats_last_info_log = time.time() + info, debug = self._log_window(helper, self.HEALTHY) + assert not info.called + assert "Scroll frame stats" in debug.call_args[0][0] + + @pytest.mark.parametrize("window", ["SLOW", "STALLING"]) + def test_degraded_window_is_info(self, helper, window): + helper._stats_last_info_log = time.time() + info, debug = self._log_window(helper, getattr(self, window)) + assert "Scroll frame stats" in info.call_args[0][0] + assert not debug.called + + def test_recovery_window_is_info_then_quiet(self, helper): + helper._stats_last_info_log = time.time() + self._log_window(helper, self.SLOW) + info, _ = self._log_window(helper, self.HEALTHY) + assert info.called, "the recovery was not reported" + info, debug = self._log_window(helper, self.HEALTHY) + assert not info.called and debug.called + + def test_heartbeat_comes_back_after_the_interval(self, helper): + from src.common.scroll_helper import STATS_HEARTBEAT_INTERVAL + helper._stats_last_info_log = time.time() - STATS_HEARTBEAT_INTERVAL - 1 + info, _ = self._log_window(helper, self.HEALTHY) + assert info.called + + def test_reset_scroll_does_not_rearm_the_heartbeat(self, helper): + helper._stats_last_info_log = time.time() + helper.reset_scroll() + info, _ = self._log_window(helper, self.HEALTHY) + assert not info.called + + class TestIdleGapIsNotAFrame: """The first frame of a scroll has no predecessor, so timing one measures the idle gap since the last scroll rather than a frame. From 69f179b0d470ce016819fb3c80c5d6eeeea2c60c Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 1 Oct 2026 22:45:01 -0400 Subject: [PATCH 6/6] docs(changelog): note the cheap per-frame and per-fetch savings Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Uc5DAbSwGGUTm3MrCtpC2m --- CHANGELOG.md | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 29c9f698a..06749a4c6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,33 @@ accepts both, but the store flags the old spelling as deprecated ## Unreleased +### Cheap per-frame and per-fetch savings + +- `BaseOddsManager.get_odds()` no longer pretty-prints every odds response + for a debug line: the `json.dumps(..., indent=2)` calls in the fetch path + and `_extract_espn_data` are guarded with `isEnabledFor(DEBUG)`, and the + other debug f-strings there take %-style arguments. Same messages at DEBUG. +- `ScrollHelper`'s integer frame path (`_get_visible_portion_integer`) takes + `tobytes()` straight from the strip's column slice instead of copying it + with `np.ascontiguousarray()` first; the bytes are identical (a test pins + them). At 512x64 on a Pi 4 the bytes step went from ~45 us to ~21 us a + frame. +- `systemd/ledmatrix-web.service` sets `MALLOC_ARENA_MAX=2`, as + `ledmatrix.service` has since #476. Existing installs pick it up when + `scripts/install/install_service.sh` or `install_web_service.sh` is re-run; + until then the startup drift check reports the web unit as changed. +- `APIHelper.get()`/`post()`, `BaseOddsManager.get_odds()`, the two + `LogoDownloader` team fetches and `DynamicTeamResolver`'s rankings fetch + parse with `src.common.json_body.response_json` (orjson when installed), + like `background_data_service` already did. A body orjson rejects falls + back to `response.json()`, so a bad body raises the same + `requests.exceptions.JSONDecodeError` these call sites already catch. +- The `Scroll frame stats` line is logged at INFO only for a degraded window + (fps under 0.9 of the rate the window was locked to, or more than 1% of + frames stalled), the window after one, and a 5-minute heartbeat per + scroller, as the `Vegas FPS` line already was; every window is still logged + at DEBUG. `docs/SCROLL_PERFORMANCE.md` says how to see them all. + ### Garbage-collection pauses in the frame stats - The display now times every Python garbage collection