数据库与缓存排查 列表全部文章
数据库与缓存排查

Redis 隔几分钟“抽风”一次:一个 200 万字段的 Hash,拖着全公司业务一起卡

Redis 没宕机、CPU 也不高,却隔几分钟整体卡顿,别的业务跟着超时。用 SLOWLOG、latency doctor、--bigkeys / --memkeys、MEMORY USAGE 揪出一个大 Hash 和一条 HGETALL,附 UNLINK、SCAN、拆 key 的完整修法。

更多

周三下午三点,钉钉群里先是订单组的同学问:“Redis 是不是抖了?”过了一分钟,用户中心组也冒出来:“我这边偶发超时。”又过了一分钟,风控组发了个表情包——一只小猫盯着屏幕流泪。

我打开监控:Redis 实例没宕机、内存没涨、CPU 也就 30%,可业务侧 Jedis/Lettuce 的超时日志像雪一样飘:Command timed out after 3 second(s)。最诡异的是——它是“隔几分钟抽一下”,抽完自己又好了。这类“间歇性、全局性”的卡顿,我的第一直觉是:有人在 Redis 这个单线程里干了一件很慢的事,所有人都得排队等他。

一、现象:不是慢,是“停摆”

先理解一个前提:Redis 命令执行是(基本上)单线程的。官方延迟文档里写得很清楚:一个请求处理得慢,其他所有客户端都要等它。所以“一条慢命令”对别的业务而言,效果等同于“Redis 整体不可用了 N 秒”。

我们当时看到的证据:

  • 业务日志:多个不同业务、不同 key 的 GET/HGET 同时超时(这些命令本身是 O(1),不可能慢,所以它们是“被拖累”的);
  • Redis 监控:instantaneous_ops_per_sec 出现周期性“凹陷”——不是流量下降,是那几秒 Redis 根本没在处理;
  • 网络流出流量(net output)出现尖刺:某一刻突然输出了几百 MB,这是个很重要的线索,后面解释;
  • Redis 所在机器 CPU 正常,没有 swap,磁盘 IO 也正常(用 vmstat 1、iostat -xk 1 排除过)。

先做一个 30 秒的小实验,判断是不是“Redis 自己停摆”,而不是网络问题:

$ redis-cli -h 10.0.0.21 -p 6379 --latency-history -i 5
min: 0, max: 1, avg: 0.19 (1314 samples) -- 5.01 seconds range
min: 0, max: 1, avg: 0.18 (1299 samples) -- 5.00 seconds range
min: 0, max: 2314, avg: 27.65 (312 samples) -- 5.01 seconds range
min: 0, max: 1, avg: 0.20 (1301 samples) -- 5.00 seconds range

--latency-history 每隔 -i 秒重新统计一段(默认 15 秒),单位是毫秒。前两段最大 1ms 很健康,第三段 max 高达 2314ms,样本数从 1300 掉到 312——PING 都被卡了两秒多,说明 Redis 这两秒确实在忙别的、没空回复。至此,“单线程被某个慢操作占住”成立。

二、排查路线图

Redis 偶发整体卡顿,我的排查顺序是:先看慢命令,再看大 key,然后才怀疑持久化、fork、swap 这些系统层面的原因。

① --latency-history确认 Redis 自己停摆(排除网络) ② SLOWLOG GET谁是慢命令耗时多少 μs ③ --bigkeys/--memkeys全库扫描大 keyMEMORY USAGE 复核 ④ LATENCY DOCTOR交叉验证事件command / fork / aof ⑤ 修UNLINK / SCAN拆 key / 禁危险命令 若 SLOWLOG 为空:看 fork(latest_fork_usec)、AOF fsync、swap、透明大页 → 官方延迟文档的 checklist 注意:SLOWLOG 只记录“命令执行”耗时,不含网络收发;所以“返回超大结果”造成的卡顿要结合流量看

三、动手:一步步把凶手揪出来

第 1 步:SLOWLOG GET——谁在占着单线程

