Compare commits

..
Author SHA1 Message Date
ChuckBuilds 73fff8d2d5 test(systemd): pin the arena value instead of accepting a range
Review follow-up. The range check accepted 1, 3 and 4, so a change to 4 --
which hands most of the resident saving back -- passed a test whose whole
purpose is to notice that.

Pinned to the value the unit ships, in one named constant. Raising it is still
a legitimate response to a frame-time regression, but it should be a visible
edit here rather than silent drift, and the failure message says so.

Mutation-checked: changing the unit to 4 now fails.
2026-08-20 01:55:14 -04:00
ChuckBuilds 446207ffbc perf(systemd): cap glibc malloc arenas on the display service
Measured on a live rig 2.5 hours after start:

    RSS                          1030 MB
    Private_Dirty                 988 MB
    anonymous mappings > 10 MB       23
    largest        104, 79, 66, 63, 63 MB, on 64 MB-aligned addresses
    threads                           9
    cores                             3   -> glibc ceiling = 8 x 3 = 24 arenas

23 against a ceiling of 24, all 64 MB-aligned: these are glibc's per-thread
malloc arenas, not live objects. The data the process was actually holding
accounts for perhaps 15 MB -- the widest scroll strip observed was 35,746 x 64,
about 7 MB as RGB and the same again for its numpy mirror.

It is bloat rather than a leak: sampled four times over 135 seconds, RSS sat
between 990 and 1030 MB rather than climbing. glibc gives each allocating
thread its own arena, grows them to hold peak demand, and never gives them
back. A process that builds and drops large images across several threads is
exactly the shape that produces this.

The device had 59 MB free at the time, on 1845 MB total.

MALLOC_ARENA_MAX=2 trades a little allocator concurrency for that resident
memory. It is a tuning knob rather than a fix for a defect, so the rationale
and the measurements sit next to it in the unit file, and a test asserts they
stay there -- a bare environment variable invites removal by whoever meets it
next.

Two things this is NOT, both checked rather than assumed:

- Not an OOM problem today. A grep for "oom" in the service journal returned
  24 matches, all of which were the radar logging zoom=9 and zoom=7. The kernel
  OOM killer has not fired: dmesg has zero matches.
- Not currently capped by the unit's MemoryMax=85% either. That directive is in
  this file but absent from the unit actually installed on the rig, which
  reports MemoryMax=infinity, so nothing is enforcing a ceiling there.

