Skip to main content

Watching a cache in production

A health check and an admin endpoint for a cache: entries, bytes on disk, hit ratio, the size limit, the write-ahead log, check() for damage, and the log lines worth alerting on.

A cache runs inside your workers for weeks without anyone looking at it, until a page gets slow or the disk fills up and someone asks whether the cache is working. Is it full? Is anything hitting it? Is the write-ahead log eating the disk? The numbers that answer those questions are cheap to read, so put them on a health endpoint or an admin page before you need them.

A health check

Everything here reads a few numbers and never waits on writers, so it’s fine to call on every health probe:

import os
import tempfile

from diskcache_oxide import Cache, CacheLike

cache = Cache(tempfile.mkdtemp(), size_limit=64 * 2**20)
cache.stats(enable=True)  # at startup, in every worker: counting is off until something turns it on

def wal_bytes(cache: CacheLike) -> int:
    if cache.directory is None:  # a NullCache
        return 0
    try:
        return os.path.getsize(os.path.join(cache.directory, 'diskcache-oxide.sqlite-wal'))
    except FileNotFoundError:
        return 0

def cache_health(cache: CacheLike) -> dict:
    hits, misses = cache.stats()
    lookups = hits + misses
    volume = cache.volume()
    return {
        'enabled': cache.enabled,
        'entries': len(cache),
        'volume_mib': round(volume / 2**20, 1),
        'percent_of_limit': round(100 * volume / cache.size_limit, 1),
        'eviction_policy': cache.eviction_policy,
        'hits': hits,
        'misses': misses,
        'hit_ratio': round(hits / lookups, 2) if lookups else None,
        'wal_mib': round(wal_bytes(cache) / 2**20, 1),
    }

for n in range(200):
    cache.set(f'page:{n}', 'x' * 20_000)
for n in range(300):
    cache.get(f'page:{n}')

print(cache_health(cache))
{'enabled': True, 'entries': 200, 'volume_mib': 3.9, 'percent_of_limit': 6.2, 'eviction_policy': 'least-recently-stored', 'hits': 200, 'misses': 100, 'hit_ratio': 0.67, 'wal_mib': 3.9}

Return it from an endpoint and you have something to graph or alert on. In Flask:

@app.get('/health/cache')
def health_cache() -> dict:
    return cache_health(cache)

In FastAPI the same function body works under @app.get('/health/cache'). Keep the endpoint behind your admin auth or on an internal port: the numbers aren’t secret, but there’s no reason to publish them.

In Kubernetes or behind a load balancer, use it as a readiness check, never a liveness check. A liveness failure restarts the process, and a cache outage is exactly what durable=True absorbs: restarting for it only adds a cold start.

What the numbers mean

  • enabled is False for a NullCache. If the cache comes from a Caches registry, that’s what a lookup hands out while the cache can’t open, so enabled: false on a cache you never switched off means something is wrong. The log says what.
  • len(cache) counts live entries: an entry stops counting the moment it expires, even before its row is removed. It’s a stored total less the expired rows still on disk, so it costs the same on a cache of ten entries or ten million, plus a little for each expired entry nothing has removed yet.
  • volume() is the cache’s size in bytes: the database pages in use plus the value files. It leaves out the write-ahead log and pages freed by deletes, which SQLite keeps in the file for reuse, so du on the directory can show more. check(fix=True) (below) gives the freed pages back.
  • size_limit and eviction_policy. Under the default 'least-recently-stored', a full cache sits close to its limit, and that’s normal: each set() that finds it over the limit evicts the oldest entries. Under 'none' nothing is evicted for size, so percent_of_limit can pass 100. On a sessions or work queue cache, that’s the number to alert on. Both attributes are the values this process last saw; cache.reset('size_limit') and cache.reset('eviction_policy') read what’s stored now, in case another process changed them.
  • Hits and misses count get and cache[key] in this process. An expired entry, and a value answered as a miss by on_decode_error, count as misses. in, pop and iteration don’t count, and a durable=True outage answered as a miss counts as nothing. A FanoutCache sums its shards, and a NullCache always reports (0, 0).

A low hit ratio on a full 'least-recently-stored' cache can mean size_limit is too small for what you’re caching: entries are evicted before anyone reads them twice. Raise it with cache.reset('size_limit', 2 * 2**30), which every process picks up at its next write, or in the constructor for the next deploy.

Hits and misses across workers

The counts live in each process’s memory and are never written to the database, so reading them costs nothing. That also means a health probe that lands on one gunicorn worker sees that worker’s counts only, since its last restart; a forked child starts from zero. Every handle on one directory in a process shares one set of counts, and they survive closing the last handle.