Redis 的慢日志会记录执行时间超过阈值的命令,阈值由 slowlog-log-slower-than 决定(单位微秒,默认 10000,即 10ms),最多保留 slowlog-max-len 条。先确认配置,再看内容:

$ redis-cli -h 10.0.0.21 config get slowlog-log-slower-than
1) "slowlog-log-slower-than"
2) "10000"
$ redis-cli -h 10.0.0.21 config get slowlog-max-len
1) "slowlog-max-len"
2) "128"

$ redis-cli -h 10.0.0.21 slowlog get 5
1) 1) (integer) 4823
   2) (integer) 1730272931
   3) (integer) 1874553
   4) 1) "HGETALL"
      2) "cart:promo:hot"
   5) "10.0.2.15:52344"
   6) "order-service"
2) 1) (integer) 4822
   2) (integer) 1730272611
   3) (integer) 2130971
   4) 1) "HGETALL"
      2) "cart:promo:hot"
   5) "10.0.2.16:41188"
   6) "order-service"
3) 1) (integer) 4821
   2) (integer) 1730272301
   3) (integer) 312044
   4) 1) "SMEMBERS"
      2) "user:tags:all"
   5) "10.0.3.7:38820"
   6) "profile-service"
...

每条记录含 6~7 个字段(第 7 个参数总数是新版本才有的):唯一 ID、Unix 时间戳、执行耗时(微秒)、命令与参数、客户端 IP:端口、客户端名(需要 CLIENT SETNAME,所以建议客户端都配名字,这一步会直接告诉你是哪个服务)。

解读:第一条 1874553 微秒 = 1.87 秒,命令是 HGETALL cart:promo:hot;第二条 2.13 秒,还是它;间隔大约 5 分钟(时间戳 1730272611 → 1730272931 差 320 秒)——正好对应“隔几分钟抽一下”。第三条是 SMEMBERS user:tags:all,312ms,也不是善茬。

顺带说一下,SLOWLOG 记的是命令执行本身的时间,不含网络 IO。所以如果是“返回值太大、发送很慢”,SLOWLOG 可能只记到一部分,还要配合网络流量曲线看。

第 2 步:INFO commandstats——从统计上再确认一次

$ redis-cli -h 10.0.0.21 info commandstats | egrep 'hgetall|smembers|keys|get:|hget:'
cmdstat_get:calls=918273645,usec=1102394817,usec_per_call=1.20,rejected_calls=0,failed_calls=0
cmdstat_hget:calls=88123411,usec=112009231,usec_per_call=1.27,rejected_calls=0,failed_calls=0
cmdstat_hgetall:calls=48211,usec=39823310977,usec_per_call=826043.51,rejected_calls=0,failed_calls=0
cmdstat_smembers:calls=9021,usec=1204993211,usec_per_call=133572.09,rejected_calls=0,failed_calls=0

看 usec_per_call:GET 平均 1.2 微秒,HGETALL 平均 826 毫秒,差了 近 70 万倍。调用次数才 4 万多,总耗时(usec)却是 GET 的 36 倍。这一行数据足以说服任何人:问题不是“请求多”,而是“少数请求太慢”。

第 3 步:redis-cli --bigkeys / --memkeys——谁家的 value 这么胖

命令本身是 O(N),慢在 N 大。N 是谁?找大 key。redis-cli --bigkeys 内部用 SCAN 遍历,不会像 KEYS * 那样阻塞服务;还可以用 -i 0.1 每 100 次 SCAN 睡 0.1 秒来降低对线上的冲击。建议在从库上执行,新版本对 cluster 从节点也支持。

$ redis-cli -h 10.0.0.22 --bigkeys -i 0.1

# Scanning the entire keyspace to find biggest keys as well as
# average sizes per key type.  You can use -i 0.1 to sleep 0.1 sec
# per 100 SCAN commands (not usually needed).

