perf: cheap per-frame and per-fetch savings

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.
+
 ### Fewer SD-card writes from the cache
 
 - **An unchanged `CacheManager.set()` no longer rewrites the file.**

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

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
 
 
 
@@ -146,7 +147,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 +160,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,26 +174,30 @@ 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)
 
             # The response cache may answer only inside this caller's own
             # interval, the age at which its cached odds expire anyway.
             response = fetch_get(self.session, url, timeout=self.request_timeout,
                                  cache_max_age=interval)
             response.raise_for_status()
-            raw_data = response.json()
+            raw_data = response_json(response)
 
             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)
@@ -226,12 +231,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
@@ -254,13 +259,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

src/common/api_helper.py

@@ -17,6 +17,7 @@
     store_espn_scoreboard_cache,
 )
 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
@@ -157,7 +158,7 @@ def _get(self, url: str, params: Optional[Dict], headers: Optional[Dict],
             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:
@@ -304,7 +305,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}")

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
@@ -573,9 +602,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):
@@ -1207,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 = []

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', [])

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

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

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

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)