The Slowlog Is Empty and the Cache Still Feels Slow

An alert says the cache is slow. You open the slowlog, and it is empty. The natural conclusion is that Redis is fine and the problem sits in the application.

That conclusion is wrong often enough to be worth a post. The slowlog is not a list of slow commands. It is a list of commands that crossed a threshold you probably never set.

The default threshold is 10 milliseconds

Two settings control the log, and both have defaults that matter:

redis-cli CONFIG GET slowlog-log-slower-than   # 10000 (microseconds)
redis-cli CONFIG GET slowlog-max-len           # 128 (entries)

Execution time is recorded in microseconds, so the default admits only commands slower than 10 ms. On a cache where a normal GET takes 50 microseconds, a command that takes 8 ms is 160 times slower than normal and still leaves no trace.

The second default matters during incidents. The buffer holds 128 entries, and it is in memory only. A burst of slow commands pushes the earlier ones out, and a restart erases the whole thing.

One more property is easy to misread: the recorded time covers execution inside Redis and excludes the network round trip and the time spent writing the reply back to the client. A command can be fast in the slowlog and slow for the user.

Two clocks, two questions

redis-cli --latency answers a different question. It sends PING in a loop and reports the round trip, which includes the network path, the socket, and the server itself.

redis-cli --latency
# min: 0, max: 2, avg: 0.15 (99 samples)

That is a healthy local instance. If this number is high while the slowlog is empty, the problem lives between the client and the server rather than inside command execution. If both are healthy, the next suspect is the application, the connection pool, or the client library.

What a single blocking command does

Here is the case that hides best. A 200,000-key instance, one KEYS *, default threshold:

Redis is single threaded for command execution, so those 39 milliseconds are not slow for one client. They are 39 milliseconds during which every other client waits. At 5,000 requests per second, that one command queues roughly 200 of them.

SCAN did the same work in 200 calls averaging 357 microseconds. Total server time was higher, 71 ms against 39 ms, and that is the honest trade: cursor iteration costs more overall and never blocks anyone for long. It also never appears in the slowlog, because no single call comes close to 10 ms.

So the slowlog stays empty while a client that walks the keyspace with SCAN in a tight loop keeps the server busy all day. INFO commandstats is where that shows up.

When the log is empty, make it talk

Lower the threshold for a few minutes.

redis-cli CONFIG SET slowlog-log-slower-than 1000   # 1 ms
# wait through the slow period
redis-cli SLOWLOG GET 10
redis-cli CONFIG SET slowlog-log-slower-than 10000  # put it back

On the same test instance, dropping the threshold to 1 ms turned an empty log into 40 entries within one keyspace walk. Restore the value when you are done: at 1 ms a busy production server fills 128 entries in seconds, and the buffer stops being useful.

Read per-command averages.

redis-cli INFO commandstats
# cmdstat_keys:calls=1,usec=39217,usec_per_call=39217.00
# cmdstat_scan:calls=200,usec=71500,usec_per_call=357.50

This is the view that catches the death-by-a-thousand-cuts case: a command that never crosses any threshold, called far too often.

Turn on the latency monitor.

redis-cli CONFIG SET latency-monitor-threshold 20
redis-cli LATENCY LATEST
redis-cli LATENCY DOCTOR

The monitor is off by default (latency-monitor-threshold 0). Once armed it records spikes by event type, including events the slowlog cannot attribute to a command: fork pauses during a background save, expire cycles, and eviction storms under maxmemory.

The commands worth hunting

Four patterns account for most of what a slowlog surfaces once you can see it:

• KEYS on anything but a toy dataset. Replace it with SCAN and a cursor.
• Whole-collection reads: HGETALL, SMEMBERS, LRANGE key 0 -1 on collections that grew past a few thousand elements. HSCAN, SSCAN, and ranged reads exist for this.
• Lua scripts that loop. Everything inside EVAL runs as one blocking unit.
• DEL on a huge collection. Freeing a million-element set costs real time; UNLINK moves that work to a background thread.

Doing this from a phone at 2 AM

The measurements above are four terminal commands, which is fine at a desk and awkward from a phone through a bastion host.

CacheDeck runs the same checks as a screen. The Analyze view pulls INFO, reads SLOWLOG, and samples the keyspace with SCAN cursors, then reports what it found. Key browsing always uses SCAN, never KEYS, so inspecting a production instance from your phone cannot become the incident. Connections can be opened read-only, which blocks every mutation until you unlock them for five minutes on purpose, and anything tagged PROD carries a badge and a type-to-confirm step before a destructive command runs.

The checklist

1. redis-cli --latency for the round trip.
2. SLOWLOG GET 10, remembering the 10 ms default.
3. CONFIG SET slowlog-log-slower-than 1000 for a few minutes, then read again and restore it.
4. INFO commandstats for commands that are cheap once and expensive by volume.
5. CONFIG SET latency-monitor-threshold 20, then LATENCY LATEST for spikes with no command attached.

An empty slowlog is a fact about your threshold. It is not a verdict about your cache.