[00.00%] Biggest string found so far '"session:8a3f..."' with 512 bytes
[03.11%] Biggest hash   found so far '"cart:promo:hot"' with 412007 fields
[17.52%] Biggest set    found so far '"user:tags:all"' with 903112 members
[41.90%] Biggest hash   found so far '"cart:promo:hot"' with 2018733 fields
...
-------- summary -------

Sampled 4823017 keys in the keyspace!
Total key length in bytes is 121803321 (avg len 25.25)

Biggest   hash found '"cart:promo:hot"' has 2018733 fields
Biggest    set found '"user:tags:all"' has 903112 members
Biggest string found '"cfg:rules:json"' has 3145728 bytes

0 lists with 0 items (00.00% of keys, avg size 0.00)
2811003 hashs with 6871390 fields (58.29% of keys, avg size 2.44)
1930811 strings with 812340111 bytes (40.03% of keys, avg size 420.71)
...

真凶现身:一个叫 cart:promo:hot 的 Hash,有 201 万个 field。它是几个月前某个“活动促销参与记录”功能建的:把所有参与用户都塞进同一个 Hash(field = 用户 ID,value = 参与信息),当时活动才几千人,谁能想到后来这个 key 会长成“胖子”。

注意 --bigkeys 衡量的是元素个数(字符串是字节数),不是占多少内存。一个 200 万个短 field 的 Hash 不一定比一个 3MB 的 String 更占内存,但对 O(N) 命令的伤害是元素个数决定的。想看内存视角,用 --memkeys:

$ redis-cli -h 10.0.0.22 --memkeys -i 0.1
...
Biggest   hash found '"cart:promo:hot"' has 187436412 bytes
Biggest    set found '"user:tags:all"' has 74510223 bytes
Biggest string found '"cfg:rules:json"' has 3145784 bytes

然后用 MEMORY USAGE 对可疑 key 精确复核,并用 HLEN/SCARD 看元素数(这两个都是 O(1),可以放心敲):

$ redis-cli -h 10.0.0.22 memory usage cart:promo:hot samples 0
(integer) 187436472
$ redis-cli -h 10.0.0.22 hlen cart:promo:hot
(integer) 2018733
$ redis-cli -h 10.0.0.22 type cart:promo:hot
hash
$ redis-cli -h 10.0.0.22 object encoding cart:promo:hot
"hashtable"

约 178 MB、201 万 field。MEMORY USAGE 对嵌套类型默认只抽样 5 个元素估算总大小,SAMPLES 0 表示全部采样,更准但对超大 key 本身也会花时间——所以在从库上敲,别在主库上对着最大的 key 玩。

第 4 步:LATENCY DOCTOR——让 Redis 自己“交代”

Redis 2.8.13 起提供延迟监控子系统。默认关闭,需要设置阈值(毫秒)才会记录:

$ redis-cli -h 10.0.0.21 config set latency-monitor-threshold 100
OK
# 等下一次卡顿后:
$ redis-cli -h 10.0.0.21 latency latest
1) 1) "command"
   2) (integer) 1730273251
   3) (integer) 1874
   4) (integer) 2130
$ redis-cli -h 10.0.0.21 latency doctor
Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave?

1. command: 5 latency spikes (average 1533ms, mean deviation 412ms, period 302.20 sec). Worst all time event 2130ms.

I have a few advices for you:

- Check your Slow Log to understand what are the commands you are running which are too slow to execute. Please check http://redis.io/commands/slowlog for more information.
- Deleting, expiring or evicting (because of maxmemory policy) large objects is a blocking operation. If you have very large objects that are often deleted, expired, or evicted, try to fragment those objects into multiple smaller objects.

三个信息互相印证:command 事件出现了 5 次超过阈值的延迟尖刺,平均 1533ms,周期约 302 秒——和 SLOWLOG 里 5 分钟的间隔吻合;doctor 给的建议也直指“慢命令 + 大对象”。(latency latest 的四列依次是:事件名、最近一次发生的时间戳、最近一次耗时 ms、历史最大耗时 ms。)

