Compare commits

..
Author SHA1 Message Date
ChuckBuildsandClaude Opus 5 dab4b3ea57 fix: use a monotonic clock and only mark metrics persisted once written
Two review findings on the throttle, both right.

The interval compared wall-clock timestamps. These devices have no RTC, so
the clock jumps by however far off boot-time was the moment NTP first syncs
-- a forward jump would allow an early write, a backward one would stall the
snapshot well past the interval. time.monotonic() is not subject to either.

The timestamp was also recorded before cache_manager.set(). A set() that
raised would buy the next interval's silence without leaving a snapshot
behind, which is the one case where skipping the write is least affordable.
Recorded after the write lands instead, so a failure is retried on the next
call.

Verified by restoring the original ordering: the new test then reports one
write where two are expected.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
2026-08-20 07:42:24 -04:00
ChuckBuildsandClaude Opus 5 0fd2bfae99 perf(plugins): stop rewriting a plugin's metrics file on every call
Plugin metrics were persisted to the cache inside monitor_call, so every
call by every plugin rewrote a small JSON file. Measured on a running rig:
one plugin's plugin_metrics file changed nine times a minute, with fourteen
such files active. Each is around 350 bytes, which on ext4 costs a 4KB block
plus a journal entry, so the cost is dominated by the write itself rather
than the payload. Cache writes accounted for essentially all of that device's
2.4 MB/min of SD traffic, on a card that wears out and has already failed
twice on the other rig.

Metrics cannot be de-duplicated the way health state can, because call_count
changes on every call and the timings usually do too. So they are rate-limited
instead: at most one write per plugin per 30 seconds.

The in-memory copy stays authoritative and exact -- a plugin's call_count is
still precise the instant after it runs. Only the cross-process snapshot the
web UI reads is delayed, and telemetry up to half a minute old is still a fair
description of a long-running plugin.

reset_metrics clears the throttle timestamp, so a reset is not left showing a
deleted key for the rest of the interval.

Extrapolating the sampled rate, this takes metric writes from roughly 126 a
minute to 28. Health persistence, the other half of the churn, is handled
separately in #475.

