perf(cache): skip rewriting unchanged CacheManager.set() records (#730)

The disk cache's unchanged-payload skip now ignores a CacheManager.set() record's timestamp, so unchanged re-saves are skipped; a skip moves the file's mtime to the new timestamp instead, and readers take a record's age from the newer of the two (never more than an hour past the embedded timestamp). Per-plugin plugin_metrics:<id> records become one plugin_metrics_snapshot written at most once a minute, and CacheManager builds its ConfigManager on first use. On hdpi, cache file writes went from ~37 to 8.6 a minute.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

test/test_cache_manager_lazy_config.py

@@ -0,0 +1,98 @@
+"""CacheManager builds its ConfigManager on first use, not in __init__.
+
+Every CacheManager built a ConfigManager and loaded the whole config for a
+cache strategy that no longer reads it. The attribute stays public -- the
+sports plugins resolve the global timezone through
+``cache_manager.config_manager`` -- so it is now built on first access.
+"""
+
+from unittest.mock import MagicMock, patch
+
+import pytest
+
+import src.config_manager as config_manager_module
+from src.cache_manager import CacheManager
+
+
+@pytest.fixture
+def built(monkeypatch):
+    """Count ConfigManager constructions and load_config calls."""
+    made = []
+
+    class CountingConfigManager:
+        def __init__(self):
+            made.append(self)
+            self.loads = 0
+
+        def load_config(self):
+            self.loads += 1
+            return {}
+
+    monkeypatch.setattr(config_manager_module, "ConfigManager", CountingConfigManager)
+    return made
+
+
+@pytest.fixture
+def manager(tmp_path):
+    with patch('src.cache_manager.CacheManager._get_writable_cache_dir',
+               return_value=str(tmp_path)):
+        cm = CacheManager()
+    cm.stop_cleanup_thread()
+    return cm
+
+
+def test_construction_does_not_load_the_config(built, manager):
+    manager.set("k", {"v": 1})
+    assert manager.get("k") == {"v": 1}
+    assert manager.get_cache_strategy("sports_live")["max_age"] > 0
+    assert built == []
+
+
+def test_first_access_builds_and_loads_it_once(built, manager):
+    first = manager.config_manager
+    assert manager.config_manager is first
+    assert getattr(manager, "config_manager", None) is first
+    assert len(built) == 1 and first.loads == 1
+
+
+def test_assignment_still_wins(built, manager):
+    replacement = MagicMock()
+    manager.config_manager = replacement
+    assert manager.config_manager is replacement
+    assert built == []
+
+
+def test_an_unimportable_config_manager_is_none(manager, monkeypatch):
+    import builtins
+    real_import = builtins.__import__
+
+    def refuse(name, *args, **kwargs):
+        if name == "src.config_manager":
+            raise ImportError("no config manager here")
+        return real_import(name, *args, **kwargs)
+
+    monkeypatch.setattr(builtins, "__import__", refuse)
+    assert manager.config_manager is None
+
+
+def test_a_failed_load_is_retried_on_the_next_access(manager, monkeypatch):
+    attempts = []
+
+    class Flaky:
+        def load_config(self):
+            attempts.append(1)
+            if len(attempts) == 1:
+                raise RuntimeError("config.json unreadable")
+            return {}
+
+    monkeypatch.setattr(config_manager_module, "ConfigManager", Flaky)
+    with pytest.raises(RuntimeError):
+        manager.config_manager
+    assert isinstance(manager.config_manager, Flaky)
+    assert len(attempts) == 2
+
+
+def test_a_manager_made_without_init_still_answers(built):
+    bare = CacheManager.__new__(CacheManager)
+    bare.logger = MagicMock()
+    assert bare.config_manager is built[0]

test/test_cache_unchanged_resave.py

@@ -0,0 +1,242 @@
+"""An unchanged CacheManager.set() does not rewrite the file, and the skip
+never changes how old the record looks.
+
+DiskCache.set already skipped a payload identical to the last one it wrote,
+but CacheManager.set stamps every record with time.time(), so for set() the
+payload was never identical and every unchanged re-save was a full rewrite on
+the SD card. The digest now leaves the header timestamp out, and the newer
+timestamp lives in the file's mtime instead ("UNCHANGED RE-SAVES" in
+src/cache/disk_cache.py). These tests pin both halves: the write is skipped,
+and every reader still ages the record from its newest save -- across a
+restart, and with a bound on what a foreign mtime can claim.
+"""
+
+import os
+import shutil
+import tempfile
+import time
+from unittest.mock import patch
+
+import pytest
+
+from src.cache import disk_cache as disk_cache_module
+from src.cache.disk_cache import (
+    DiskCache,
+    _MAX_TIMESTAMP_LIFT,
+    _effective_timestamp,
+)
+from src.cache_manager import CacheManager
+
+
+@pytest.fixture
+def writes(monkeypatch):
+    """Count real writes: every atomic write starts with mkstemp."""
+    calls = []
+    real = tempfile.mkstemp
+
+    def counting(*args, **kwargs):
+        calls.append(kwargs.get("prefix"))
+        return real(*args, **kwargs)
+
+    monkeypatch.setattr(disk_cache_module.tempfile, "mkstemp", counting)
+    return calls
+
+
+@pytest.fixture
+def clock(monkeypatch):
+    """time.time() for the cache modules, advanced by hand."""
+    now = [time.time()]
+    fake = type("FakeTime", (), {"time": staticmethod(lambda: now[0])})
+    monkeypatch.setattr(disk_cache_module, "time", fake)
+    import src.cache_manager as cache_manager_module
+    monkeypatch.setattr(cache_manager_module, "time", fake)
+    return now
+
+
+@pytest.fixture
+def cm(tmp_path):
+    with patch('src.cache_manager.CacheManager._get_writable_cache_dir',
+               return_value=str(tmp_path)):
+        manager = CacheManager()
+    manager.stop_cleanup_thread()
+    yield manager
+
+
+def _record(ts, data=None, ttl=None):
+    """A record laid out the way CacheManager.set writes it."""
+    rec = {"timestamp": ts}
+    if ttl is not None:
+        rec["ttl"] = ttl
+    rec["data"] = data if data is not None else {"games": [1, 2, 3]}
+    return rec
+
+
+class TestTheWriteIsSkipped:
+    def test_repeated_identical_set_writes_once(self, cm, writes):
+        path = cm._get_cache_path("scores")
+        for _ in range(20):
+            cm.set("scores", {"games": [1, 2, 3]}, ttl=60)
+        assert len(writes) == 1
+        # The data is the same and the file is the same file.
+        assert cm.get("scores", max_age=60, memory_ttl=0) == {"games": [1, 2, 3]}
+        assert os.stat(path).st_nlink == 1
+
+    def test_the_file_is_not_replaced(self, tmp_path, clock):
+        disk = DiskCache(str(tmp_path))
+        disk.set("k", _record(clock[0]))
+        before = os.stat(disk.get_cache_path("k"))
+        clock[0] += 30
+        disk.set("k", _record(clock[0]))
+        after = os.stat(disk.get_cache_path("k"))
+        assert after.st_ino == before.st_ino
+        assert after.st_mtime == pytest.approx(clock[0], abs=1e-3)
+
+    def test_changed_data_rewrites(self, cm, writes):
+        cm.set("scores", {"games": [1]})
+        cm.set("scores", {"games": [2]})
+        assert len(writes) == 2
+        assert cm.get("scores", memory_ttl=0) == {"games": [2]}
+
+    def test_a_changed_ttl_rewrites(self, cm, writes):
+        cm.set("scores", {"games": [1]}, ttl=60)
+        cm.set("scores", {"games": [1]}, ttl=600)
+        cm.set("scores", {"games": [1]})
+        assert len(writes) == 3
+
+    def test_a_timestamp_going_backwards_rewrites(self, tmp_path, writes, clock):
+        disk = DiskCache(str(tmp_path))
+        disk.set("k", _record(clock[0]))
+        disk.set("k", _record(clock[0] - 100))
+        assert len(writes) == 2
+        assert disk.get("k", max_age=None)["timestamp"] == pytest.approx(clock[0] - 100)
+
+    def test_unchanged_data_is_still_rewritten_once_the_lift_runs_out(
+            self, tmp_path, writes, clock):
+        disk = DiskCache(str(tmp_path))
+        start = clock[0]
+        disk.set("k", _record(start))
+        clock[0] = start + _MAX_TIMESTAMP_LIFT - 1
+        disk.set("k", _record(clock[0]))
+        assert len(writes) == 1
+        clock[0] = start + _MAX_TIMESTAMP_LIFT + 1
+        disk.set("k", _record(clock[0]))
+        assert len(writes) == 2
+        # ...and the embedded timestamp caught up.
+        with open(disk.get_cache_path("k"), "rb") as f:
+            assert disk_cache_module._loads(f.read())["timestamp"] == clock[0]
+
+    def test_another_writer_replacing_the_file_forces_a_rewrite(self, tmp_path, writes):
+        mine, theirs = DiskCache(str(tmp_path)), DiskCache(str(tmp_path))
+        now = time.time()
+        mine.set("k", _record(now, {"v": "mine"}))
+        theirs.set("k", _record(now + 1, {"v": "theirs"}))
+        mine.set("k", _record(now + 2, {"v": "mine"}))
+        assert len(writes) == 3
+        assert mine.get("k", max_age=None)["data"] == {"v": "mine"}
+
+    def test_a_record_without_a_timestamp_still_skips(self, tmp_path, writes):
+        disk = DiskCache(str(tmp_path))
+        disk.set("k", {"plain": True})
+        disk.set("k", {"plain": True})
+        assert len(writes) == 1
+
+
+class TestAgeAfterSkippedWrites:
+    def test_a_skipped_save_keeps_the_record_fresh(self, tmp_path, clock):
+        disk = DiskCache(str(tmp_path))
+        disk.set("k", _record(clock[0], ttl=60))
+        for _ in range(10):          # ten minutes of unchanged 50 s re-saves
+            clock[0] += 50
+            disk.set("k", _record(clock[0], ttl=60))
+        clock[0] += 50
+        record = disk.get("k", max_age=300)
+        assert record is not None
+        # Handed back as a rewrite would have left it.
+        assert record["timestamp"] == pytest.approx(clock[0] - 50, abs=1e-3)
+
+    def test_and_it_expires_on_time_once_the_saves_stop(self, tmp_path, clock, monkeypatch):
+        disk = DiskCache(str(tmp_path))
+        disk.set("k", _record(clock[0]))
+        clock[0] += 200
+        disk.set("k", _record(clock[0]))
+        clock[0] += 59
+        assert disk.get("k", max_age=60) is not None
+        clock[0] += 2
+        parses = []
+        real = disk_cache_module._loads
+        monkeypatch.setattr(disk_cache_module, "_loads",
+                            lambda raw: parses.append(1) or real(raw))
+        assert disk.get("k", max_age=60) is None
+        assert parses == []      # still decided from the header
+
+    def test_the_ttl_is_honoured_the_same_way(self, tmp_path, clock):
+        disk = DiskCache(str(tmp_path))
+        disk.set("k", _record(clock[0], ttl=30))
+        clock[0] += 100
+        disk.set("k", _record(clock[0], ttl=30))
+        clock[0] += 20
+        assert disk.get("k", max_age=5) is not None     # ttl wins, 20 < 30
+        clock[0] += 20
+        assert disk.get("k", max_age=3600) is None      # 40 > 30
+
+    def test_a_restart_sees_the_newest_save(self, tmp_path, clock, writes):
+        disk = DiskCache(str(tmp_path))
+        disk.set("k", _record(clock[0]))
+        clock[0] += 250
+        disk.set("k", _record(clock[0]))
+        restarted = DiskCache(str(tmp_path))     # empty digest map
+        assert restarted.get("k", max_age=60) is not None
+        # It rewrites once (it cannot know what is on disk), then skips.
+        clock[0] += 10
+        restarted.set("k", _record(clock[0]))
+        clock[0] += 10
+        restarted.set("k", _record(clock[0]))
+        assert len(writes) == 2
+
+    def test_the_cache_manager_reads_it_across_processes(self, cm, tmp_path, clock):
+        cm.set("display_state", {"mode": "clock"})
+        clock[0] += 100
+        cm.set("display_state", {"mode": "clock"})
+        # The web interface: its own manager, memory tier bypassed.
+        with patch('src.cache_manager.CacheManager._get_writable_cache_dir',
+                   return_value=str(tmp_path)):
+            web = CacheManager()
+        web.stop_cleanup_thread()
+        clock[0] += 60
+        assert web.get("display_state", max_age=120, memory_ttl=0) == {"mode": "clock"}
+        clock[0] += 70
+        assert web.get("display_state", max_age=120, memory_ttl=0) is None
+
+    def test_retention_sees_the_newest_save(self, cm, clock):
+        cm.set("odds_x", {"line": 1})
+        path = cm._get_cache_path("odds_x")
+        clock[0] += 3000
+        cm.set("odds_x", {"line": 1})
+        assert os.path.getmtime(path) == pytest.approx(clock[0], abs=1e-3)
+
+
+class TestFreshnessCannotBeBorrowed:
+    def test_a_record_written_with_an_old_timestamp_reads_old(self, tmp_path):
+        disk = DiskCache(str(tmp_path))
+        old = time.time() - 600
+        disk.set("k", _record(old))
+        assert os.path.getmtime(disk.get_cache_path("k")) == pytest.approx(old, abs=1e-3)
+        assert disk.get("k", max_age=300) is None
+
+    def test_a_copy_without_mtime_is_bounded(self, tmp_path):
+        disk = DiskCache(str(tmp_path))
+        day_old = time.time() - 86400
+        disk.set("k", _record(day_old))
+        copy_dir = tmp_path / "restored"
+        copy_dir.mkdir()
+        shutil.copyfile(disk.get_cache_path("k"), copy_dir / "k.json")  # mtime = now
+        restored = DiskCache(str(copy_dir))
+        assert restored.get("k", max_age=300) is None
+        record = restored.get("k", max_age=None)
+        assert record["timestamp"] == pytest.approx(day_old + _MAX_TIMESTAMP_LIFT)
+
+    def test_effective_timestamp(self):
+        assert _effective_timestamp(1000.0, None) == 1000.0
+        assert _effective_timestamp(1000.0, 900.0) == 1000.0       # mtime older
+        assert _effective_timestamp(1000.0, 1500.0) == 1500.0      # a skipped save
+        assert _effective_timestamp(1000.0, 10 ** 9) == 1000.0 + _MAX_TIMESTAMP_LIFT

test/test_espn_scoreboard_cache.py

@@ -13,6 +13,7 @@ No network: sessions are fakes, and the fetch service is a fresh one per test.
 
 import json
 import logging
+import os
 import threading
 import time
 from datetime import date, datetime
@@ -321,6 +322,10 @@ class TestWithARealCacheManager:
         record["timestamp"] = time.time() - seconds
         with open(path, "w", encoding="utf-8") as fh:
             json.dump(record, fh)
+        # Rewriting the file moves its mtime to now, and the disk cache takes a
+        # record's age from the newer of its timestamp and its mtime (an
+        # unchanged re-save only touches the file), so age the mtime as well.
+        os.utime(path, (record["timestamp"], record["timestamp"]))
         cm._memory_cache_component.clear()
 
     def test_a_writers_long_ttl_does_not_outlast_the_readers(self, cm, service):

test/test_resource_monitor.py

@@ -18,6 +18,7 @@ from src.plugin_system.resource_monitor import (
     ResourceLimits,
     ResourceLimitExceeded,
     PSUTIL_AVAILABLE,
+    METRICS_SNAPSHOT_KEY,
 )
 
 
@@ -174,7 +175,7 @@ class TestMetricsPersistenceChurn:
         with patch.object(rm.time, "monotonic", return_value=12.0):
             mon.monitor_call("p", lambda: None)
         writes = [c for c in cache.set.call_args_list
-                  if "plugin_metrics:" in str(c)]
+                  if c.args and c.args[0] == rm.METRICS_SNAPSHOT_KEY]
         assert writes, \
             "the first snapshot was dropped because the process was young"
 
