RedisTemplate的踩坑现场

3,020 阅读8分钟

在这里插入图片描述

张伟帆(网易严选技术团队)

RedisTemplate是Spring封装的一个最常用的redis数据访问工具类,功能强大,使用简洁。但在RedisTemplate看似简单的API下,也是暗流涌动,背后别有一番洞天。本文从一个线上性能问题入手,抽丝剥茧一步步探索RedisTemplate,挖出了RedisTemplate操作psetex命令的深坑。



一、背景

在之前的压测过程中,商详页面RT居高不下,发现yx_malltech_user这个redis集群的异常报警,起初是在业务没有开启分流读的情况下,一个Redis集群slave节点存在大量连接,占用大量CPU资源,且导致redis主从断掉等异常行为。

dba分析后发现,从数据库实时监控平台,可以看到有大量的cluster命令产生,且这个请求一直存在,只是压测流量过大,导致问题放大,单个cluster命令请求都是在30毫秒以上。都是打到随机一个NODE节点上,导致这个节点cpu飙升。

然后DBA开始相应的处理,包括但不限于单独隔离异常节点到独立机器上,配置参数优化等,问题没有根本解决。可以确定不是Redis服务端问题,应该是业务代码端问题,需要从业务用法开始排查使用方式,看是如何触发了大量的cluster命令。

6.9单压商详发现问题还是存在。开始我们的排查之路。


二、服务信息

  • 涉及服务:yanxuan-app
  • 涉及场景:商详
  • spring版本:4.0.8
  • spring-data-redis版本:1.8.4.RELEASE
  • jedis版本:2.9.0

三、分析过程

1. 监控观察

既然是cluster命令异常过多,我们观察下监控数据。 6.9号下午对于商详的单压

在这里插入图片描述 可以看到cluster命令确实过多,且耗时较长。从而影响其他正常get,set操作。

我们仔细观察,发现异常的请求不仅仅是cluster,还是psetex。正常来讲,我们操作缓存并不会直接使用psetex命令。单独观察下两者。

下面两张图分别是 psetex命令与cluster命令的走势图,发现是一致的。基本可以确定psetex和cluster是有强关联关系的。

pset如下 在这里插入图片描述 cluster如下 在这里插入图片描述

且cluster只打到 10.130.68.239:16379 这一台机器上。 在这里插入图片描述

2. 代码分析

从上面观察得到,psetex命令和cluster命令基本同比例,且psetex命令请求量不少。而我们开发中,实际上并不会使用pset,我们都是redisTemplate.opsForValue().set()

这一点很奇怪,所以我们开始撸下代码。

在这里插入图片描述

这里面封装了缓存逻辑,底层就是redisTemplate.opsForValue().set()方法,那我们进去redisTemplate源码看下,它究竟偷偷做了啥。 在这里插入图片描述 在这个代码里面,我们就明白了psetex哪里来的。如果你timeout使用的时间单元是ms,就会使用psetex,而其他就使用setex命令。感觉我们往前走了一步。但是psetex和cluster命令同比例为啥呢?继续看下。 在这里插入图片描述 这里面会根据key去计算对应的槽所在节点。我们再进去topology方法里瞧瞧。 在这里插入图片描述 看到这段代码,真相就在眼前了。原来获取集群拓扑信息有一个缓存,失效时间100ms(这里吐槽下,spring居然把缓存过期时间写死了)。缓存失效,然后从cluster的clusternodes循环取节点去发送cluster nodes命令来更新拓扑信息。这里就证明了cluste命令与psetex命令之间存在的关联性了。缓存过期时间是100ms,必然引起频繁的发起cluster nodes命令。通过和dba大大峰哥确认,确实在压测过程中存在的大量cluster命令,就是cluster nodes命令。验证了猜想。

四. 解决方法与验证


1. 解决方法

解决方法很简单:将设置缓存中使用毫秒作为过期时间的代码全都改成按秒级别来设置缓存。

