The DEL that blocked the server, and UNLINK

Once an hour, every request slowed by about 400 milliseconds for roughly two seconds, and then everything was fine again. Nothing in the application ran on that schedule. The application was not the problem — the cache cleanup was, and it was three lines long.

The symptom

The response-time graph had a comb pattern: flat, then a spike, then flat again, at :07 past every hour. The spike touched every endpoint at once, including ones that do almost nothing, which is the shape of a shared dependency rather than a slow query.

$ redis-cli --latency-history -i 10
min: 0, max: 1, avg: 0.19 (1029 samples) -- 10.00 seconds range
min: 0, max: 1, avg: 0.21 (1024 samples) -- 10.00 seconds range
min: 0, max: 412, avg: 8.94 (287 samples) -- 10.01 seconds range   ← here
min: 0, max: 1, avg: 0.18 (1031 samples) -- 10.00 seconds range

That is Redis reporting on itself, and it is unambiguous: a 412 millisecond round trip on a server whose ordinary maximum is one. The application was waiting on the cache, and the cache was waiting on itself.

Why it happens

Redis executes commands one at a time on a single thread. That is a design decision rather than a limitation — it removes locking entirely and is why individual operations are measured in microseconds — but it has a direct consequence that is easy to forget: while one command runs, every other client waits.

Most commands are trivially fast, so this never matters. DEL is not one of them. Deleting a key means freeing the memory that held it, and for a hash with two million fields that is two million individual deallocations on the thread that is also serving every other request.

127.0.0.1:6379> DEBUG SLEEP 0
OK
127.0.0.1:6379> MEMORY USAGE sessions:index
(integer) 418209344
127.0.0.1:6379> DEBUG OBJECT sessions:index
Value at:0x7f8e... encoding:hashtable serializedlength:... ql_nodes:0

# 400 MB in one key. deleting it is 400 MB of frees, in the foreground.

The hourly job was DEL sessions:index followed by a rebuild. Nobody had thought of a delete as expensive, because in every other database it is a write to a log and the space is reclaimed later by something else.

The fix

UNLINK, which arrived in 4.0 this month

UNLINK removes the key from the keyspace immediately and hands the actual deallocation to a background thread. The key is gone from the caller’s point of view in constant time; the memory comes back a moment later.

// before
$redis->del('sessions:index');

// after — same semantics for the caller, different thread does the freeing
$redis->rawCommand('UNLINK', 'sessions:index');

// phpredis 3.1.3 does not have ::unlink() yet, hence rawCommand.
// the wrapper is worth having anyway, because it needs a fallback:
final class Cache
{
    public function forget($key)
    {
        if ($this->supportsUnlink) {
            $this->redis->rawCommand('UNLINK', $key);
            return;
        }

        $this->redis->del($key);
    }
}

The capability check matters because a 3.2 server answers UNLINK with an error rather than falling back, and a cache layer that throws on eviction is worse than one that blocks briefly. Reading INFO server once at boot and caching the answer is enough.

Making it the default rather than a call site

4.0 also added configuration that applies the same treatment to deletes the application never issues explicitly — expiry, eviction under maxmemory, and the implicit delete when a key is overwritten by a rename.

lazyfree-lazy-eviction    yes   # freeing under maxmemory pressure
lazyfree-lazy-expire      yes   # freeing an expired key
lazyfree-lazy-server-del  yes   # the implicit del inside RENAME etc.
replica-lazy-flush        yes   # a replica wiping its dataset on full resync

These default to no, which is the conservative choice for an upgrade and the wrong one for any instance holding large collections. The eviction one is the most valuable: an instance at its memory limit is evicting constantly, and doing that in the foreground turns a memory problem into a latency problem.

What else blocks, which is more than DEL

Once the single thread is the mental model, a set of commands that looked harmless becomes obviously dangerous. All of them are O(n) on the foreground thread.

// KEYS scans the entire keyspace. never in production.
$redis->keys('session:*');

// SCAN is the replacement — a cursor, bounded work per call
$cursor = null;

do {
    $keys = $redis->scan($cursor, 'session:*', 500);

    if ($keys !== false) {
        foreach ($keys as $key) {
            $redis->rawCommand('UNLINK', $key);
        }
    }
} while ($cursor > 0);

// FLUSHALL / FLUSHDB — 4.0 takes ASYNC
$redis->rawCommand('FLUSHDB', 'ASYNC');

// and the one people write themselves:
// a Lua script looping over a million elements is a million operations
// on the single thread, and MULTI/EXEC is the same.

The Lua case is the one that catches experienced people, because scripts are described as atomic and atomicity is achieved by not letting anything else run. A script is a lock on the whole server for its duration, so the correct length for one is short.

The slow log finds these without guessing, and its default threshold of 10,000 microseconds is far too generous for a store whose normal operation is under 200. Lowering it to 5,000 during an investigation is free.

127.0.0.1:6379> CONFIG SET slowlog-log-slower-than 5000
OK
127.0.0.1:6379> SLOWLOG GET 3
1) 1) (integer) 1841
   2) (integer) 1500901620
   3) (integer) 411208            ← microseconds
   4) 1) "DEL"
      2) "sessions:index"
2) 1) (integer) 1840
   2) (integer) 1500898020
   3) (integer) 398471
   4) 1) "DEL"

Verifying it worked

# same command, the following hour
$ redis-cli --latency-history -i 10
min: 0, max: 1, avg: 0.19 (1030 samples) -- 10.00 seconds range
min: 0, max: 2, avg: 0.22 (1028 samples) -- 10.00 seconds range   ← :07 past
min: 0, max: 1, avg: 0.18 (1031 samples) -- 10.00 seconds range

# application p99, hourly buckets
# before  188ms 191ms 604ms 187ms 190ms 611ms
# after   186ms 189ms 193ms 188ms 191ms 190ms

The comb is gone from both graphs. The assertion worth making is the second one: the fix is only interesting if it shows up in what a user experiences, and a Redis latency graph on its own does not prove that.

Worth adding permanently rather than for the investigation: a check that samples latency-history and alerts on a maximum above a few milliseconds. This class of problem is invisible in average latency — the hourly spike moved the average by nine milliseconds — and only shows up in a maximum or a high percentile.

What this costs

Memory is reclaimed later rather than immediately, so peak usage is higher than it was. On an instance sized close to its limit that is a real risk: the freeing that maxmemory eviction triggers is now asynchronous too, so a burst can push past the limit while the background thread catches up.

The honest summary is that this trades a memory guarantee for a latency guarantee, and that is the right trade for a cache and possibly the wrong one for a queue backing store sized to the megabyte. The larger cost is conceptual: every operation now needs to be thought about in terms of how long it occupies a thread that everything else is waiting for, and that is not how anyone is used to thinking about a key-value store.