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

前言

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

周榜方案细节回顾

        之前有过一个排行榜文章，基于zset与bloom filter的排行榜与点赞方案设计，里面大量使用到Redis中间件，其中周榜的功能完全由Redis Zset数据结构来实现，功能上从测试或者线上运行情况来看是完全支持的，没有出现问题，大概效果图如下，左边为该用户基本信息，右边为榜单数据。

        榜单的实现逻辑在上一篇文章中有写到，不再赘述。而用户基本信息这一块，有个较为特殊的需求，多个星星数相同的并列用户视为一名，即如果榜单第一个用户和第二个用户都是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结合计算出当前用户去重的排名来实现：

慢请求定位问题

问题洞察

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

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

时间	耗时(ms)	查询语句
2021年1月21日 15:01:41	33.78	ZREVRANGE zset 0 -1 withscores
2021年1月21日 15:00:26	33.11	ZREVRANGE zset 0 -1 withscores
2021年1月21日 14:34:00	32.35	ZREVRANGE zset 0 -1 withscores
2021年1月21日 14:25:50	33.12	ZREVRANGE zset 0 -1 withscores
2021年1月21日 14:18:45	33.59	ZREVRANGE zset 0 -1 withscores

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

问题定位

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

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

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

总结

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

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

参考

Redis zrangebyscore

Redis 占用内存预估