TimeUnit引发的血案:RedisTemplate踩坑实践

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

一. 背景

每年的618，双十一是电商的狂欢购物节。我们在618来临之际，各项保障任务也在有条不紊的进行。压测就是校验我们系统能力以及提前暴露风险的重要方式之一。

而在最近的全链路压测过程中，商品详情页面RT居高不下，从而引起整体系统load较高，系统整体性能指标存在风险，这个问题必须解决！

二. 服务信息

spring-data-redis版本：1.8.4.RELEASE

三. 分析过程

1. 问题分析

商品详情 页面RT较高，通过一些trace发现是操作redis较为耗时。然后我们通过监控平台查看，发现有一个redis集群的异常报警，起初是在业务没有开启Redis服务分流读的情况下，该集群slave节点存在大量连接，占用大量CPU资源，且导致redis主从断掉等异常行为。

DBA分析后发现，从数据库实时监控平台，可以看到有大量的cluster命令产生，且这个请求一直存在，只是压测流量过大，导致问题放大，单个cluster命令请求都是在30毫秒以上。压力表现都是打到某一个NODE节点上，导致这个节点cpu飙升。然后DBA开始相应的处理，包括但不限于单独隔离异常节点到独立机器上，配置参数优化等，问题没有根本解决。可以确定不是Redis服务端问题，应该是业务代码端问题，需要从业务用法开始排查使用方式，看是如何触发了大量的cluster命令。6月9号性能测试组同学进行 商品详情 单独压测，缩小范围进行定位，问题同样存在，产生了大量cluster命令。开始我们的排查之路。

2. 监控观察

既然是cluster命令异常过多，我们观察下监控数据。

对于 商品详情 的单压如下：

可以看到cluster命令确实过多，且耗时较长。从而影响其他正常get，set操作。

我们仔细观察，发现异常的请求不仅仅是cluster，还是psetex。正常来讲，我们操作缓存并不会直接使用psetex命令。单独观察下两者。下面两张图分别是 psetex命令与cluster命令的走势图，发现是一致的。推测psetex和cluster是有强关联关系的。pset如下

cluster如下

且cluster命令只打到xx.xxx.xx.xxx:16379这一台机器上。

3. 代码分析

从上面观察得到，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命令来更新拓扑信息。这里就证明了cluster命令与psetex命令之间存在的关联性了。缓存过期时间是100ms，必然引起频繁的发起cluster nodes命令。通过和DBA确认，确实在压测过程中存在的大量cluster命令，就是cluster nodes命令。验证了猜想。

四. 解决方法与验证

1. 解决方法

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

，带来的频繁cluster nodes命令。

2. 验证

改完上线后，观察监控。发现在上线过程中，明显有下降的趋势。

在平峰期表现，已经降到非常低了

最终的压测验证：

从压测结果来看，表现也是非常良好。问题得以解决。

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

五. 总结与思考

1. 总结

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

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

2. 思考

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

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

后续优化措施：

• 1. 梳理出一个版本的最佳实践，然后规范框架的使用版本。比如spring-data-redis1.x版本就统一使用1.8.4，然后有对应的最佳实践；2.x版本就统一使用2.2.4，也有对应的最佳实践。这样子可以避免踩重复的坑，能站在巨人的肩膀上看的更远。

• 2. 建立规范的CodeReview机制。通过多人的代码review以及不同人的经验，可能发现一些隐藏的坑。避免上线后出现问题。

六. 番外

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

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

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

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

在网上资料查到，这个bug已经官方修复了。https://jira.spring.io/browse/DATAREDIS-890在2.1.3版本发布了。

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

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

答案在下图，CLUSTER_SLOTS常量等于16384，因此redis每次都要循环很多次去组装每个节点的slot信息。CPU至少需要循环16384乘以N次，N为redis集群master的个数。因此，随着redis集群规模的扩大、以及客户端节点数的增加，NODES命令打满CPU的问题会越来越严重。redis系统命令NODES的性能问题，在2018年已经有反馈给redis官方：https://github.com/antirez/redis/issues/5574

3. PSETEX命令的使用场景？

https://redis.io/commands/psetex  查看了redis官方对于PSETEX命令的说明

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

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

所以我个人理解，psetex应该是用在对于过期时间的精度要求较高的场景吧。

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

张伟帆， 2018年毕业后加入网易。 曾参与严选商城，严选Opera发布平台的开发。 目前主要负责严选用户会员体系的 相关建设，以及建模优化，性能提升等工作，致力于为用户提供优质的用户会员服务。

本文由作者授权严选技术团队发布