@@ -184,7 +185,7 @@ class TestMetricsPersistenceChurn:
         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:")]
+                  if c.args and c.args[0] == METRICS_SNAPSHOT_KEY]
         assert len(writes) == 1, (
             f"50 calls produced {len(writes)} metric writes; expected 1")
 
@@ -194,10 +195,10 @@ class TestMetricsPersistenceChurn:
         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._snapshot_persisted_at -= 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:")]
+                  if c.args and c.args[0] == METRICS_SNAPSHOT_KEY]
         assert len(writes) == 2
 
     def test_in_memory_metrics_stay_exact_while_writes_are_skipped(self):
@@ -213,8 +214,11 @@ class TestMetricsPersistenceChurn:
         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"
+                  if c.args and c.args[0] == METRICS_SNAPSHOT_KEY]
+        # The first call, the reset (which drops the plugin), the next call.
+        assert len(writes) == 3, "reset should clear the throttle timestamp"
+        assert "p" not in writes[1].args[1]["plugins"]
+        assert writes[2].args[1]["plugins"]["p"]["call_count"] == 1
 
     def test_a_failed_write_does_not_buy_the_next_interval_of_silence(self):
         """A set() that raises must not count as having persisted.
@@ -230,5 +234,107 @@ class TestMetricsPersistenceChurn:
         # 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:")]
+                  if c.args and c.args[0] == METRICS_SNAPSHOT_KEY]
         assert len(writes) == 2, "a failed write should be retried, not skipped"
+
+
+class TestOneSnapshotForAllPlugins:
+    """Every plugin's metrics share one record, written at most once a minute.
+
+    A record per plugin, each throttled to 30 s, was still two writes a minute
+    per plugin. The web UI's output must not change: it reads the same numbers
+    for the same plugins, from the snapshot or, for a plugin the snapshot does
+    not have yet, from the per-plugin record an older version left.
+    """
+
+    @pytest.fixture
+    def cache_dir(self, tmp_path):
+        return str(tmp_path)
+
+    def _manager(self, cache_dir):
+        from src.cache_manager import CacheManager
+        with patch('src.cache_manager.CacheManager._get_writable_cache_dir',
+                   return_value=cache_dir):
+            manager = CacheManager()
+        manager.stop_cleanup_thread()
+        return manager
+
+    def test_many_plugins_one_write(self):
+        cache = _cache()
+        mon = PluginResourceMonitor(cache, enable_monitoring=False)
+        for _ in range(10):
+            for pid in ("a", "b", "c", "d"):
+                mon.monitor_call(pid, lambda: None)
+        sets = cache.set.call_args_list
+        assert len(sets) == 1
+        assert not any(str(c.args[0]).startswith("plugin_metrics:") for c in sets)
+
+    def test_the_web_reads_what_the_display_has(self, cache_dir):
+        display = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        for pid in ("a", "b"):
+            display.monitor_call(pid, lambda: None)
+        display._snapshot_persisted_at = None        # let the next call publish
+        display.monitor_call("a", lambda: None)
+        web = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        for pid in ("a", "b"):
+            assert web.get_metrics_summary(pid, force_reload=True) == \
+                display.get_metrics_summary(pid)
+        assert web.get_metrics_summary("a", force_reload=True)["call_count"] == 2
+
+    def test_a_per_plugin_record_from_an_older_version_is_still_read(self, cache_dir):
+        old = self._manager(cache_dir)
+        old.set("plugin_metrics:legacy", {"call_count": 9, "total_execution_time": 1.8,
+                                          "last_update_time": time.time()})
+        display = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        display.monitor_call("other", lambda: None)
+        web = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        assert web.get_metrics_summary("legacy", force_reload=True)["call_count"] == 9
+        # The display carries the count on from it, into the snapshot.
+        display.monitor_call("legacy", lambda: None)
+        display._snapshot_persisted_at = None
+        display.monitor_call("other", lambda: None)
+        assert web.get_metrics_summary("legacy", force_reload=True)["call_count"] == 10
+
+    def test_a_restart_keeps_plugins_it_has_not_run(self, cache_dir):
+        first = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        first.monitor_call("disabled_later", lambda: None)
+        restarted = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        restarted.monitor_call("running", lambda: None)
+        web = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        assert web.get_metrics_summary("disabled_later", force_reload=True)["call_count"] == 1
+        assert web.get_metrics_summary("running", force_reload=True)["call_count"] == 1
+
+    def test_a_reset_from_the_web_sticks_for_a_plugin_the_display_is_not_running(
+            self, cache_dir):
+        display = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        display.monitor_call("idle", lambda: None)
+        web = PluginResourceMonitor(self._manager(cache_dir), enable_monitoring=False)
+        assert web.get_metrics_summary("idle", force_reload=True)["call_count"] == 1
+        web.reset_metrics("idle")
+        display._snapshot_persisted_at = None
+        display.monitor_call("busy", lambda: None)
+        assert web.get_metrics_summary("idle", force_reload=True)["call_count"] == 0
+
+    def test_a_long_idle_plugin_is_dropped(self, cache_dir):
+        import src.plugin_system.resource_monitor as rm
+        manager = self._manager(cache_dir)
+        manager.set(METRICS_SNAPSHOT_KEY, {"schema": 1, "plugins": {
+            "gone": {"call_count": 3, "last_update_time":
+                     time.time() - rm._METRICS_SNAPSHOT_ENTRY_MAX_AGE - 10},
+            "recent": {"call_count": 4, "last_update_time": time.time() - 60},
+        }})
+        display = PluginResourceMonitor(manager, enable_monitoring=False)
+        display.monitor_call("p", lambda: None)
+        plugins = manager.get(METRICS_SNAPSHOT_KEY, max_age=None, memory_ttl=0)["plugins"]
+        assert set(plugins) == {"recent", "p"}
+
+    @pytest.mark.parametrize("junk", [[1, 2], {"schema": 99, "plugins": {"p": {}}},
+                                      {"schema": 1, "plugins": "nope"}])
+    def test_an_unusable_snapshot_is_ignored(self, junk):
+        cache = MagicMock()
+        cache.get.side_effect = lambda key, **kw: junk if key == METRICS_SNAPSHOT_KEY else None
+        mon = PluginResourceMonitor(cache, enable_monitoring=False)
+        assert mon.get_metrics_summary("p", force_reload=True)["call_count"] == 0
+        mon.monitor_call("p", lambda: None)
+        written = cache.set.call_args.args[1]
+        assert written["plugins"]["p"]["call_count"] == 1