用 SLOWLOG 定位 Redis 慢命令与典型元凶
接口偶发变慢,怀疑是 Redis 拖后腿,单独压测 PING 又是亚毫秒——这种"间歇性卡顿"多半是某条慢命令在主线程里排队。Redis 单线程执行命令,一条执行 2 秒的命令会让所有并发请求多等 2 秒。SLOWLOG 是 Redis 自带的慢查询日志,会把超过阈值的命令连同参数、耗时、来源客户端一起记下来,是性能排查的第一入口。本文以 Redis 7 为准,讲清记录机制、查看方式与生产环境最常见的元凶清单。
一、SLOWLOG 的记录机制
理解三个要点,就能正确解读结果。第一,一条命令只有在执行完之后才可能进慢日志,排队等待的时间不计入,所以 slowlog 记录的是"这条命令本身有多慢",而不是"客户端感觉有多慢"。第二,阈值配置 slowlog-log-slower-than 的单位是微秒,Redis 7 默认 10000,即 10 毫秒;设为 0 会记录所有命令,设为 -1 则完全关闭。第三,慢日志是内存里的定长队列,slowlog-max-len 默认 128 条,超出后最老的被挤出,实例重启即清空,不会落盘。
因为只统计纯执行耗时,slowlog 看不到网络 RTT 和客户端序列化开销;但反过来,只要 slowlog 里出现长耗时命令,它就一定在主线程里阻塞了这么久,所有并发请求都得排队。另外,Redis 7 的 SLOWLOG GET 支持可选的 count 参数指定返回条数,不带参数时默认返回全部条目,SLOWLOG HELP 可以随时查看子命令列表。
"排队时间不计入"这一条值得再展开,因为它解释了最常见的误判。假设主线程被一条 2 秒的 KEYS 阻塞,在此期间到达的 500 条 GET 全部排队等待,每条 GET 的客户端观测耗时可能接近 2 秒。但 slowlog 里只有一条 2 秒的 KEYS 记录,GET 一条都不会进——每条 GET 自身执行只花了几微秒。所以排查时的正确推理是:客户端看到的慢,要找一个能在时间上覆盖它的慢命令,而不是期望每条慢请求都有自己的 slowlog 记录。
这也决定了排查的顺序:先看 slowlog 里最大的那条是什么、发生在几点几分,再去客户端监控里找同一时间段的延迟尖峰,两边对上才算定位成功。如果 slowlog 完全为空而客户端确实在报慢,那么瓶颈一定不在命令执行上,应该转向网络、连接池排队、客户端 GC 或者系统级阻塞(fork、AOF 刷盘)。
二、开启与查看
# 先把阈值调低到 1ms,宽进严出;排查完再收紧
CONFIG SET slowlog-log-slower-than 1000
CONFIG SET slowlog-max-len 256
SLOWLOG LEN # 当前条数
SLOWLOG GET 5 # 最近 5 条
SLOWLOG RESET # 清空重来
一条记录的完整形态:
127.0.0.1:6379> SLOWLOG GET 1
1) 1) (integer) 14 # 递增 ID
2) (integer) 1769300000 # 命令执行完的 UNIX 时间戳(秒)
3) (integer) 2485311 # 耗时,微秒,约 2.5 秒
4) 1) "KEYS" # 完整命令与所有参数
2) "user:*"
5) "10.0.0.8:51234" # 客户端 IP 与端口
6) "order-service" # 客户端名(CLIENT SETNAME 设置)
第 4、5、6 项是破案关键:参数告诉你它扫了什么,IP 和客户端名告诉你哪个服务在"作案"。给每个服务接入时统一执行 CLIENT SETNAME,排查时能省一半时间。
如果连 CLIENT SETNAME 也没做,还有一条补救途径:用 CLIENT LIST 把 IP 和端口反查回进程,再从进程反查服务名。
redis-cli CLIENT LIST | grep "10.0.0.8:51234"
# id=8421 addr=10.0.0.8:51234 laddr=10.0.1.11:6379 fd=31 name= age=3821 idle=0 flags=N db=0 sub=0 psub=0 ssub=0 multi=-1 watch=0 qbuf=26 qbuf-free=20448 argv-mem=10 multi-mem=0 tot-net-in=1821 tot-net-out=2653 rbs=1024 rbp=0 obl=0 oll=0 omem=0 tot-mem=5704 events=r cmd=client|list user=default redir=-1 resp=2
字段里几个值得记:name 为空说明没设客户端名;age 是连接存活秒数,可判断是长连接池还是短连接;idle 是空闲秒数,为 0 说明刚发过命令;cmd 是当前或最近执行的命令;omem 是输出缓冲区占用,数值异常大说明服务端有大量数据发不出去,可能是客户端读太慢。用户维度看 user=default,如果做了 ACL 分账号,这里能直接看出是哪个账号在操作。
三、典型元凶清单
生产环境进慢日志的命令高度集中,按出现频率排大致是这几类:
KEYS pattern:全键空间线性扫描,百万级 key 时轻松秒级。任何环境都不该出现,用SCAN游标遍历替代。- 大集合的全量读:
HGETALL、SMEMBERS、LRANGE 0 -1、ZRANGE 0 -1 WITHSCORES。集合本身是大 key 时,读全量就是 O(N)。改成HMGET取指定字段、LRANGE分页、SSCAN/HSCAN增量拉取。 - 集合运算:
SINTER、SUNION、SDIFF及*_STORE版本,ZUNIONSTORE、SORT。两个百万成员集合求交集就是百万次哈希查找。计算量大时下放到客户端,或用SCARD先估规模拒绝离谱请求。 - 大 key 删除:
DEL一个几百 MB 的 Hash,同步释放内存直接卡住主线程。改UNLINK异步释放,并开启lazyfree-lazy-expire yes、lazyfree-lazy-eviction yes。 SAVE与FLUSHALL:SAVE在主线程同步生成 RDB;FLUSHALL同步模式逐 key 释放。禁用SAVE改走BGSAVE,清库用FLUSHALL ASYNC。
注意:
BGSAVE的 fork、AOF 刷盘这类系统级阻塞不会以慢命令形式出现在 slowlog 里,它们要在 LATENCY 监控里看,详见下一篇。
还有两个计时口径的细节。其一,Lua 脚本在 slowlog 里记为一条 EVAL 或 EVALSHA,耗时是整个脚本的执行总时长:脚本内循环跑了一百条命令、总耗时 3 秒,就记一条 3 秒的 EVALSHA。其二,MULTI/EXEC 事务记为一条 EXEC,耗时是事务内全部命令之和。所以看到 EVALSHA、EXEC 进慢日志,要回溯脚本与事务体,而不是去找某条具体的命令。
四、从发现到治理
定位到元凶后,治理动作按优先级展开。先止血:把 KEYS 换成 SCAN、全量读改成增量读、DEL 换 UNLINK,这类改动成本极低。再做结构性调整:拆大 key(大 Hash 按业务分片成多个小 Hash)、把集合运算移出 Redis、给慢日志里高频出现的客户端限期整改。
配置改完记得固化:
CONFIG REWRITE # 把 CONFIG SET 的修改写回 redis.conf,否则重启回退
另外,slowlog 只能看"尖刺",看"均势"要用 INFO commandstats:它给出每个命令的累计调用次数与 usec_per_call(平均单次耗时)。slowlog 告诉你谁最坏,commandstats 告诉你谁总量最大,两者结合才能排出真正的优先级。
更重要的是把这件事变成例行巡检:定时任务每隔一分钟执行 SLOWLOG GET,按记录里的时间戳过滤出新增条目推送告警;每天汇总一次 usec_per_call 的变化趋势。慢命令治理不是一次性运动——没有常态化采集,改好的阈值会被下一个人手滑的一条 KEYS * 重新打穿。
常见坑 / 最佳实践
- 阈值不要照抄默认 10ms。 核心低延迟链路建议收到 1ms(
1000微秒),宁可多记一点,max-len 配 256~1024 也占不了多少内存。 - max-len 太小会丢现场。 慢日志是环形队列,流量大的实例 128 条几秒就冲掉,排查时要快照
SLOWLOG GET 128的输出再分析。 - 每条记录包含完整命令参数。 如果大量
SET大 value 进了慢日志,队列本身会吃内存,此时收紧阈值而不是无限调大 max-len。 - 客户端超时不等于 Redis 慢。 排队、网络重传、GC 都会造成"感觉慢",slowlog 为空时转向 LATENCY 监控和客户端侧指标。
CONFIG SET修改必须CONFIG REWRITE。 否则实例重启后阈值回退,慢日志"突然没了"往往就是这个原因。
小结
- SLOWLOG 只记录命令的纯执行耗时,阈值单位微秒,队列存内存、重启清空。
- 记录里的命令参数、客户端 IP、客户端名是定位元凶的三要素。
- 生产元凶高度集中:KEYS、大集合全量读、集合运算、大 key 删除、SAVE。
- 治理路径:增量替代全量、拆大 key、异步释放、禁用同步持久化命令。
- slowlog 看尖刺,
INFO commandstats看均值,两者配合排优先级。
- 点赞
- 收藏
- 关注作者
评论(0)