For a total across workers, have each worker add its counts to a shared counter now and then, from a timer or after every few hundred requests. Keep those counters in a small cache of their own, so reading the totals doesn’t count as lookups in the cache you’re measuring:

counters = Cache(tempfile.mkdtemp())

def publish_stats(cache: Cache, counters: Cache) -> None:
    hits, misses = cache.stats(reset=True)
    counters.incr('pages:hits', hits)
    counters.incr('pages:misses', misses)

publish_stats(cache, counters)
cache.get('page:1')
publish_stats(cache, counters)
print('every worker:', counters.get('pages:hits'), 'hits,', counters.get('pages:misses'), 'misses')
print('this worker since:', cache.stats())
every worker: 201 hits, 100 misses
this worker since: (0, 0)

stats(reset=True) returns the counts and zeroes them in one call, so a lookup between the read and the reset isn’t lost. This is the counters recipe applied to the cache itself.

An admin page for every cache

A Caches registry gives you one row per cache with stats(). It opens each registered cache, and never raises: a cache that can’t be opened gets its error set, with the exception’s type and message.

import dataclasses

from diskcache_oxide import Caches

caches = Caches(tempfile.mkdtemp(), timeout=1.0)
caches.register('general')
caches.register('pages', size_limit=256 * 2**20)
caches['general'].set('greeting', 'hello')

for name, stat in caches.stats().items():
    print(dataclasses.asdict(stat) | {'directory': '...'})
{'name': 'general', 'directory': '...', 'enabled': True, 'count': 1, 'volume': 40960, 'error': None, 'maintenance': {'interval': 300.0, 'turns': 0, 'removed': 0, 'failures': 0, 'last_error': None}}
{'name': 'pages', 'directory': '...', 'enabled': True, 'count': 0, 'volume': 40960, 'error': None, 'maintenance': {'interval': 300.0, 'turns': 0, 'removed': 0, 'failures': 0, 'last_error': None}}

A cache that can’t open shows up here with count and volume at 0 and the reason in error, for example LayoutMismatchError: ... for a directory that holds the other kind of cache. An upgrade that changed the on-disk format doesn’t: the cache opens in its versioned subdirectory. Watch for that with the warning instead. A diskcache_oxide record at WARNING saying a directory “holds a cache made by an older diskcache-oxide” (or “still holds”) means old files are waiting for remove_old_formats(), and “made by a newer diskcache-oxide” means a process is running an older release than the one that wrote the cache (see Upgrading across a format change).

As an endpoint, with each cache’s hit counts added. Every cache in this registry is a plain one; read a sharded one with caches.fanout(name) instead, since caches[name] raises TypeError for it:

@app.get('/admin/caches')
def admin_caches() -> dict:
    rows = {}
    for name, stat in caches.stats().items():
        hits, misses = caches[name].stats()
        rows[name] = dataclasses.asdict(stat) | {'hits': hits, 'misses': misses}
    return rows

@app.post('/admin/caches/<name>/clear')
def clear_cache(name: str) -> dict:
    return {'removed': caches.clear(name, timeout=10)}

caches.clear() raises if the cache can’t be opened, so the page never reports “0 removed” for a failure. It works on a disabled cache too. Give it a longer timeout= than the request path’s, since it holds the write lock once per chunk. For the rest of the registry’s admin calls, see Admin and shutdown.

Prometheus

A custom collector reads the registry at scrape time, so there’s nothing to update on each request. Entry counts and sizes come from the caches themselves, so every worker reports the same numbers and gunicorn’s Prometheus multiprocess mode isn’t needed for them:

from prometheus_client.core import REGISTRY, GaugeMetricFamily


class CacheCollector:
    def collect(self):
        entries = GaugeMetricFamily('app_cache_entries', 'Entries in each cache', labels=['cache'])
        size = GaugeMetricFamily('app_cache_bytes', 'Bytes on disk for each cache', labels=['cache'])
        up = GaugeMetricFamily('app_cache_up', '1 if the cache opened, 0 if not', labels=['cache'])
        for name, stat in caches.stats().items():
            entries.add_metric([name], stat.count)
            size.add_metric([name], stat.volume)
            up.add_metric([name], 0 if stat.error else 1)
        yield from (entries, size, up)


REGISTRY.register(CacheCollector())

Hit and miss counts are per process (stats() counts in memory), so under several workers a scrape sees only the worker that answered it. Count them in the cache itself if you need them across workers: Hits and misses across workers above shows how.