只要改成秒级别,也就是使用setex,setex不会触发cluster命令。避免使用psetex命令,带来的频繁cluster nodes命令。

2. 验证

改完上线后,观察监控。发现在上线过程中,明显有下降的趋势。 在这里插入图片描述 在平峰期表现,已经降到非常低了 在这里插入图片描述 最终的压测验证: 在这里插入图片描述 从压测结果来看,表现也是非常良好。问题得以解决。

核心链路压测中,整体商详的MRT也从之前100ms+降到66ms。


五. 总结与思考


1. 总结

这个问题比较有意思,罪魁祸首居然是一个时间单元。在于使用了 1000ms 和 1s 理论上应该是一样的,绝大部分人并不会去关心。然而spring底层留下了这么一个用法上的坑,导致了问题在大流量压测下的出现。一个小小的区别带来了巨大的影响。

而我们对于缓存的过期时间其实没必要精确到毫秒级别的,所以直接改成秒级别即可。

2. 思考

PSETEX和SETEX除了过期时间的精度问题,并没有本质的区别。

所以spring提供了根据时间单元来区别使用setex和psetex,而接口没有显示体现。我个人觉得这是spring接口设计一个不合理的地方。虽然是为了方便开发者要屏蔽细节,可是底层的逻辑并不是完全一样(不是只是发送不同命令而已)。而是有获取cluster nodes等命令逻辑,是两套逻辑。对于我们开发设计暴露出去的接口和方法也是一种警醒。一个接口,方法应该保证用户便于理解,不能有二义性。否则就得拆分多个接口,让用户选择,不给用户留坑。

后续优化措施:

  • 梳理出一个版本的最佳实践,然后规范框架的使用版本。比如spring-data-redis1.x版本就统一使用1.8.4,然后有对应的最佳实践;2.x版本就统一使用2.2.4,也有对应的最佳实践。这样子可以避免踩重复的坑,能站在巨人的肩膀上看的更远。
  • 建立规范的CodeReview机制。通过多人的代码review以及不同人的经验,可能发现一些隐藏的坑。避免上线后出现问题。

六. 番外


1. 为什么cluster命令会总是打到某一个节点上呢?

前面我们说到,还有一个问题点,cluster命令总是打到某一台节点上,导致这个节点cpu使用率飙升。

原因还是出在下面Spring-data-redis的这段代码上:

在这里插入图片描述 for循环遍历所有节点,从第一个开始发送nodes命令,如果得到返回,就直接返回了。而我们节点信息一般情况下都是不变的。因此entrySet的顺序也不会改变,Cluster Nodes命令就会一直发送到同一个节点上。

在网上资料查到,这个bug已经官方修复了。jira.spring.io/browse/DATA…

2. Cluster nodes命令为啥会很慢呢?

嗯,这个就是直接摘抄网上资料了。

答案在下图,CLUSTER_SLOTS常量等于16384,因此redis每次都要循环很多次去组装每个节点的slot信息。CPU至少需要循环16384乘以N次,N为redis集群master的个数。因此,随着redis集群规模的扩大、以及客户端节点数的增加,NODES命令打满CPU的问题会越来越严重。

redis系统命令NODES的性能问题,在2018年已经有反馈给redis官方:github.com/antirez/red… 在这里插入图片描述


3. PSETEX命令的使用场景?

redis.io/commands/ps…

PSETEX works exactly like SETEX with the sole difference that the expire time is specified in milliseconds instead of seconds.

PSETEX和SETEX除了过期时间的精度问题,并没有本质的区别。 所以我个人理解,psetex应该是用在对于过期时间的精度要求较高的场景吧。

此次问题的定位排查,感谢dba大大在服务端做了大量的优化,且提供了非常好的分析方向,才能很快且明确的从业务代码上进行排查。在业务代码的排查过程中,离不开文渊。十分感谢!!!


网易技术热爱者队伍持续招募队友中!网易严选,因为热爱所以选择, 期待志同道合的你加入我们, Java开发简历可发送至邮箱:lizhuo01@corp.netease.com