如果这里看到的是 fork、aof-write、expire-cycle 之类的事件,那就是另一个方向了:fork 是 RDB/AOF 重写时 fork 子进程造成的(内存越大越慢,还要关透明大页),expire-cycle 是大量 key 同一秒过期(上一篇写击穿时提过)。别一看到卡顿就认定是大 key,先让证据说话。

第 5 步:谁在调用它?

SLOWLOG 里带了客户端地址和名字,直接找到 order-service。翻代码,看到这么一段“聪明”的逻辑:

// 每次下单前,把活动参与记录整个拉回来,在内存里判断用户是否参与过
Map<String, String> all = stringRedisTemplate.opsForHash().entries("cart:promo:hot");
boolean joined = all.containsKey(String.valueOf(userId));

200 万个 field 一次性拉回来,只为判断“某个用户在不在里面”。Redis 里每个 field 有 O(1) 的存在性检查(HEXISTS),根本不需要 HGETALL。而另一个 SMEMBERS user:tags:all 是画像服务每 5 分钟同步一次全量标签,同样是“拿全部再本地过滤”。

这就解释了“网络流出尖刺”:一次 HGETALL 要序列化并发送 178MB 的回复,Redis 不但要遍历 201 万个元素,还要把这么大的回复写进输出缓冲区,客户端也要吃下这些数据(顺便还给 JVM 带来一次 Young GC 压力)。

四、根因:单线程 + O(N) + 大 key = 全场陪跑

Redis 主线程 GET HGET SET HGETALL cart:promo:hot(1.8 秒,O(N),N = 200 万) GET GET 其他业务的请求 GET 排队 HGET 排队 SET 排队 GET 排队 …排队… 这 1.8 秒内,所有客户端的命令都在排队 → 客户端 3 秒超时开始累计 为什么 O(N) 命令危险 1. 命令在主线程里串行执行,没有“时间片轮转”,执行多久别人就等多久 2. 大 key 还带来:巨大的回复缓冲、网络带宽尖刺、DEL/过期/淘汰时的同步释放内存

把机制讲透,有三层:

  1. 单线程串行:Redis 处理命令的主线程一次只执行一个命令。HGETALL、SMEMBERS、LRANGE 0 -1、KEYS *、SORT、SUNION 这类命令的复杂度是 O(N),N 越大执行越久,别人就得等。官方文档专门提醒:生产环境使用 KEYS 是最常见的延迟来源之一,应该改用 SCAN、SSCAN、HSCAN、ZSCAN 增量遍历。
  2. 大 key 放大 O(N):一个 field 少的 Hash 上 HGETALL 只要几十微秒,随着元素涨到百万级就变成秒级。大 key 不一定马上出问题,它是一颗“随业务增长而变大”的定时炸弹。
  3. 删除大 key 也会卡:DEL 一个 200 万元素的 Hash 需要同步释放所有元素的内存,同样会阻塞主线程好几百毫秒到数秒;过期、淘汰(maxmemory)时删除大 key 也一样——上面 LATENCY DOCTOR 的建议里就提到了这一点。UNLINK(Redis 4.0+)只在主线程里把 key 从键空间摘掉(O(1)),真正回收内存交给后台线程。

五、止血与修复

止血:先让抽风停下来

  1. 立刻停掉“罪魁调用”:让 order-service 下线那段 HGETALL 逻辑,或者通过配置中心把它降级为“跳过活动校验”;画像服务的全量同步任务先暂停;
  2. 不要在主库上直接 DEL 大 key!用 UNLINK,让内存释放在后台线程完成;
  3. 如果是 Redis 6+ 且需要“兜底”,可以通过 ACL 禁用危险命令,或者在 Redis 前面的代理层拦截 KEYS、FLUSHALL。
# 先看看有多大,再决定怎么删
$ redis-cli -h 10.0.0.21 hlen cart:promo:hot
(integer) 2018733

# 方案 A:整个 key 都不要了,异步删除(Redis 4.0+)
$ redis-cli -h 10.0.0.21 unlink cart:promo:hot
(integer) 1

