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
This commit is contained in:
ChuckBuilds
2026-08-20 07:06:21 -04:00
co-authored by Claude Opus 5
parent cf0a551f7b
commit 0fd2bfae99
2 changed files with 95 additions and 12 deletions
+48 -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,31 @@ 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``.
"""
now = time.time()
if not force and now - self._metrics_persisted_at.get(plugin_id, 0.0) \
< _METRICS_PERSIST_INTERVAL:
return
self._metrics_persisted_at[plugin_id] = now
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,
})
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 +403,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)
+47
View File
@@ -127,3 +127,50 @@ 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"