Verified by reverting the throttle: the churn test then reports 50 writes for
50 calls. 88 tests pass across resource monitor, plugin system and web API.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
2026-08-20 07:06:21 -04:00
4 changed files with 119 additions and 150 deletions
+1 -63
View File
@@ -111,12 +111,6 @@ class RestoreOptions:
"""Which sections of a backup should be restored.""" """Which sections of a backup should be restored."""
restore_config: bool = True restore_config: bool = True
#: Whether to take the backup's display.hardware block as well.
#: Off by default: that block describes the panel physically wired to
#: *this* device -- its size, chain length, mapping, multiplexing and
#: refresh cap. A backup carries the panel of the machine it was taken
#: on, and restoring one onto a different rig drives the wrong geometry.
restore_hardware: bool = False
restore_secrets: bool = True restore_secrets: bool = True
restore_wifi: bool = True restore_wifi: bool = True
restore_fonts: bool = True restore_fonts: bool = True
@@ -555,60 +549,6 @@ def _copy_file(src: Path, dst: Path) -> None:
raise raise
_HARDWARE_PATH = ("display", "hardware")
def _restore_config_preserving_hardware(src: Path, dst: Path, keep_hardware: bool) -> None:
"""Copy a backed-up config.json, optionally keeping the local panel block.
display.hardware describes the panel physically attached to this device:
cols, rows, chain_length, hardware_mapping, panel_type, multiplexing and
the refresh-rate cap. None of that travels with a configuration -- it is a
property of the machine. Restoring a backup taken on a 512x64 rig onto a
128x32 one used to overwrite the smaller panel's geometry with the larger
one's, which is not a setting the user can see going wrong; the display
simply stops being right.
Falls back to a plain copy when either file cannot be parsed, so a restore
never fails because of this.
"""
if not keep_hardware:
_copy_file(src, dst)
return
try:
incoming = json.loads(src.read_text(encoding="utf-8"))
local = json.loads(dst.read_text(encoding="utf-8")) if dst.exists() else {}
except (OSError, ValueError) as exc:
logger.warning(
"[Backup] Could not merge local panel config (%s); restoring the "
"backup's config.json as-is", exc)
_copy_file(src, dst)
return
section, key = _HARDWARE_PATH
local_hw = (local.get(section) or {}).get(key)
if not isinstance(local_hw, dict) or not local_hw:
_copy_file(src, dst)
return
if not isinstance(incoming.get(section), dict):
incoming[section] = {}
incoming_hw = incoming[section].get(key)
incoming[section][key] = local_hw
if isinstance(incoming_hw, dict) and incoming_hw != local_hw:
logger.info(
"[Backup] Kept this device's display.hardware; the backup's panel "
"was %sx%s chain %s, this one is %sx%s chain %s",
incoming_hw.get("cols"), incoming_hw.get("rows"),
incoming_hw.get("chain_length"),
local_hw.get("cols"), local_hw.get("rows"),
local_hw.get("chain_length"))
tmp_path = dst.with_suffix(dst.suffix + ".restore-tmp")
tmp_path.write_text(json.dumps(incoming, indent=2) + "\n", encoding="utf-8")
os.replace(tmp_path, dst)
def restore_backup( def restore_backup(
zip_path: Path, zip_path: Path,
project_root: Path, project_root: Path,
@@ -644,9 +584,7 @@ def restore_backup(
# Main config. # Main config.
if options.restore_config and (tmp_dir / _CONFIG_REL).exists(): if options.restore_config and (tmp_dir / _CONFIG_REL).exists():
try: try:
_restore_config_preserving_hardware( _copy_file(tmp_dir / _CONFIG_REL, project_root / _CONFIG_REL)
tmp_dir / _CONFIG_REL, project_root / _CONFIG_REL,
keep_hardware=not options.restore_hardware)
result.restored.append("config") result.restored.append("config")
except OSError as e: except OSError as e:
logger.error("[Backup] Failed to restore config.json: %s", e, exc_info=True) logger.error("[Backup] Failed to restore config.json: %s", e, exc_info=True)
+54 -12
View File
@@ -49,6 +49,20 @@ class ResourceMetrics:
self.total_execution_time = self.total_execution_time / self.call_count self.total_execution_time = self.total_execution_time / self.call_count
#: How often a plugin's metrics are written to the cache, in seconds.
#:
#: Persisting on every call meant a small file rewritten roughly nine times a
#: minute per plugin. On a rig with fourteen active plugins that was ~126
#: writes a minute for metrics alone, and since each ~350-byte file costs a
#: 4KB block plus an ext4 journal entry, it dominated the device's write
#: volume -- on an SD card, which wears out.
#:
#: The in-memory copy stays authoritative and exact; only the cross-process
#: snapshot the web UI reads is delayed, and telemetry up to half a minute old
#: is still a fair description of a long-running plugin.
_METRICS_PERSIST_INTERVAL = 30.0
class PluginResourceMonitor: class PluginResourceMonitor:
""" """
Monitors resource usage for plugins. Monitors resource usage for plugins.
@@ -75,6 +89,10 @@ class PluginResourceMonitor:
# Resource metrics per plugin # Resource metrics per plugin
self._metrics: Dict[str, ResourceMetrics] = {} self._metrics: Dict[str, ResourceMetrics] = {}
self._limits: Dict[str, ResourceLimits] = {} self._limits: Dict[str, ResourceLimits] = {}
# When each plugin's metrics last reached the cache. Metrics change on
# every call, so they cannot be de-duplicated the way health state can;
# they are rate-limited instead. See _METRICS_PERSIST_INTERVAL.
self._metrics_persisted_at: Dict[str, float] = {}
# Thread-local storage for execution tracking # Thread-local storage for execution tracking
self._local = threading.local() self._local = threading.local()
@@ -232,18 +250,8 @@ class PluginResourceMonitor:
# CPU is harder to measure per-call, so we track it separately # CPU is harder to measure per-call, so we track it separately
metrics.cpu_percent = self._get_process_cpu_percent() metrics.cpu_percent = self._get_process_cpu_percent()
# Persist metrics # Persist metrics, at most once per interval per plugin.
cache_key = self._get_metrics_key(plugin_id) self._persist_metrics(plugin_id, metrics)
self.cache_manager.set(cache_key, {
'memory_mb': metrics.memory_mb,
'cpu_percent': metrics.cpu_percent,
'execution_time': metrics.execution_time,
'call_count': metrics.call_count,
'total_execution_time': metrics.total_execution_time,
'max_execution_time': metrics.max_execution_time,
'min_execution_time': metrics.min_execution_time if metrics.min_execution_time != float('inf') else 0.0,
'last_update_time': metrics.last_update_time
})
# Check limits # Check limits
if limits: if limits:
@@ -363,6 +371,37 @@ class PluginResourceMonitor:
summaries[plugin_id] = self.get_metrics_summary(plugin_id) summaries[plugin_id] = self.get_metrics_summary(plugin_id)
return summaries return summaries
def _persist_metrics(self, plugin_id: str, metrics: ResourceMetrics,
force: bool = False) -> None:
"""Write a plugin's metrics to the cache, at most once per interval.
Caller must hold ``self._lock``.
"""
# Monotonic, not wall clock: these devices have no RTC, so the clock
# jumps by however far off boot-time was the moment NTP first syncs.
# A forward jump would allow an early write, a backward one would
# stall the snapshot well past the interval.
now = time.monotonic()
if not force and now - self._metrics_persisted_at.get(plugin_id, 0.0) \
< _METRICS_PERSIST_INTERVAL:
return
cache_key = self._get_metrics_key(plugin_id)
self.cache_manager.set(cache_key, {
'memory_mb': metrics.memory_mb,
'cpu_percent': metrics.cpu_percent,
'execution_time': metrics.execution_time,
'call_count': metrics.call_count,
'total_execution_time': metrics.total_execution_time,
'max_execution_time': metrics.max_execution_time,
'min_execution_time': (metrics.min_execution_time
if metrics.min_execution_time != float('inf')
else 0.0),
'last_update_time': metrics.last_update_time,
})
# Only after the write lands. Marking it first would mean a failed
# set() bought the next interval's silence without leaving a snapshot.
self._metrics_persisted_at[plugin_id] = now
def reset_metrics(self, plugin_id: str) -> None: def reset_metrics(self, plugin_id: str) -> None:
"""Reset metrics for a plugin.""" """Reset metrics for a plugin."""
with self._lock: with self._lock:
@@ -370,4 +409,7 @@ class PluginResourceMonitor:
self._metrics[plugin_id] = ResourceMetrics() self._metrics[plugin_id] = ResourceMetrics()
cache_key = self._get_metrics_key(plugin_id) cache_key = self._get_metrics_key(plugin_id)
self.cache_manager.delete(cache_key) self.cache_manager.delete(cache_key)
# Let the next call persist immediately rather than leaving the
# deleted key absent for the rest of the interval.
self._metrics_persisted_at.pop(plugin_id, None)
+64
View File
@@ -127,3 +127,67 @@ class TestForceReload:
fresh = mon.get_metrics_summary("p", force_reload=True) fresh = mon.get_metrics_summary("p", force_reload=True)
assert fresh["call_count"] == 7 assert fresh["call_count"] == 7
assert any(c.kwargs.get("memory_ttl") == 0 for c in cache.get.call_args_list) assert any(c.kwargs.get("memory_ttl") == 0 for c in cache.get.call_args_list)
class TestMetricsPersistenceChurn:
"""Metrics are telemetry; writing them on every call wore the SD card.
Each write is a ~350-byte file, which on ext4 costs a 4KB block plus a
journal entry. At roughly nine calls a minute per plugin across fourteen
plugins it dominated the device's write volume.
"""
def test_repeated_calls_persist_once_per_interval(self):
cache = _cache()
mon = PluginResourceMonitor(cache, enable_monitoring=False)
for _ in range(50):
mon.monitor_call("p", lambda: None)
writes = [c for c in cache.set.call_args_list
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
assert len(writes) == 1, (
f"50 calls produced {len(writes)} metric writes; expected 1")
def test_the_interval_elapsing_allows_the_next_write(self, monkeypatch):
import src.plugin_system.resource_monitor as rm
cache = _cache()
mon = PluginResourceMonitor(cache, enable_monitoring=False)
mon.monitor_call("p", lambda: None)
# pretend the interval has passed
mon._metrics_persisted_at["p"] -= rm._METRICS_PERSIST_INTERVAL + 1
mon.monitor_call("p", lambda: None)
writes = [c for c in cache.set.call_args_list
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
assert len(writes) == 2
def test_in_memory_metrics_stay_exact_while_writes_are_skipped(self):
mon = PluginResourceMonitor(_cache(), enable_monitoring=False)
for _ in range(20):
mon.monitor_call("p", lambda: None)
assert mon.get_metrics("p").call_count == 20
def test_reset_lets_the_next_call_persist_immediately(self):
cache = _cache()
mon = PluginResourceMonitor(cache, enable_monitoring=False)
mon.monitor_call("p", lambda: None)
mon.reset_metrics("p")
mon.monitor_call("p", lambda: None)
writes = [c for c in cache.set.call_args_list
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
assert len(writes) == 2, "reset should clear the throttle timestamp"
def test_a_failed_write_does_not_buy_the_next_interval_of_silence(self):
"""A set() that raises must not count as having persisted.
Marking the timestamp before the write would leave no snapshot in the
cache and still suppress the next 30 seconds of attempts.
"""
cache = _cache()
cache.set.side_effect = [OSError("disk full"), None]
mon = PluginResourceMonitor(cache, enable_monitoring=False)
with pytest.raises(OSError):
mon.monitor_call("p", lambda: None)
# the very next call must try again rather than skip the interval
mon.monitor_call("p", lambda: None)
writes = [c for c in cache.set.call_args_list
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
assert len(writes) == 2, "a failed write should be retried, not skipped"
-75
View File
@@ -1,75 +0,0 @@
#!/usr/bin/env python3
"""A restore must not repoint this device at another machine's panel.
display.hardware describes the panel physically wired to this device -- cols,
rows, chain_length, hardware_mapping, panel_type, multiplexing, the refresh
cap. A backup carries the panel of the machine it was taken on. Restoring a
512x64 rig's backup onto a 128x32 one used to overwrite the smaller panel's
geometry with the larger one's, and nothing on screen explains why: the
display just stops being right.
That is not hypothetical. It happened, and the rig it happened to had to be
reflashed.
"""
import json
import sys
from pathlib import Path
sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
from src.backup_manager import _restore_config_preserving_hardware # noqa: E402
BIG = {"display": {"hardware": {"cols": 128, "rows": 64, "chain_length": 4,
"hardware_mapping": "adafruit-hat-pwm"},
"runtime": {"gpio_slowdown": 4}},
"timezone": "America/New_York", "some-plugin": {"enabled": True}}
SMALL = {"display": {"hardware": {"cols": 64, "rows": 32, "chain_length": 2,
"hardware_mapping": "regular"},
"runtime": {"gpio_slowdown": 2}},
"timezone": "UTC"}
def _run(tmp, keep):
src = tmp / "backup_config.json"; src.write_text(json.dumps(BIG))
dst = tmp / "config.json"; dst.write_text(json.dumps(SMALL))
_restore_config_preserving_hardware(src, dst, keep_hardware=keep)
return json.loads(dst.read_text())
def test_local_panel_survives(tmp_path):
out = _run(tmp_path, keep=True)
hw = out["display"]["hardware"]
assert (hw["cols"], hw["rows"], hw["chain_length"]) == (64, 32, 2), (
"the restore repointed this device at the backup's panel")
assert hw["hardware_mapping"] == "regular", "panel wiring came from the backup"
def test_everything_else_is_restored(tmp_path):
out = _run(tmp_path, keep=True)
assert out["timezone"] == "America/New_York", "config was not restored"
assert out["some-plugin"] == {"enabled": True}, "plugin config was not restored"
assert out["display"]["runtime"] == {"gpio_slowdown": 4}, (
"only display.hardware should be held back")
def test_opting_in_takes_the_backups_panel(tmp_path):
out = _run(tmp_path, keep=False)
hw = out["display"]["hardware"]
assert (hw["cols"], hw["rows"], hw["chain_length"]) == (128, 64, 4)
def test_a_device_with_no_local_hardware_takes_the_backups(tmp_path):
src = tmp_path / "b.json"; src.write_text(json.dumps(BIG))
dst = tmp_path / "c.json"; dst.write_text(json.dumps({"timezone": "UTC"}))
_restore_config_preserving_hardware(src, dst, keep_hardware=True)
out = json.loads(dst.read_text())
assert out["display"]["hardware"]["cols"] == 128, (
"nothing local to preserve, so the backup's panel should be used")
def test_unparseable_local_config_still_restores(tmp_path):
src = tmp_path / "b.json"; src.write_text(json.dumps(BIG))
dst = tmp_path / "c.json"; dst.write_text("{ not json")
_restore_config_preserving_hardware(src, dst, keep_hardware=True)
assert json.loads(dst.read_text())["timezone"] == "America/New_York", (
"a restore must never fail because of this merge")