The write-ahead log

wal_mib in the health check is the size of diskcache-oxide.sqlite-wal beside the database. At normal load wal_size_limit keeps it at a few MiB. A burst of writes with readers in other processes can leave it much larger, and in the default wal_checkpoint='manual' mode it stays that size until something checkpoints it.

If it keeps growing, call checkpoint() from a maintenance job. It returns True when the log was copied into the database and truncated, and False, without raising, when other processes kept it busy; try again later. If that isn’t enough, open the cache with wal_checkpoint='auto'. Storage and WAL has the details. A FanoutCache has one log per shard, in the shard folders (000/, 001/, …), so add those up for the total.

Checking for damage

check() compares the database with the value files and returns what it found as a list of warnings.WarningMessage, without issuing any warnings. An empty list means nothing is wrong. Here a value file is deleted behind the cache’s back:

import glob

damaged = Cache(tempfile.mkdtemp())
damaged.set('report', b'x' * 100_000)   # 64 KiB or more: stored in a file of its own
damaged.set('summary', 'small')
[path] = glob.glob(os.path.join(damaged.directory, '*', '*.val'))
os.remove(path)                          # what a bad disk or a stray rm would do

for warning in damaged.check():
    print(warning.category.__name__, str(warning.message).replace(damaged.directory, '...'))
print('repaired:', len(damaged.check(fix=True)), '| after:', damaged.check(), '| entries:', len(damaged))
UserWarning file not found: .../be/be8cb21af8d69b1a87ca1e0e12288c87.val
repaired: 1 | after: [] | entries: 1

It reports SQLite’s integrity_check lines, value files that are missing or the wrong size, files nobody owns that are over an hour old, and stored totals that don’t match the rows. check(fix=True) also repairs: it removes entries whose files are missing or cut short (they read as misses anyway), removes unowned files in the value folders, corrects the totals, then runs VACUUM, which shrinks the database file to what’s in use, and checkpoints.

Run it from a scheduled job one worker claims, never from a health probe. integrity_check reads the whole database and VACUUM rewrites it, and writers and forks wait for both. VACUUM also needs room for a temporary copy of the database in SQLITE_TMPDIR, TMPDIR or /tmp.

import logging

log = logging.getLogger('my_app')

def nightly_cache_check() -> None:
    problems = cache.check()
    for warning in problems:
        log.warning('cache check: %s', warning.message)
    if problems:
        cache.check(fix=True)

Log lines to alert on

Where diskcache-oxide has been told not to raise, it logs on the diskcache_oxide logger instead, and that line is then the only sign anything happened. Make sure the logger reaches your log aggregator or Sentry:

  • A Caches cache that can’t open logs at ERROR with the traceback, once per retry, and hands out a NullCache meanwhile. An open that only timed out logs at WARNING.
  • durable=True logs swallowed failures at most once a minute per cache handle, with counts by operation: WARNING for a busy lock, ERROR for a full disk, an I/O error or a failed delete.
  • on_decode_error='miss' logs a warning for a stored value it couldn’t read.
  • A cache whose directory holds another on-disk format logs a WARNING once per process: “holds a cache made by an older diskcache-oxide” (or “still holds”, while the old files remain), or “made by a newer diskcache-oxide” when a process runs an older release than the one that wrote it. The record carries directory, using, found and found_in. See Upgrading across a format change.
  • A FanoutCache whose folder has another shard count than shards= logs a WARNING once per process (the record carries directory, stored_shards and requested_shards), and a Caches registry logs its own WARNING and one ERROR per process.

The exact messages, and what to do about each, are in Errors and what to do about them.

Things to know

  • stats() turns counting on. Its enable argument defaults to True, so a health check that reads the counts also starts them. stats(enable=False) turns counting off and stops the counts where they are.
  • Counts reset on restart. Graph the hit ratio, not the raw counts, or publish the counts as above.
  • volume() includes expired entries until background maintenance or a set()’s cleanup removes them, though len() already leaves them out, so it can drop on its own between calls.
  • Background maintenance reports in maintenance_stats(): its interval (0 when it’s off for the cache in this process), the turns that ran, the entries they removed, failures and the last_error. A failure is also logged once as a WARNING on the diskcache_oxide logger, by the next get, set or other single-key call, so a cache nobody calls shows it here only. caches.stats() carries it per cache as maintenance. Alert on failures going up.
  • Health checks shouldn’t write. Everything in cache_health is a read. check() and checkpoint() belong in a maintenance job.