From 0fd2bfae990ba945069e130173f70233bc188edc Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 20 Aug 2026 07:06:21 -0400 Subject: [PATCH] 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) Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW --- src/plugin_system/resource_monitor.py | 60 +++++++++++++++++++++------ test/test_resource_monitor.py | 47 +++++++++++++++++++++ 2 files changed, 95 insertions(+), 12 deletions(-) diff --git a/src/plugin_system/resource_monitor.py b/src/plugin_system/resource_monitor.py index 42ded4ec..1891cde3 100644 --- a/src/plugin_system/resource_monitor.py +++ b/src/plugin_system/resource_monitor.py @@ -49,6 +49,20 @@ class ResourceMetrics: 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: """ Monitors resource usage for plugins. @@ -75,6 +89,10 @@ class PluginResourceMonitor: # Resource metrics per plugin self._metrics: Dict[str, ResourceMetrics] = {} 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 self._local = threading.local() @@ -232,18 +250,8 @@ class PluginResourceMonitor: # CPU is harder to measure per-call, so we track it separately metrics.cpu_percent = self._get_process_cpu_percent() - # Persist metrics - 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 - }) + # Persist metrics, at most once per interval per plugin. + self._persist_metrics(plugin_id, metrics) # Check limits if limits: @@ -363,6 +371,31 @@ class PluginResourceMonitor: summaries[plugin_id] = self.get_metrics_summary(plugin_id) 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: """Reset metrics for a plugin.""" with self._lock: @@ -370,4 +403,7 @@ class PluginResourceMonitor: self._metrics[plugin_id] = ResourceMetrics() cache_key = self._get_metrics_key(plugin_id) 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) diff --git a/test/test_resource_monitor.py b/test/test_resource_monitor.py index 6b3dbe48..9f672764 100644 --- a/test/test_resource_monitor.py +++ b/test/test_resource_monitor.py @@ -127,3 +127,50 @@ class TestForceReload: fresh = mon.get_metrics_summary("p", force_reload=True) assert fresh["call_count"] == 7 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"