The saving is unmeasured on hardware: applying it needs a service restart,
which blanks the panel, so that is the user's call rather than something to do
mid-audit. If p99 frame time regresses -- it sits at 18.4 ms against a 16.7 ms
budget for 60 FPS, so there is not much headroom -- raise the value rather than
remove it.
2026-08-20 00:17:27 -04:00
5 changed files with 162 additions and 118 deletions
+1 -1
View File
@@ -328,7 +328,7 @@ class ScrollHelper:
elapsed_time = current_time - (self.scroll_start_time or current_time)
# The image already includes display_width padding, so we only need total_scroll_width
required_total_distance = self.total_scroll_width
self.logger.debug(
self.logger.info(
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
elapsed_time,
self.calculated_duration,
+54 -54
View File
@@ -83,7 +83,7 @@ class PluginAdapter:
# into unrelated headlines once the strip refreshed to 9,505px.
self._offset_shapes: dict = {}
logger.debug(
logger.info(
"PluginAdapter initialized: display=%dx%d",
self.display_width, self.display_height
)
@@ -109,7 +109,7 @@ class PluginAdapter:
Returns:
List of PIL Images representing plugin content, or None if no content
"""
logger.debug(
logger.info(
"[%s] Getting content (class=%s)",
plugin_id, plugin.__class__.__name__
)
@@ -118,7 +118,7 @@ class PluginAdapter:
cached = self._get_cached(plugin_id)
if cached is not None:
total_width = sum(img.width for img in cached)
logger.debug(
logger.info(
"[%s] Using cached content: %d images, %dpx total",
plugin_id, len(cached), total_width
)
@@ -126,46 +126,46 @@ class PluginAdapter:
# Try native Vegas content method first
has_native = hasattr(plugin, 'get_vegas_content')
logger.debug("[%s] Has get_vegas_content: %s", plugin_id, has_native)
logger.info("[%s] Has get_vegas_content: %s", plugin_id, has_native)
if has_native:
content = self._get_native_content(plugin, plugin_id, offscreen_only)
if content:
total_width = sum(img.width for img in content)
logger.debug(
logger.info(
"[%s] Native content SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width
)
return self._finalize(content, plugin_id, 'native', plugin)
logger.debug("[%s] Native content returned None", plugin_id)
logger.info("[%s] Native content returned None", plugin_id)
# Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds)
has_scroll_helper = hasattr(plugin, 'scroll_helper')
logger.debug("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
logger.info("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only)
if content:
total_width = sum(img.width for img in content)
logger.debug(
logger.info(
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width
)
return self._finalize(content, plugin_id, 'scroll_helper', plugin)
if has_scroll_helper:
logger.debug("[%s] ScrollHelper content returned None", plugin_id)
logger.info("[%s] ScrollHelper content returned None", plugin_id)
if offscreen_only:
# Display capture needs the shared canvas; leave it to the caller.
logger.debug(
logger.info(
"[%s] Needs display capture, deferring to the render thread",
plugin_id
)
return None
# Fall back to display capture
logger.debug("[%s] Trying fallback display capture...", plugin_id)
logger.info("[%s] Trying fallback display capture...", plugin_id)
content = self._capture_display_content(plugin, plugin_id)
if content:
total_width = sum(img.width for img in content)
logger.debug(
logger.info(
"[%s] Fallback capture SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width
)
@@ -226,7 +226,7 @@ class PluginAdapter:
kept.append(result.image)
if not kept:
logger.debug(
logger.info(
"[%s] All %d image(s) from %s were blank — contributing nothing",
plugin_id, len(images), source
)
@@ -235,14 +235,14 @@ class PluginAdapter:
trimmed_width = sum(img.width for img in kept)
if trimmed_width < self.config.min_plugin_width:
logger.debug(
logger.info(
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
plugin_id, trimmed_width, self.config.min_plugin_width
)
return None
if trimmed_width != original_width or dropped_blank:
logger.debug(
logger.info(
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
"%d image(s) kept, %d blank dropped",
plugin_id, source, original_width, trimmed_width,
@@ -431,7 +431,7 @@ class PluginAdapter:
"""
if self._offset_shapes.get(plugin_id) != shape:
if plugin_id in self._item_offsets:
logger.debug(
logger.info(
"[%s] Content is %s now, was %s — restarting the rotation "
"rather than resuming at a position that no longer means "
"anything", plugin_id, shape,
@@ -579,7 +579,7 @@ class PluginAdapter:
consumed += 1
if mode == 'truncate':
logger.debug(
logger.info(
"[%s] Width budget %dpx: showing the first %d of %d row(s) "
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
plugin_id, budget, len(selected), len(images), used
@@ -587,7 +587,7 @@ class PluginAdapter:
else:
self._record_offset(
plugin_id, (start + consumed) % len(images), shape)
logger.debug(
logger.info(
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
"from offset %d; remainder deferred to a later cycle",
plugin_id, budget, len(selected), len(images), used, start
@@ -636,7 +636,7 @@ class PluginAdapter:
if mode != 'truncate':
self._record_offset(
plugin_id, 0 if end >= img.width else end, shape)
logger.debug(
logger.info(
"[%s] Width budget %dpx: cropped continuous %dpx image to "
"[%d:%d] (no item gaps of %dpx+ to align to)%s",
plugin_id, budget, img.width, offset, end, min_run,
@@ -674,7 +674,7 @@ class PluginAdapter:
self._record_offset(
plugin_id, 0 if end >= img.width else end_index, shape)
logger.debug(
logger.info(
"[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
"(%dpx) at item boundaries %d-%d of %d, %s",
plugin_id, budget, img.width, start, end, end - start,
@@ -698,7 +698,7 @@ class PluginAdapter:
List of images or None
"""
try:
logger.debug("[%s] Native: calling get_vegas_content()", plugin_id)
logger.info("[%s] Native: calling get_vegas_content()", plugin_id)
# Tell the plugin how much width the ticker wants it to use, and
# narrow the canvas for the duration of the call. A plugin that
@@ -707,7 +707,7 @@ class PluginAdapter:
# be explicit can read get_vegas_render_width().
render_width = self.resolve_render_width(plugin, plugin_id)
if render_width != self.display_width:
logger.debug(
logger.info(
"[%s] Native: requesting %dpx instead of %dpx",
plugin_id, render_width, self.display_width
)
@@ -735,19 +735,19 @@ class PluginAdapter:
plugin._vegas_render_width = None
if result is None:
logger.debug("[%s] Native: get_vegas_content() returned None", plugin_id)
logger.info("[%s] Native: get_vegas_content() returned None", plugin_id)
return None
# Normalize to list
if isinstance(result, Image.Image):
images = [result]
logger.debug(
logger.info(
"[%s] Native: got single Image %dx%d",
plugin_id, result.width, result.height
)
elif isinstance(result, (list, tuple)):
images = list(result)
logger.debug(
logger.info(
"[%s] Native: got %d items in list/tuple",
plugin_id, len(images)
)
@@ -768,14 +768,14 @@ class PluginAdapter:
)
continue
logger.debug(
logger.info(
"[%s] Native: item[%d] is %dx%d, mode=%s",
plugin_id, i, img.width, img.height, img.mode
)
# Ensure correct height
if img.height != self.display_height:
logger.debug(
logger.info(
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
plugin_id, i, img.width, img.height,
img.width, self.display_height
@@ -793,13 +793,13 @@ class PluginAdapter:
if valid_images:
total_width = sum(img.width for img in valid_images)
logger.debug(
logger.info(
"[%s] Native: SUCCESS - %d images, %dpx total width",
plugin_id, len(valid_images), total_width
)
return valid_images
logger.debug("[%s] Native: no valid images after validation", plugin_id)
logger.info("[%s] Native: no valid images after validation", plugin_id)
return None
except (AttributeError, TypeError, ValueError, OSError) as e:
@@ -833,20 +833,20 @@ class PluginAdapter:
logger.debug("[%s] No scroll_helper attribute", plugin_id)
return None
logger.debug(
logger.info(
"[%s] Found scroll_helper: %s",
plugin_id, type(scroll_helper).__name__
)
cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is None:
logger.debug(
logger.info(
"[%s] scroll_helper.cached_image is None, triggering content generation",
plugin_id
)
if offscreen_only:
# Generating it calls display(), which needs the canvas.
logger.debug(
logger.info(
"[%s] scroll_helper cache empty; deferring generation "
"to the render thread", plugin_id
)
@@ -859,13 +859,13 @@ class PluginAdapter:
return None
if not isinstance(cached_image, Image.Image):
logger.debug(
logger.info(
"[%s] scroll_helper.cached_image is not an Image: %s",
plugin_id, type(cached_image).__name__
)
return None
logger.debug(
logger.info(
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
plugin_id, cached_image.width, cached_image.height, cached_image.mode
)
@@ -888,7 +888,7 @@ class PluginAdapter:
# Ensure correct height
if img.height != self.display_height:
logger.debug(
logger.info(
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
plugin_id, img.width, img.height,
img.width, self.display_height
@@ -902,7 +902,7 @@ class PluginAdapter:
if img.mode != 'RGB':
img = img.convert('RGB')
logger.debug(
logger.info(
"[%s] ScrollHelper content ready: %dx%d",
plugin_id, img.width, img.height
)
@@ -1002,7 +1002,7 @@ class PluginAdapter:
with self._capture():
# Method 1: Try _create_scrolling_display (stocks pattern)
if hasattr(plugin, '_create_scrolling_display'):
logger.debug(
logger.info(
"[%s] Triggering via _create_scrolling_display()",
plugin_id
)
@@ -1010,7 +1010,7 @@ class PluginAdapter:
plugin._create_scrolling_display()
cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is not None and isinstance(cached_image, Image.Image):
logger.debug(
logger.info(
"[%s] _create_scrolling_display() SUCCESS: %dx%d",
plugin_id, cached_image.width, cached_image.height
)
@@ -1022,7 +1022,7 @@ class PluginAdapter:
# Method 2: Try display(force_clear=True) which typically builds scroll content
if hasattr(plugin, 'display'):
logger.debug(
logger.info(
"[%s] Triggering via display(force_clear=True)",
plugin_id
)
@@ -1031,12 +1031,12 @@ class PluginAdapter:
plugin.display(force_clear=True)
cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is not None and isinstance(cached_image, Image.Image):
logger.debug(
logger.info(
"[%s] display(force_clear=True) SUCCESS: %dx%d",
plugin_id, cached_image.width, cached_image.height
)
return cached_image
logger.debug(
logger.info(
"[%s] display(force_clear=True) did not populate cached_image",
plugin_id
)
@@ -1045,7 +1045,7 @@ class PluginAdapter:
"[%s] display(force_clear=True) failed", plugin_id
)
logger.debug(
logger.info(
"[%s] Could not trigger scroll content generation",
plugin_id
)
@@ -1077,15 +1077,15 @@ class PluginAdapter:
try:
# Save current display state
original_image = self.display_manager.image.copy()
logger.debug("[%s] Fallback: saved original display state", plugin_id)
logger.info("[%s] Fallback: saved original display state", plugin_id)
# Ensure plugin has fresh data before capturing
has_update_data = hasattr(plugin, 'update_data')
logger.debug("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
logger.info("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
if has_update_data:
try:
plugin.update_data()
logger.debug("[%s] Fallback: update_data() called", plugin_id)
logger.info("[%s] Fallback: update_data() called", plugin_id)
except (AttributeError, RuntimeError, OSError):
logger.exception("[%s] Fallback: update_data() failed", plugin_id)
@@ -1097,41 +1097,41 @@ class PluginAdapter:
# arrangement rather than one that has to be cropped afterwards.
render_width = self.resolve_render_width(plugin, plugin_id)
if render_width != self.display_width:
logger.debug(
logger.info(
"[%s] Fallback: rendering at %dpx instead of %dpx",
plugin_id, render_width, self.display_width
)
with self._capture(), self._render_at(render_width):
self.display_manager.clear()
logger.debug("[%s] Fallback: display cleared, calling display()", plugin_id)
logger.info("[%s] Fallback: display cleared, calling display()", plugin_id)
# First try without force_clear (some plugins behave better this way)
try:
plugin.display()
logger.debug("[%s] Fallback: display() called successfully", plugin_id)
logger.info("[%s] Fallback: display() called successfully", plugin_id)
except TypeError:
# Plugin may require force_clear argument
logger.debug("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
logger.info("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
plugin.display(force_clear=True)
# Capture the result
captured = self.display_manager.image.copy()
logger.debug(
logger.info(
"[%s] Fallback: captured frame %dx%d, mode=%s",
plugin_id, captured.width, captured.height, captured.mode
)
# Check if captured image has content (not all black)
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
logger.debug(
logger.info(
"[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
plugin_id, bright_ratio * 100
)
if is_blank:
logger.debug(
logger.info(
"[%s] Fallback: first capture blank, retrying with force_clear",
plugin_id
)
@@ -1142,7 +1142,7 @@ class PluginAdapter:
captured = self.display_manager.image.copy()
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
logger.debug(
logger.info(
"[%s] Fallback: retry brightness - %.3f%% bright pixels",
plugin_id, bright_ratio * 100
)
@@ -1159,7 +1159,7 @@ class PluginAdapter:
if captured.mode != 'RGB':
captured = captured.convert('RGB')
logger.debug(
logger.info(
"[%s] Fallback: SUCCESS - captured %dx%d",
plugin_id, captured.width, captured.height
)
+12
View File
@@ -8,6 +8,18 @@ Type=simple
User=root
WorkingDirectory=__PROJECT_ROOT_DIR__
Environment=PYTHONDONTWRITEBYTECODE=1
# glibc gives each allocating thread its own malloc arena, up to 8 x CPU count,
# and an arena that has grown is never handed back to the OS. This process runs
# 9 threads on a 3-core Pi, so the ceiling is 24 arenas -- and a rig measured at
# 1030 MB resident held 23 large anonymous mappings on 64 MB-aligned addresses,
# 920 MB of them, while the live data it was actually holding (widest scroll
# strip seen: 35,746 x 64) accounts for roughly 15 MB. That gap is arena bloat,
# not leaked objects: RSS was flat across repeated sampling, not climbing.
#
# Capping the arenas trades a little allocator concurrency for a large amount of
# resident memory on a device that has neither to spare. 2 is the usual value;
# raise it if frame times regress.
Environment=MALLOC_ARENA_MAX=2
ExecStart=/usr/bin/python3 __PROJECT_ROOT_DIR__/run.py
# Restart=always, not on-failure: run.py exiting 0 (a clean shutdown path taken
# for a reason that no longer applies, e.g. a config reload) would otherwise leave
+95
View File
@@ -0,0 +1,95 @@
"""The display unit must cap glibc's malloc arenas.
glibc hands each allocating thread its own malloc arena, up to 8 x CPU count,
and an arena that has grown is never returned to the OS. This process runs
threads for the render loop, the update workers and the background fetchers, so
on a 3-core Pi the ceiling is 24 arenas.
Measured on a live rig, 2.5 hours in:
RSS 1030 MB
Private_Dirty 988 MB
anonymous mappings > 10 MB 23 (ceiling is 8 x 3 = 24)
largest few 104, 79, 66, 63, 63 MB, on 64 MB-aligned addresses
against live data that accounts for perhaps 15 MB -- the widest scroll strip
observed was 35,746 x 64, about 7 MB as RGB and the same again for its numpy
mirror. Repeated sampling showed RSS flat between 990 and 1030 MB rather than
climbing, so this is arena bloat rather than a leak: memory Python has freed
but glibc is holding per-arena.
The device had 59 MB free at the time.
Capping the arena count trades a little allocator concurrency for that resident
memory. The render loop is latency-sensitive, so if p99 frame time regresses the
right response is to raise this rather than remove it.
"""
import re
from pathlib import Path
import pytest
UNIT = (Path(__file__).resolve().parent.parent / "systemd" / "ledmatrix.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
#: them is what this project ships.
EXPECTED_ARENA_MAX = 2
def _environment(unit_text):
return dict(
line.split("=", 2)[1:3] if line.count("=") >= 2 else (line.split("=", 1)[1], "")
for line in unit_text.splitlines()
if line.startswith("Environment=")
)
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"))
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"
)
value = int(env["MALLOC_ARENA_MAX"])
# Pinned, not a range. A range let a change to 4 -- which hands most of the
# saving back -- pass unnoticed, which was the point of the finding that
# prompted this. Raising it is a legitimate response to a frame-time
# regression, but it should be a visible edit here rather than a silent
# drift, so the number lives in one place and changing it shows up in
# review.
assert value == EXPECTED_ARENA_MAX, (
f"MALLOC_ARENA_MAX={value}, expected {EXPECTED_ARENA_MAX}. If this was "
"raised deliberately because frame times regressed, update "
"EXPECTED_ARENA_MAX here and say so in the commit."
)
def test_the_reason_is_recorded_next_to_it():
"""A bare tuning knob invites removal by whoever meets it next."""
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("#"))
assert "arena" in comment.lower(), "no explanation precedes the setting"
assert re.search(r"\d", comment), (
"the explanation cites no measurement, so a reader cannot tell whether "
"it still applies to their hardware"
)
@pytest.mark.parametrize("unit", ["ledmatrix.service"])
def test_the_unit_still_parses_as_ini(unit):
"""systemd will refuse a malformed unit, and the panel stays dark."""
import configparser
path = UNIT.parent / unit
parser = configparser.ConfigParser(strict=False)
# systemd allows repeated keys; ConfigParser needs them merged, not rejected.
parser.read_string(path.read_text(encoding="utf-8"))
assert parser.has_section("Service")
assert parser.has_option("Service", "ExecStart")
-63
View File
@@ -1,63 +0,0 @@
"""The Vegas content path must trace at DEBUG, not INFO.
plugin_adapter narrates every step of acquiring content from every plugin --
"Has get_vegas_content", "Native: calling get_vegas_content()", "Native content
returned None", "Has scroll_helper", the per-item sizes -- and it does that for
each plugin on each cycle.
Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO and
35 were WARNING. plugin_adapter alone produced 2,457 of them. That is ~223
lines a minute of string formatting on a Pi that is also driving the panel, all
of it written through journald to the SD card, and it buries the 35 lines that
actually indicate a problem.
Nothing is lost by moving it to DEBUG: the 19 warning/error/exception calls in
the module are untouched, so real failures still surface at their own level.
One INFO call is deliberate and stays -- the padding-strip message chooses its
level at runtime (`logger.warning if (left and right) else logger.info`) and
test_vegas_plugin_adapter.py pins it.
"""
import ast
from pathlib import Path
import pytest
ADAPTER = (Path(__file__).resolve().parent.parent / "src" / "vegas_mode"
/ "plugin_adapter.py")
def _info_calls(path):
"""Direct logger.info(...) call sites in a module."""
tree = ast.parse(path.read_text(encoding="utf-8"))
found = []
for node in ast.walk(tree):
if (isinstance(node, ast.Call)
and isinstance(node.func, ast.Attribute)
and node.func.attr == "info"
and getattr(node.func.value, "id", None) == "logger"):
found.append(node.lineno)
return found
def test_the_content_path_does_not_trace_at_info():
calls = _info_calls(ADAPTER)
assert not calls, (
"plugin_adapter should trace at DEBUG; found logger.info at lines "
f"{calls}. This path runs per plugin per cycle and its output goes to "
"the SD card via journald."
)
def test_real_failures_still_have_a_level_of_their_own():
"""Demoting the trace must not have swept up the error reporting."""
source = ADAPTER.read_text(encoding="utf-8")
loud = sum(source.count(f"logger.{level}(")
for level in ("warning", "error", "exception"))
assert loud >= 15, f"only {loud} warning/error/exception calls remain"
def test_the_deliberate_runtime_chosen_level_survives():
"""The padding-strip message picks its level at runtime; leave it alone."""
source = ADAPTER.read_text(encoding="utf-8")
assert "logger.warning if (left and right) else logger.info" in source