What happens
RedisStore.Keys() in engine/cache/redis.go issues the Redis KEYS command.
KEYS is O(N) over the entire keyspace, and Redis executes commands on a single
thread — io-threads parallelises socket reads and protocol parsing only, not
command execution. So for as long as a KEYS call runs, every other client of
that Redis waits, whatever it was asking for.
The CDN calls this in a hot loop. engine/cdn/cdn_log_engine.go:
func (s *Service) waitingJobs(ctx context.Context) {
for {
time.Sleep(250 * time.Millisecond)
...
keyListQueue := cache.Key(keyJobLogQueue, "*")
listKeys, err := s.Cache.Keys(keyListQueue)
Four full keyspace scans per second, forever, for the lifetime of the service.
Measurements
From a CDS instance with a 143k-key Redis (redis_version 7.4.3, io-threads 1):
SLOWLOG LEN 128
entries matching KEYS cdn:log:job:* 128 ← every single entry
per-call duration 27,085–35,560 µs (27–35 ms)
DBSIZE 143,523
instantaneous_ops_per_sec 252
redis CPU under load 88% of a core
Every entry in the slow-command log was this one call. Nothing else in the
system was slow enough to register.
The knock-on effect is not confined to the CDN — every CDS service shares this
Redis, so the stall lands on lock acquisition, queue pops and cache reads
belonging to unrelated components. On our instance a repository analysis sat
unclaimed for 136 seconds while its poller ticked every 5 seconds, because
each tick's Redis work was queued behind these scans.
Severity depends on keyspace size
The blocking is inherent to KEYS on any Redis deployment, but the cost is
O(keyspace). A small installation may never notice; ours became unusable. Worth
saying plainly so the report isn't read as universal breakage.
Proposed fix
Walk the keyspace with SCAN instead. Same result, never blocks for more than
one batch. SCAN can return duplicates across cursor steps (de-duplicated) and
is a moving view rather than a snapshot — for a caller polling to find work to
pick up, that is what KEYS gave it in practice anyway.
PR: #7837
After the change, same instance
SLOWLOG LEN 0 (was 128, all KEYS)
command latency 0.00 ms (was 27–35 ms blocking)
instantaneous_ops_per_sec 153 (was 252)
redis CPU 47.6% (was 88%)
CDN "unable to list jobs queues" errors 0
Batch size matters: at COUNT 1000 the 143k keyspace takes ~140 cursor steps
and the command rate went up (252 → 523/s) before settling at ~15 steps and
153/s with COUNT 10000.
What happens
RedisStore.Keys()inengine/cache/redis.goissues the RedisKEYScommand.KEYSis O(N) over the entire keyspace, and Redis executes commands on a singlethread —
io-threadsparallelises socket reads and protocol parsing only, notcommand execution. So for as long as a
KEYScall runs, every other client ofthat Redis waits, whatever it was asking for.
The CDN calls this in a hot loop.
engine/cdn/cdn_log_engine.go:Four full keyspace scans per second, forever, for the lifetime of the service.
Measurements
From a CDS instance with a 143k-key Redis (
redis_version 7.4.3,io-threads 1):Every entry in the slow-command log was this one call. Nothing else in the
system was slow enough to register.
The knock-on effect is not confined to the CDN — every CDS service shares this
Redis, so the stall lands on lock acquisition, queue pops and cache reads
belonging to unrelated components. On our instance a repository analysis sat
unclaimed for 136 seconds while its poller ticked every 5 seconds, because
each tick's Redis work was queued behind these scans.
Severity depends on keyspace size
The blocking is inherent to
KEYSon any Redis deployment, but the cost isO(keyspace). A small installation may never notice; ours became unusable. Worth
saying plainly so the report isn't read as universal breakage.
Proposed fix
Walk the keyspace with
SCANinstead. Same result, never blocks for more thanone batch.
SCANcan return duplicates across cursor steps (de-duplicated) andis a moving view rather than a snapshot — for a caller polling to find work to
pick up, that is what
KEYSgave it in practice anyway.PR: #7837
After the change, same instance
Batch size matters: at
COUNT 1000the 143k keyspace takes ~140 cursor stepsand the command rate went up (252 → 523/s) before settling at ~15 steps and
153/s with
COUNT 10000.