# 方案 B:key 还要留,但想分批瘦身(避免一次性大删除)——用 HSCAN 分批删 field
$ redis-cli -h 10.0.0.21 hscan cart:promo:hot 0 count 500
1) "1048576"
2) 1) "u_100001"
   2) "{\"joined\":true}"
   ...

分批删 field 的 Java 示例(每批 500,批间小睡,避免占用主线程太久):

public void shrinkBigHash(String key) throws InterruptedException {
    ScanOptions opts = ScanOptions.scanOptions().count(500).build();
    try (Cursor<Map.Entry<Object, Object>> cursor = redis.opsForHash().scan(key, opts)) {
        List<Object> batch = new ArrayList<>(500);
        while (cursor.hasNext()) {
            batch.add(cursor.next().getKey());
            if (batch.size() >= 500) {
                redis.opsForHash().delete(key, batch.toArray());
                batch.clear();
                Thread.sleep(10);          // 让出主线程,别人还要用
            }
        }
        if (!batch.isEmpty()) redis.opsForHash().delete(key, batch.toArray());
    }
}

根治 1:把 O(N) 命令换成 O(1)/O(logN),或增量遍历

危险写法替代说明
KEYS patternSCAN cursor MATCH pattern COUNT 100增量、非阻塞,但可能返回重复 key,需要客户端去重
HGETALL bigHGET / HMGET / HEXISTS / HSCAN要判断“在不在”就用 HEXISTS,要全量遍历用 HSCAN 分批
SMEMBERS bigSISMEMBER / SSCAN判断成员关系是 O(1)
LRANGE big 0 -1LRANGE big 0 99 分页大 list 永远别全取
DEL bigUNLINK bigRedis 4.0+,后台线程回收内存;也可配 lazyfree-lazy-user-del yes 让 DEL 变异步
# 用 SCAN 替代 KEYS 的命令行写法
$ redis-cli -h 10.0.0.22 --scan --pattern 'cart:promo:*' -i 0.01 | head
# 用 HEXISTS 判断用户是否参与(O(1))
$ redis-cli -h 10.0.0.21 hexists cart:promo:hot u_100001
(integer) 1

上面代码里那段“拉回全部再 containsKey”,改成一行:

boolean joined = Boolean.TRUE.equals(stringRedisTemplate.opsForHash().hasKey("cart:promo:hot", String.valueOf(userId)));

根治 2:拆 key——把一个大 key 变成一群小 key

200 万 field 的 Hash,按用户 ID 做分桶(sharding),变成 1024 个小 Hash,每个约 2000 个 field:

// 分桶键:cart:promo:{bucket},bucket = hash(userId) % 1024
private String bucketKey(long userId) {
    int bucket = (int) (Math.abs(Long.hashCode(userId)) % 1024);
    return "cart:promo:" + bucket;
}
redis.opsForHash().put(bucketKey(userId), String.valueOf(userId), json);
redis.opsForHash().hasKey(bucketKey(userId), String.valueOf(userId));

拆分后每次操作只落在一个小 Hash 上,HGETALL 即便误用也只是 2000 个元素(微秒级)。拆分时要注意两点:第一,迁移过程用双写 + 灰度,别一刀切;第二,Redis Cluster 下不同分桶会落到不同槽位/节点,这是好事(数据分散),但需要跨桶的 Lua/事务会受限。

另外几个“常见胖子”的拆法:

  • 大 List(如消息流水):按日期/序号分段,如 msg:{uid}:{yyyyMMdd},或者干脆换成 Stream 并限长(XADD ... MAXLEN ~ 10000);
  • 大 Set(如用户标签全集):反过来存,从“标签 → 所有用户”改成“用户 → 自己的标签”,查询按用户走;
  • 大 String(如几 MB 的 JSON 配置):压缩后存、或按模块拆成多个 key、或改成本地缓存 + 版本号轮询;
  • 给大 key 设 TTL,避免无限增长——但要记得“过期删除大 key 也会阻塞”,所以最终还是要拆。

根治 3:把大 key 发现变成常规巡检

