一次Redis慢请求到排行榜bug定位的分析过程

2,084 阅读7分钟

前言

        怎么也没想到排行榜的这个文章居然还要连载,直到这周在观察线上Redis性能问题之后,不断深挖发现了一行bug代码导致一名用户(榜单第一名)的数据问题,觉得整个分析过程还是需要记录一下。

周榜方案细节回顾

        之前有过一个排行榜文章,基于zset与bloom filter的排行榜与点赞方案设计,里面大量使用到Redis中间件,其中周榜的功能完全由Redis Zset数据结构来实现,功能上从测试或者线上运行情况来看是完全支持的,没有出现问题,大概效果图如下,左边为该用户基本信息,右边为榜单数据。 排行榜效果图1.png         榜单的实现逻辑在上一篇文章中有写到,不再赘述。而用户基本信息这一块,有个较为特殊的需求,多个星星数相同的并列用户视为一名,即如果榜单第一个用户和第二个用户都是100颗星,那么他们就都显示为第一名,且第三个用户是第二名。这样的话Redis Zset Api是无法满足需求的,Zset的排行不会做重复处理,因此需要我们自行做判断,我这里主要用到两个api来实现。

1.获取对应id用户倒排(reverse)在set中排名,排名为游标,从第0位开始
int reverseRank(zset,name)

2.获取对应游标start、stop之间的全部对象数据,如获取第一名到第五名reverseRangeWithScores(zset, 0, 4)
List<Object> reverseRangeWithScores(zset, start, stop)

        依据上述两个api,我这边的逻辑如下,根据两个api结合计算出当前用户去重的排名来实现: 获取rank排名流程图.png

慢请求定位问题

问题洞察

        这次使用Redis Zset,会将我们全部活跃的用户id存入,由于是用户维度因此空间复杂度较高,使用Redis 占用内存预估对内存使用做了一下预估,大概为100-200m左右,这是一个典型的Redis大key,Redis大key问题是线上经常遇到的严重问题之一,因此格外上心,几乎每天都会看阿里云Redis监控。

        果不出其然,在监控中看到了一些慢请求,如下所示:

时间耗时(ms)查询语句
2021年1月21日 15:01:4133.78ZREVRANGE zset 0 -1 withscores
2021年1月21日 15:00:2633.11ZREVRANGE zset 0 -1 withscores
2021年1月21日 14:34:0032.35ZREVRANGE zset 0 -1 withscores
2021年1月21日 14:25:5033.12ZREVRANGE zset 0 -1 withscores
2021年1月21日 14:18:4533.59ZREVRANGE zset 0 -1 withscores
        可以看到这些慢请求基本都在30ms左右,熟悉Redis的各位应该很清楚,它是一个完全基于内存的单线程运行模型的数据库,基本命令处理时间都在微秒(us)级别,一个命令如果超过5ms就会对其他在队列中的请求造成较大的影响,那么就可以断定为慢请求。由于我们的在阿里云的Redis产品为集群cluster,所以首先想到的是否为集群对应key的crc16哈希分片策略的问题导致某些分片hot key数量较多,对应分片负载高导致的这同一个命令的高延迟,于是找到对应分片查看高延迟时对应的实例性能如下图:在高延迟时实例性能没有受到任何影响。
分片对应响应时间.png
分片对应性能参数.png

问题定位

        那么分片实例计算及内存都不是瓶颈,问题肯定出现在了命令中。如果了解Redis Zset数据结构底层原理就知道它是使用跳表来实现的,对于范围查找,首先通过二分法找到对应node,然后再向前或向后遍历获取n条数据,因此它的操作时间复杂度是在log(M)+N,M为数据总量,N为范围查询元素个数。根据我们元素总量及业务计算,时间复杂度是N,不应该有这么高的延迟。

跳表数据结构.png

        视线又回到这行命令上 “ZREVRANGE zset 0 -1 withscores”,发现ZREVRANGE后的两个参数分别为0,-1。查了查文档,第二个参数游标如果为-1,那么视为返回整个Zset中全部的数据,因此执行的是全量的扫描,时间复杂度瞬间上升了N个量级导致了慢请求。

zreverse1参数.png         为何会有-1的参数呢,于是开始codeReview和日志定位,发现问题出现在我们最开始流程中的 reverseRangeWithScores(zset, 0, rank-1),如果请求中rank为0(周榜zset中的第一名),那么第二个游标就变成了-1扫描整个Zset,并且在后续计算的排名也不准确,无法计算出第一的逻辑。因此发现了生产环境bug,并且使用第一名用户的数据请求后复现问题,最终紧急上线对第一名排名计算单独处理的逻辑代码解决问题。

总结

        这次算是典型的通过对生产环境中间件监控,接着分析定位问题,最终解决问题的一次经历。回过头来看,真是全身冷汗,我们的这个集群Redis是多个服务共用的,而这次的是属于大key问题。Redis对外服务的单线程模式,导致如果生产环境出现大key便会拖慢其他服务全部的请求,稍有不慎造成整个链路的雪崩也是有很大可能的。         这次之所以能够早些洞察到问题,是因为在业务需求方案的评审初期就已经对风险做了预估,榜单需求需要多注意Redis的问题,才能够在问题扩大之前及时解决。因此我们对于这个缓存中间件的使用还是需要有敬畏之心,大概总结如下:

  1. 长期观察Redis缓存内存使用情况,如果直线上升需要检查是否有未过期的key,定期清理,内存慢后会造成暂停服务的问题;
  2. 观察日志是否有hot key,如果有hot key可以考虑根据服务实例进行拆key或进行降级处理为服务实例本地缓存(参考guava cache、caffine),hot key会对集群模式Redis中相应分片产生巨大压力;
  3. 观察慢请求统计日志,如果有少量高峰期不同命令的慢请求,大概率为集群性能瓶颈,可考虑升配扩容等方案;如果有大量相同命令慢请求,则需要快速定位慢请求来源,是否为业务需求方案问题,考虑降级或者问题修复;造成Redis忽然变慢的原因还有很多,需要具体问题具体分析。

参考

Redis zrangebyscore

Redis 占用内存预估