perf: cheap per-frame and per-fetch savings (#725)

Six small savings with no behaviour change: the odds fetch no longer pretty-prints every response for a debug line; the scroll integer-slice path drops a redundant full-frame np.ascontiguousarray; ledmatrix-web.service gets MALLOC_ARENA_MAX=2 like the display unit; core ESPN responses are parsed via response_json (orjson when installed); and the scroll frame stats go to INFO only for degraded windows plus a 5-minute heartbeat.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Chuck
2026-10-03 14:26:03 -04:00
committed by GitHub
co-authored by Claude Opus 5.5
parent 7bb85c0356
commit ed0753c1ca
12 changed files with 261 additions and 32 deletions
+27
View File
@@ -19,6 +19,33 @@ accepts both, but the store flags the old spelling as deprecated
## Unreleased ## 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 ### Fewer SD-card writes from the cache
- **An unchanged `CacheManager.set()` no longer rewrites the file.** - **An unchanged `CacheManager.set()` no longer rewrites the file.**
+14 -2
View File
@@ -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 healthy 100 fps. The stats line reports the tail for that reason — read the
percentiles, not the fps. percentiles, not the fps.
Every scroller emits one line every 5 seconds covering *every* frame in that Every scroller summarises each 5-second window, covering *every* frame in it,
window, tagged with the plugin it came from: 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 ```bash
journalctl -u ledmatrix --since "-10min" --no-pager | grep "Scroll frame stats" 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 | 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. 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 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 frame of every scroll was timed against the end of the *previous* scroll, so
+22 -13
View File
@@ -20,6 +20,7 @@ from typing import Dict, Any, Optional, List, cast
from src.common.api_helper import DEFAULT_HTTP_HEADERS from src.common.api_helper import DEFAULT_HTTP_HEADERS
from src.common.fetch_service import fetch_get, share_connection_pool from src.common.fetch_service import fetch_get, share_connection_pool
from src.common.json_body import response_json
@@ -146,7 +147,7 @@ class BaseOddsManager:
if _is_no_odds_marker(cached_data): if _is_no_odds_marker(cached_data):
self.logger.debug("Cached no-odds marker for %s", cache_key) self.logger.debug("Cached no-odds marker for %s", cache_key)
return None 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 return cached_data
if time.monotonic() < self._skip_network_until: if time.monotonic() < self._skip_network_until:
@@ -159,7 +160,7 @@ class BaseOddsManager:
self._skip_network_until - time.monotonic()) self._skip_network_until - time.monotonic())
return None 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: try:
# Map league names to ESPN API format # Map league names to ESPN API format
@@ -173,26 +174,30 @@ class BaseOddsManager:
espn_league = league_mapping.get(league, league) espn_league = league_mapping.get(league, league)
url = f"{self.base_url}/{sport}/leagues/{espn_league}/events/{event_id}/competitions/{event_id}/odds" 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 # The response cache may answer only inside this caller's own
# interval, the age at which its cached odds expire anyway. # interval, the age at which its cached odds expire anyway.
response = fetch_get(self.session, url, timeout=self.request_timeout, response = fetch_get(self.session, url, timeout=self.request_timeout,
cache_max_age=interval) cache_max_age=interval)
response.raise_for_status() response.raise_for_status()
raw_data = response.json() raw_data = response_json(response)
self._skip_network_until = 0.0 # reachable again 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) odds_data = self._extract_espn_data(raw_data)
if odds_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.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: 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 # Cache the absence too, so the game is not re-requested
# on every update until the interval passes. # on every update until the interval passes.
self.cache_manager.set(cache_key, {"no_odds": True}, ttl=interval) self.cache_manager.set(cache_key, {"no_odds": True}, ttl=interval)
@@ -226,12 +231,12 @@ class BaseOddsManager:
Returns: Returns:
Formatted odds data dictionary or None 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"]: 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] 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 # The ESPN API returns odds data directly in the item, not in a
# providers array. ESPN sends explicit JSON nulls for absent # providers array. ESPN sends explicit JSON nulls for absent
@@ -254,13 +259,17 @@ class BaseOddsManager:
.get("pointSpread") or {}).get("value") .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 return extracted_data
# Check if this is a valid empty response or an unexpected structure # 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"] == []: 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 # 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 return None
else: else:
# This is an unexpected response structure # This is an unexpected response structure
+3 -2
View File
@@ -17,6 +17,7 @@ from src.common.espn_dates import (
store_espn_scoreboard_cache, store_espn_scoreboard_cache,
) )
from src.common.fetch_service import fetch_get, fetch_post, share_connection_pool 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 from typing import TYPE_CHECKING, Any, Dict, Mapping, Optional, cast
import requests import requests
@@ -157,7 +158,7 @@ class APIHelper:
response.raise_for_status() response.raise_for_status()
# Parse JSON response # Parse JSON response
data: Dict[Any, Any] = response.json() data: Dict[Any, Any] = response_json(response)
# Cache response if cache key provided # Cache response if cache key provided
if cache_key and self.cache_manager: if cache_key and self.cache_manager:
@@ -304,7 +305,7 @@ class APIHelper:
) )
response.raise_for_status() 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: except requests.exceptions.RequestException as e:
self.logger.error(f"POST request failed for {url}: {e}") self.logger.error(f"POST request failed for {url}: {e}")
+52 -7
View File
@@ -28,6 +28,30 @@ import numpy as np
# long over one frame, so a sample this large is an idle gap between scrolls. # long over one frame, so a sample this large is an idle gap between scrolls.
FPS_LOG_INTERVAL = 5.0 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: def _rgb_pixels(item) -> np.ndarray:
"""An appended item's pixels as an RGB array, as pasting it would draw them.""" """An appended item's pixels as an RGB array, as pasting it would draw them."""
@@ -189,6 +213,11 @@ class ScrollHelper:
# Every frame time since the last stats line, so the 5s summary can # Every frame time since the last stats line, so the 5s summary can
# report the tail rather than one arbitrary sample. Cleared on log. # report the tail rather than one arbitrary sample. Cleared on log.
self._window: list = [] 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 # Scrolling state management
self.is_scrolling = False self.is_scrolling = False
@@ -573,9 +602,12 @@ class ScrollHelper:
img_w = self.cached_array.shape[1] img_w = self.cached_array.shape[1]
if end_x <= img_w: if end_x <= img_w:
# Normal case: single contiguous slice (fastest path) # Normal case: single contiguous slice (fastest path). tobytes()
frame_array = np.ascontiguousarray(self.cached_array[:, start_x:end_x]) # on the column-slice view already returns C-order bytes, so
return Image.frombytes('RGB', _size, frame_array.tobytes()) # ascontiguousarray() first only added a second full-frame copy.
return Image.frombytes(
'RGB', _size,
self.cached_array[:, start_x:end_x].tobytes())
else: else:
# Ensure frame buffer is allocated for all non-simple paths # 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): if self._frame_buffer is None or self._frame_buffer.shape != (self.display_height, self.display_width, 3):
@@ -1207,10 +1239,23 @@ class ScrollHelper:
# as an idle gap. There is nothing to report, and reporting the # as an idle gap. There is nothing to report, and reporting the
# gap itself is the bug above. # gap itself is the bug above.
if self._window: if self._window:
self.logger.info( # INFO when degraded, on the window that recovers from it, and
"Scroll frame stats - %s", # as a slow heartbeat; DEBUG otherwise.
format_frame_stats(self._window), 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.last_fps_log_time = current_time
self.frame_count = 0 self.frame_count = 0
self._window = [] self._window = []
+2 -1
View File
@@ -23,6 +23,7 @@ import requests
from typing import Any, Dict, List from typing import Any, Dict, List
from src.common.api_helper import DEFAULT_HTTP_HEADERS from src.common.api_helper import DEFAULT_HTTP_HEADERS
from src.common.json_body import response_json
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)
@@ -157,7 +158,7 @@ class DynamicTeamResolver:
response = requests.get(rankings_url, headers=dict(DEFAULT_HTTP_HEADERS), response = requests.get(rankings_url, headers=dict(DEFAULT_HTTP_HEADERS),
timeout=self.request_timeout) timeout=self.request_timeout)
response.raise_for_status() response.raise_for_status()
data = response.json() data = response_json(response)
rankings = {} rankings = {}
rankings_data = data.get('rankings', []) rankings_data = data.get('rankings', [])
+3 -2
View File
@@ -21,6 +21,7 @@ from PIL.PngImagePlugin import PngInfo
from requests.adapters import HTTPAdapter from requests.adapters import HTTPAdapter
from urllib3.util.retry import Retry from urllib3.util.retry import Retry
from src.common.api_helper import DEFAULT_HTTP_HEADERS 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.logo_helper import MAX_LOGO_BYTES
from src.common.permission_utils import ( from src.common.permission_utils import (
ensure_directory_permissions, ensure_directory_permissions,
@@ -481,7 +482,7 @@ class LogoDownloader:
logger.info(f"Fetching team data for {league} from ESPN API...") 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 = self.session.get(api_url, params={'limit':1000},headers=self.headers, timeout=self.request_timeout)
response.raise_for_status() response.raise_for_status()
data: Dict = response.json() data: Dict = response_json(response)
logger.info(f"Successfully fetched team data for {league}") logger.info(f"Successfully fetched team data for {league}")
return data return data
@@ -505,7 +506,7 @@ class LogoDownloader:
logger.info(f"Fetching team data for team {team_id} in {league} from ESPN API...") 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 = self.session.get(f"{api_url}/{team_id}", headers=self.headers, timeout=self.request_timeout)
response.raise_for_status() 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}") logger.info(f"Successfully fetched team data for {team_id} in {league}")
return data return data
+5
View File
@@ -19,6 +19,11 @@ Type=simple
User=__USER__ User=__USER__
WorkingDirectory=__PROJECT_ROOT_DIR__ WorkingDirectory=__PROJECT_ROOT_DIR__
Environment=USE_THREADING=1 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 ExecStart=/usr/bin/python3 __PROJECT_ROOT_DIR__/scripts/utils/start_web_conditionally.py
Restart=on-failure Restart=on-failure
RestartSec=10 RestartSec=10
+18
View File
@@ -200,6 +200,24 @@ class TestGetOdds:
manager.get_odds('football', 'nfl', '401') # hit manager.get_odds('football', 'nfl', '401') # hit
assert [r for r in caplog.records if r.levelno == logging.INFO] == [] 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 # _extract_espn_data
+21
View File
@@ -116,3 +116,24 @@ def test_response_json_prefers_orjson_and_falls_back():
assert json_body.response_json(response) == payload assert json_body.response_json(response) == payload
# A response object without bytes content (a test double) still works. # A response object without bytes content (a test double) still works.
assert json_body.response_json(SimpleNamespace(json=lambda: payload)) == payload 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)
+85
View File
@@ -6,6 +6,7 @@ get_visible_portion, calculate_dynamic_duration, set_* methods,
reset_scroll, clear_cache, get_scroll_info. reset_scroll, clear_cache, get_scroll_info.
""" """
import numpy as np
import pytest import pytest
import time import time
from unittest.mock import patch from unittest.mock import patch
@@ -172,6 +173,21 @@ class TestGetVisiblePortion:
# Just verify both are valid PIL images with correct size # Just verify both are valid PIL images with correct size
assert img1.width == img2.width == DISPLAY_W 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 # reset_scroll / clear_cache
@@ -396,6 +412,75 @@ class TestFrameStatsPercentiles:
assert helper._window == [] 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: class TestIdleGapIsNotAFrame:
"""The first frame of a scroll has no predecessor, so timing one measures """The first frame of a scroll has no predecessor, so timing one measures
the idle gap since the last scroll rather than a frame. the idle gap since the last scroll rather than a frame.
+9 -5
View File
@@ -30,6 +30,8 @@ from pathlib import Path
import pytest import pytest
UNIT = (Path(__file__).resolve().parent.parent / "systemd" / "ledmatrix.service") 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 #: 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 #: 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" assert UNIT.is_file(), f"{UNIT} is missing"
def test_malloc_arena_max_is_capped(): @pytest.mark.parametrize("unit", [UNIT, WEB_UNIT], ids=lambda p: p.name)
env = _environment(UNIT.read_text(encoding="utf-8")) def test_malloc_arena_max_is_capped(unit):
env = _environment(unit.read_text(encoding="utf-8"))
assert "MALLOC_ARENA_MAX" in env, ( assert "MALLOC_ARENA_MAX" in env, (
"the display unit does not cap glibc arenas; on a 3-core Pi the default " "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" "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.""" """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") index = text.index("Environment=MALLOC_ARENA_MAX")
preamble = text[:index].splitlines()[-12:] preamble = text[:index].splitlines()[-12:]
comment = "\n".join(line for line in preamble if line.startswith("#")) 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): def test_the_unit_still_parses_as_ini(unit):
"""systemd will refuse a malformed unit, and the panel stays dark.""" """systemd will refuse a malformed unit, and the panel stays dark."""
import configparser import configparser