一次访问Redis延时高问题排查与总结
一次访问Redis延时高问题排查与总结 https://mp.weixin.qq.com/s/f3dQIC4DBhWibyXQKBXrzg
实战总结|一次访问Redis延时高问题排查与总结(续) https://mp.weixin.qq.com/s/trbGNYZPEfzaAMz6kZ_YKg
一次访问Redis延时高问题排查与总结
阿里妹导读
作者抽丝剥茧的记录了一次访问Redis延时高问题的排查和总结。
背景
20230308 在某地域进行了线上压测, 发现接口RT频繁超时, 性能下降严重, P50 400ms+, P90 1200ms+, P99 2000ms+。细致排查发现其中重要的原因是, 访问缓存rt竟然飙到了1.2s左右。作为高性能爱好者, 榨干CPU的每一分价值是我们的宗旨, 是可忍孰不可忍, 怎么能光空转, 不干活呢? 那就仔细分析下问题。为啥Redis访问延时如此高?
我们简化下Redis访问流程如下:
可能性1: 服务端问题?
- 我们Redis使用的是 redis_amber_master_4xlarge_multithread 16C32G+480G SSD 规格, 最大QPS参考值24w, 最大连接数3w, 配置还是非常豪华的。
- 如下, QPS以及Load在峰值请求阶段, 都仍然处于低位。
可能性2: 物理网络问题?
如下, 请求远远没有达到机器带宽, 不是瓶颈. 另外单独看了网卡重传率等指标, 也都正常。可能性3: 客户端问题?
那么很大概率就是客户端自身问题了. 我们把客户端详细放大如下:JVM FGC STW?
根据当时ARMS监控结果如下, 虽然YGC次数与耗时有所上升, 但没有发生FGC:JedisPool问题?
把内存Dump出来, 分析JedisConnectionFactory几个相关重要指标, 发现问题有如下2个:- maxBorrowWaitTimeMills过大: 即最大等待时间过久。在等待从连接池中获取连接, 最大等待了1200ms。很大概率是因为block在连接池获取, 导致请求处理缓慢。
- Redis连接创建销毁次数过多: createdCount 11555次; destroyedCount: 11553次。说明max-idle参数设置不合理(on return的时候检查idle是否大于maxIdle, 如果大于则直接销毁该连接)。每个对象的创建就是一次TCP连接的创建, 开销较大。导致脉冲式请求过来时引发频繁创建/销毁, 也会影响整体性能。
顺便说一句: maxBorrowWaitTimeMills, createdCount, destroyedCount 几个metrics信息是JedisPool对象持久维护的全局变量信息, 只要JVM不重启, 这个信息就会一直存在。这也就是为啥不需要在压测峰值时获取内存dump, 而是事后dump也可以。
此外, 如果细致探索JedisPool参数工作机制, 就需要了解apache的ObjectPool2的机制。刚好笔者在之前研究过ObjectPool, 后续会出单独文章阐述&对比ObjectPool, ObjectPool2, JedisPool以及经常踩坑的DruidPool的实现原理与差异。
本文就不再赘述, 敬请期待~
至此, 定位问题是JedisPool行为异常导致。
如何解决问题?
线上JedisPool实际参数
部分参数是由 redis.clients.jedis.JedisPoolConfig 继承而来
spring.redis.jedis.pool.max-active=100
spring.redis.jedis.pool.max-idle=16
spring.redis.jedis.pool.time-between-eviction-runs-millis=30000
spring.redis.jedis.pool.min-idle=0
spring.redis.jedis.pool.test-while-idle=true
spring.redis.jedis.pool.num-tests-per-eviction-run=-1
spring.redis.jedis.pool.min-evictable-idle-time-millis=60000
参数行为解析
- max-active: 连接池的最大数量为100, 包括 idle + active. 注意, 这里spring.redis.jedis.pool.max-active被映射为了ObjectPool的maxTotal参数上。
- 连接池的最大空闲数量为16, 即如果return时, idleObject>=16, 则该对象直接被销毁。
- 启动后台线程, 每30s执行一次, 定时心跳保活与检测。
- 连接池最小空闲的连接数量为0. 即corePoolSize为0, 不会长期maintain一个固定的容量。
脉冲式请求引发的问题
我们把问题简化为如下序列, 即可发现问题所在. 在T2~T3内, 84个对象创建, 84个对象销毁. 造成了极大的损耗。期望的行为模式
由于线上环境, Redis服务器配置较高, 为了能充分压榨性能, 同时应对容器场景下典型的突发峰值, 因此如下行为:- 连接池的最大数量=连接池的最小数量=连接池的稳定数量. 即不要临时去创建连接, 防止等待过久。
- 需要定时心跳保活与检测, 及时删除掉超时/无效的连接。
- 不要因为idle时间过久而重建连接(只因为连接失效而重建)。防止无意义的大规模连接重建。
spring.redis.jedis.pool.max-active=500 // 线上稳定保有4台, 4*500=2000, 仍然远小于Redis规格支持的3w
spring.redis.jedis.pool.max-idle=500
spring.redis.jedis.pool.time-between-eviction-runs-millis=30000 // 定时心跳保活与检测
spring.redis.jedis.pool.min-idle=500 // 连接池的稳定数量
spring.redis.jedis.pool.test-while-idle=true //定时心跳保活与检测
spring.redis.jedis.pool.num-tests-per-eviction-run=-1 // 每次保活检测, 都需要把500个连接都检测一遍. 如果设置为-2, 则每次检测1/2比例的的连接.
spring.redis.jedis.pool.min-evictable-idle-time-millis=-1 // 不要因为idleTime大于某个阈值从而把连接给删除掉. 这样可以防止无意义的大规模连接重建。
效果验证
终于在20230413重新迎来了一波压测, 流量模型与上次相同。结果如下:-
maxBorrowWaitTimeMills 下降比例接近 80%
-
createdCount 也从之前的 11555次 下降到了 500次(即池子初始化的size)
- 业务侧整体性能也大幅提升, P50与P90均下降了将近60%, P99更是夸张地下降了70%。简直是amazing, 完结撒花!~
实战总结|一次访问Redis延时高问题排查与总结(续)
阿里妹导读
本文是一次访问Redis延时高问题排查与总结的续篇,主要讲述了当时没有发现的一些问题和解决方案。
背景
在今年4月份,笔者写的 一次访问Redis延时高问题排查与总结 中,通过配置参数实现了一个稳态的连接池,解决了问题(至少在当时这么认为的)。
但近期压测分析发现,仍然有部分请求卡在了从JedisPool中获取连接上。从而导致整体请求处理超时。
- 如下,每天22:00会固定压测, 从而导致一波超时错误:(理论上按照服务器容量预估, 不应该超时)
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139712-1968051023.png)
-
JedisPool详细信息如下,获取连接最大等待耗时仍然在900ms以上:
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139987-2121700499.png)
问题1: 为啥还是会获取Jedis连接超时?
根据 一次访问Redis延时高问题排查与总结 文中介绍, 可以通过设置如下参数,来保持一个稳定的Pool(即只在failover场景下会重建Pool内对象):
根据当时的并发量300~500,理论上不应该有等待获取Jedis连接。但为啥还是会有如此之高的连接获取等待耗时?再仔细看了下属性值,发现了异常:spring.redis.jedis.pool.max-active=500 // 线上稳定保有4台, 4*500=2000, 仍然远小于Redis规格支持的3w
spring.redis.jedis.pool.max-idle=500
spring.redis.jedis.pool.min-idle=500 // 连接池的稳定数量
spring.redis.jedis.pool.test-while-idle=true //定时心跳保活与检测
spring.redis.jedis.pool.time-between-eviction-runs-millis=30000 // 定时心跳保活与检测
spring.redis.jedis.pool.num-tests-per-eviction-run=-1 // 每次保活检测, 都需要把500个连接都检测一遍. 如果设置为-2, 则每次检测1/2比例的的连接.
spring.redis.jedis.pool.min-evictable-idle-time-millis=-1 // 不要因为idleTime大于某个阈值从而把连接给删除掉. 这样可以防止无意义的大规模连接重建.
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139914-885982199.png)
为啥 createdCount, destroyedCount 的量仍然较大? 大概率超时还是由于连接反复重建导致。
这里勘误 一次访问Redis延时高问题排查与总结 文中最终查看池内对象新建&销毁量, 需要看 createdCount 而不是 createCount 值. 当时有点儿得意忘形导致看错。
再去拉取线上其他机器上看了下,如下 create/borrow 比例将近70%。说明该问题并非偶然。按照之前文章参数,并不能实现 稳态的连接池!里边的对象(连接)仍然是被反复销毁&重建的!
// 小流量地域
borrowedCount: 670756
createdCount: 468204
destroyedCount: 467704
destroyedByEvictorCount: 467704
// 大流量地域
borrowedCount: 10308566
createdCount: 3973975
destroyedCount: 3973475
destroyedByEvictorCount: 3973475
问题2: 为啥Jedis连接还是会反复销毁&重建连接?
仔细看如下参数值, destroyedCount与destroyedByEvictorCount的值相同, 也就是说这次全都是因为 Evictor 导致. 与上篇文章中解决的因为 池子里Idle连接的数量 导致销毁的原因是完全不同的. 那我们接下来分析下Evictor的逻辑:
destroyedCount: 467704
destroyedByEvictorCount: 467704
Evictor逻辑分析
核心代码: org.apache.commons.pool2.impl.GenericObjectPool#evict
流程解析如下:
如上图所示, 可能有2点导致连接被回收:
- Idle时间超过阈值
-
Redis心跳探活失败
我们分别去分析:
可能性1: 是否是Idle超时导致?
我们来看下如何判定Idle是否超过阈值, 根据配置文件参数分析, evict()判定必然返回false, 因此必然不会因为连接Idle超时导致. 而这个参数也是Jedis官方背书的。
可能性2: 是否Redis心跳探活失败导致?
尝试在本机Ping了下RedisServer, 发现延时等都正常. 理论上只有RedisServer挂了或者主备切换或者网络故障等才会导致探活失败。
此时排查进入了死胡同。
实际分析
由于destroy量很大,因此推测线上evict一直在发生。此时只能通过终极武器Arthas来分析。果然抓到了一些线索:
-
发现idleEvictTime并非我们预期的**Long.MAX_VALUE**, 而是**60000ms**如下:
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139751-390733469.png)
- 导致连接只要超过60秒空闲, 就会把这个连接给释放掉。
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139972-53893479.png)
- 另外由于JedisPool默认是LIFO模式, 更是加剧了该问题. 在空闲时, 处于队尾的一堆Connection处于反复的 Create---> Idle>minIdle(60s) --> Destroy --> Create 循环中。
- Borrow时, 始终从 队首 获取连接;
- Return时, 根据是否是LIFO, 来判定是放在队首还是队尾:
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139947-1499295692.png)
- 如下 LIFO默认为true
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139732-591241615.png)
- 但为啥如下关键参数未生效呢? 而是使用了JedisClient的默认值(即60s)呢?
spring.redis.jedis.pool.min-evictable-idle-time-millis=-1 // 不要因为idleTime大于某个阈值从而把连接给删除掉. 这样可以防止无意义的大规模连接重建.
问题3: 为啥JedisPool参数注入失败?
我们来分析下SpringBoot为JedisPool参数注入的流程:
入口:
org.springframework.boot.autoconfigure.data.redis.JedisConnectionConfiguration#jedisPoolConfig
- 核心逻辑如下: 其中 RedisProperties.Pool 即为配置文件中配置反序列化出来的对象. 如下, 发现根本没有从 RedisProperties.Pool 对象中获取MinEvictableIdleTimeMillis参数, 因此也就没有赋值给真正的配置 JedisPoolConfig 中:
private JedisPoolConfig jedisPoolConfig(RedisProperties.Pool pool) {
JedisPoolConfig config = new JedisPoolConfig();
config.setMaxTotal(pool.getMaxActive());
config.setMaxIdle(pool.getMaxIdle());
config.setMinIdle(pool.getMinIdle());
if (pool.getTimeBetweenEvictionRuns() != null) {
config.setTimeBetweenEvictionRunsMillis(pool.getTimeBetweenEvictionRuns().toMillis());
}
if (pool.getMaxWait() != null) {
config.setMaxWaitMillis(pool.getMaxWait().toMillis());
}
return config;
}
- 再来查看 org.springframework.boot.autoconfigure.data.redis.RedisProperties.Pool 的属性清单如下, 发现也根本没有MinEvictableIdleTimeMillis这个字段。 也就是说properties文件反序列化成为RedisProperties.Pool对象的时候, 就会忽略掉 min-evictable-idle-time-millis这项配置!
private int maxIdle = 8;
private int minIdle = 0;
private int maxActive = 8;
private Duration maxWait = Duration.ofMillis(-1);
private Duration timeBetweenEvictionRuns;
-
其余的参数都被SpringBoot使用了如下默认值, 我们可以看到把**MinEvictableIdleTimeMillis**参数强制设置为了60s:
这里很有意思的一点, JedisPoolConfig 专门写了一行注释, 希望使用这个Default配置, 能让大家的生活更愉快一些。
然而但当看到这里, 我内心是抓狂的. 这个可恶的MinEvictableIdleTimeMillis参数, 使用SpringBoot还无法通过配置文件修改, 一点都不愉快!
public JedisPoolConfig() {
// defaults to make your life with connection pool easier :)
setTestWhileIdle(true);
setMinEvictableIdleTimeMillis(60000); // 这里设置了默认值60s!
setTimeBetweenEvictionRunsMillis(30000);
setNumTestsPerEvictionRun(-1);
}
至此问题已经明确: SpringBoot官方(version 2.5.6)对于JedisPool的配置Properties文件, 根本不支持**min-evictable-idle-time-millis**这个参数!!
如何解决该问题?
方案1: 升级spring-boot-autoconfig版本? --> 不可行
首先想到的是升级spring-boot-autoconfig版本, 说不定更高版本中, 他们良心发现, 把 MinEvictableIdleTimeMillis 参数加入到 RedisProperties.Pool 属性里了呢?当前应用依赖的是2.5.6, 但悲剧的是即使是最新的3.1.2, 也没有将该参数加上去, 参见[1]
方案2: 修改LIFO为FIFO? --> 不可行
我们发现JedisPool实际可以通过设置setLifo(false)来将pool切换到FIFO模式:
org.apache.commons.pool2.impl.BaseObjectPoolConfig#setLifo这样, 在1min有500次Cache访问的情况下, 每个Connection都会active至少一次, 也就持续保活了。按照我们线上平均请求来说, 达成这个目标轻而易举。但实现起来, 同样存在如 min-evictable-idle-time-millis一样的问题, 虽然JedisPool原生支持该参数, 但通过SpringBoot透出来的AutoConfig里, 不支持配置该参数。
方案3: 延长Evictor的运行间隔(甚至停止Evictor)? --> 不可行
因为SpringBootAutoConfig天然支持 evictor参数: spring.redis.jedis.pool.time-between-eviction-runs-millis
-
当前配置是30s, 如果配置为60s,在稳定流量情况下,因为Idle而导致释放的Connection量会减少一半。
- 如果配置为-1,则代表禁用Evictor机制,也就不会因为Idle时间导致空闲连接被删除/重建。
Evictor机制
- 重新回顾下Evictor的流程:
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139675-1506700970.jpg)
- 总结下来, Evictor除了对于连接的Idle检测外, 还担任了 连接探活与重建这个重要的任务!!!
- 查看了Jedis相关源码, 发现Jedis对于池内的连接探活/重建, 只会发生在如下2种情况下:
-
场景1: testOnBorrow, testOnReturn 等时间点, 会与Redis服务端进行一次Ping/Pong的心跳校验. 但如果开启, 则在每次从池子里borrow的时候都执行一次Ping/Pong校验, 但会极大地影响性能. 因此默认都是关闭的.
- 场景2: 定时的Evictor: 即上述所讲的Evictor流程啦.
- 而我们线上为了性能考虑, follow默认的convention, 即 testOnBorrow, testOnReturn, testOnCreate都为false. 如果再把Evictor禁用, 会导致在Redis/网络故障时, 无法执行连接重建. 因此该方案不可行.
Evictor实际作用
如下, 这是近期发生的Redis主备切换故障, 如下应用日志, 都是基于Jedis的定时validate&evict机制才使得连接池内可以将故障的连接删除&重建的:
引申: 一个有意思的讨论点
这里如果仔细思考,会引出一个非常有意思的讨论点:为啥JedisPool不在拿到连接, 应用执行语句抛出Connection异常的时候, 自动进行重连呢? 这样的实现就类似于一个乐观锁:-
克服了testOnBorrow, testOnReturn (类似与悲观锁) 等性能损耗。
- 克服了定时Evictor如果运行间隔时间过久, 导致的连接探活/重建不及时的问题。
简直是两全其美! 官方也针对这个进行了说明,参见[2]
总结下来就是, 如果为了实现上述方案,Jedis需要在内部维护一个Command队列,便于在Jedis对于连接重建之后将这些失败/未执行的Command重新执行,否则会导致应用已经提交的Command根本不执行,而应用也压根感知不到Command没有执行! 这个风险显然是不可接受的。所以Jedis会直接把这个链接异常抛出给外层应用,由应用感知并进行自定义的failover操作。
方案4: 扩展JedisConnectionConfiguration支持其他参数? --> 最终方案
SpringBoot对于JedisPool相关参数优化&配置的资料非常少, 经过千辛万苦的搜索, 终于很欣喜地看到, 在今年1月份, 有人也提出了这个问题, 如下:Provide more configuration properties for Jedis's connection pool · Issue #33814 · spring-projects/spring-boot[3]希望SpringBoot官方能够在配置文件里支持这些JedisPool/CommonsObjectPool2原生的参数。我们得到如下信息:
-
虽然暂时官方仍在讨论是否添加这些Properties支持。
- 但实际上我们可以使用 JedisClientConfigurationBuilderCustomizer 这种高级的方式来扩展实现这些参数的注入。
效果验证
JedisConnection维持稳态, 不再重复销毁&创建
select * from org.springframework.data.redis.connection.jedis.JedisConnectionFactory如下, 这次是真的维持了稳态:
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140140135-398175919.png)
压测导致的超时现象消失
如下, 每天22:00固定压测引发的超时已经完全消失。
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139738-1708374965.png)
连接获取等待时间回归正常
如下,连接等待时间也已经从之前的900ms+降低到了几十毫秒:
![图片](https://img2023.cnblogs.com/blog/1006507/202309/1006507-20230919140139973-1472198266.png)
总结
总结1: 在SpringBoot下, 如何来创建一个固定的JedisPool?
即我们希望连接池里的连接创建之后就不要再被销毁, 只在真正RedisServer故障时进行连接重建。
- 步骤1: 配置SpringBoot支持的核心Pool参数
spring.redis.jedis.pool.max-active=500 // 线上稳定保有4台, 4*500=2000, 仍然远小于Redis规格支持的3w
spring.redis.jedis.pool.max-idle=500
spring.redis.jedis.pool.min-idle=500 // 连接池的稳定数量
spring.redis.jedis.pool.test-while-idle=true //定时心跳保活与检测
spring.redis.jedis.pool.time-between-eviction-runs-millis=30000 // 定时心跳保活与检测
spring.redis.jedis.pool.num-tests-per-eviction-run=-1 // 每次保活检测, 都需要把500个连接都检测一遍. 如果设置为-2, 则每次检测1/2比例的的连接. 但SpringBoot默认是不识别这个参数的!
spring.redis.jedis.pool.min-evictable-idle-time-millis=-1 // 不要因为idleTime大于某个阈值从而把连接给删除掉. 这样可以防止无意义的大规模连接重建. 但SpringBoot默认是不识别这个参数的!
-
步骤2: 实现自己的 JedisClientConfigurationBuilderCustomizer , 从而识别min-evictable-idle-time-millis参数, 详细参见: Provide more configuration properties for Jedis's connection pool · Issue #33814 · spring-projects/spring-boot[3]
- 拓展: 其他如下SpringBoot未官方支持的重要参数, 都可以通过相同的Customizer机制扩展&注入:
spring.redis.jedis.pool.num-tests-per-eviction-run=-2 # 每次evict执行的量/比例
spring.redis.jedis.pool.lifo=false # 将LIFO模式修改为FIFO模式
总结2:很惭愧,在第一篇文章中有如下问题
-
查看总体Connection的创建&销毁量, 应该查看CreatedCount, 而不是CreateCount.
- 没有仔细去分析SpringBoot对于JedisPool参数的注入流程, 导致想当然地按照convention配置了一个当前根本就不支持的配置! 导致问题只解决了一半.
-
重新研究了下JedisPool/CommonsPool2对于failover的机制与原理。这样在配置各个参数&调优时,才能做到心中有数。
- 重新研究了下SpringBoot对于JedisConnectionConfiguration以及其他属性文件注入的流程。这样在其他参数注入时可以按图索骥, 防止再次踩坑。
[1]https://github.com/spring-projects/spring-boot/blob/main/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/data/redis/RedisProperties.java
[2]https://github.com/redis/jedis/issues/83
[3]https://github.com/spring-projects/spring-boot/issues/33814