# 每周在从库上跑一次,输出存档;-i 0.1 降低压力
$ redis-cli -h 10.0.0.22 --bigkeys -i 0.1 > /data/redis-audit/bigkeys-$(date +%F).txt

# 同时打开延迟监控和慢日志,并调小慢日志阈值(单位微秒,这里 5ms)
$ redis-cli -h 10.0.0.21 config set slowlog-log-slower-than 5000
$ redis-cli -h 10.0.0.21 config set slowlog-max-len 1000
$ redis-cli -h 10.0.0.21 config set latency-monitor-threshold 50

# 让 DEL/过期/淘汰默认走后台线程回收(Redis 4.0+ 的 lazy free)
$ redis-cli -h 10.0.0.21 config set lazyfree-lazy-user-del yes
$ redis-cli -h 10.0.0.21 config set lazyfree-lazy-expire yes
$ redis-cli -h 10.0.0.21 config set lazyfree-lazy-eviction yes

客户端统一 CLIENT SETNAME(Lettuce/Jedis 配置里都有 clientName),这样 SLOWLOG 里直接看到“是谁干的”,不用去翻 IP 对应哪台机器。

六、验证

$ redis-cli -h 10.0.0.21 --latency-history -i 15
min: 0, max: 1, avg: 0.17 (1350 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.18 (1348 samples) -- 15.00 seconds range
min: 0, max: 2, avg: 0.18 (1349 samples) -- 15.00 seconds range

$ redis-cli -h 10.0.0.21 slowlog get 3
(empty array)

连续观察一个小时,业务侧再没有出现“集体超时”,网络流出尖刺也消失了,SLOWLOG 是空的。

七、复盘

做法为什么
Redis 必须开启慢日志,阈值调到几毫秒,最大长度别用默认 128单线程下“慢”就是“全局慢”,慢命令是第一嫌疑
客户端配置 CLIENT SETNAMESLOWLOG 第 6 个字段直接指向责任服务
生产禁用 KEYS,统一用 SCAN/HSCAN/SSCAN/ZSCAN增量遍历不会长时间占住主线程
禁止 HGETALL / SMEMBERS / LRANGE 0 -1 用在会增长的集合上元素数会随业务增长,今天几百明天几百万
删除大 key 用 UNLINK,并开启 lazyfree 系列配置释放内存交后台线程,主线程只做 O(1) 摘链
设计阶段控制单 key 体积(经验值:String 几十 KB、集合元素数万级以内)大 key 一旦形成,拆分成本远高于设计时多想一步
定期在从库跑 --bigkeys / --memkeys,接入巡检告警提前发现“会长胖的 key”,而不是等它出事
监控 usec_per_call、instantaneous_ops_per_sec 凹陷、网络出流量尖刺这三条曲线组合基本就是“O(N) 命令阻塞”的指纹

一句话备忘:Redis 偶发整体卡顿 → latency-history 确认停摆 → SLOWLOG GET 找命令 → --bigkeys / --memkeys / MEMORY USAGE 找 key → UNLINK 删、SCAN 遍历、拆 key 降体积。

后来那个 Hash 拆完,我在代码 review 里给自己立了条规矩:看到 HGETALL 就问一句“它会长到多大”。同事说我像个只会问“您有预约吗”的前台。没办法,Redis 是单线程,任何一个人插队,队伍里的所有人都得陪着站。

参考资料

— 感谢读到这里 —发现错误,或想补充?告诉我 →
TURN KNOWLEDGE INTO SOMETHING REAL

有想法,也想把它做出来?

从技术方案到上线交付,聊聊你的下一个项目。

聊聊需求

一起聊聊

搜索文章

输入关键词,按标题和摘要即时筛选。

浏览分类文章归档

阅读设置

字号
行宽
专注模式

专注模式会隐藏页头与侧栏,只留正文。设置保存在当前浏览器。

稍后阅读

保存在当前浏览器,留给下一次安静阅读。

总浏览 -- 次 · 总访客 -- 人 · 今日浏览 -- 次 · 今日访客 -- 人