一次访问Redis延时高问题排查与总结

一次访问Redis延时高问题排查与总结 https://mp.weixin.qq.com/s/f3dQIC4DBhWibyXQKBXrzg

实战总结｜一次访问Redis延时高问题排查与总结（续） https://mp.weixin.qq.com/s/trbGNYZPEfzaAMz6kZ_YKg

一次访问Redis延时高问题排查与总结

原创寒亭阿里云开发者 2023-06-21 09:02 发表于浙江

阿里妹导读

作者抽丝剥茧的记录了一次访问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=100spring.redis.jedis.pool.max-idle=16
spring.redis.jedis.pool.time-between-eviction-runs-millis=30000
spring.redis.jedis.pool.min-idle=0spring.redis.jedis.pool.test-while-idle=truespring.redis.jedis.pool.num-tests-per-eviction-run=-1spring.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规格支持的3wspring.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延时高问题排查与总结（续）

原创寒亭阿里云开发者 2023-09-15 08:31 发表于浙江

阿里妹导读

本文是一次访问Redis延时高问题排查与总结的续篇，主要讲述了当时没有发现的一些问题和解决方案。

背景

在今年4月份，笔者写的一次访问Redis延时高问题排查与总结中，通过配置参数实现了一个稳态的连接池，解决了问题(至少在当时这么认为的)。

但近期压测分析发现，仍然有部分请求卡在了从JedisPool中获取连接上。从而导致整体请求处理超时。

如下，每天22:00会固定压测, 从而导致一波超时错误：(理论上按照服务器容量预估, 不应该超时)

JedisPool详细信息如下，获取连接最大等待耗时仍然在900ms以上：

难道之前的方案不对么？此时感觉又回到了原点。

问题1: 为啥还是会获取Jedis连接超时?

根据一次访问Redis延时高问题排查与总结文中介绍, 可以通过设置如下参数，来保持一个稳定的Pool(即只在failover场景下会重建Pool内对象)：

spring.redis.jedis.pool.max-active=500 // 线上稳定保有4台, 4*500=2000, 仍然远小于Redis规格支持的3wspring.redis.jedis.pool.max-idle=500spring.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大于某个阈值从而把连接给删除掉. 这样可以防止无意义的大规模连接重建.

根据当时的并发量300~500，理论上不应该有等待获取Jedis连接。但为啥还是会有如此之高的连接获取等待耗时?再仔细看了下属性值，发现了异常：

为啥 createdCount, destroyedCount 的量仍然较大? 大概率超时还是由于连接反复重建导致。

这里勘误一次访问Redis延时高问题排查与总结文中最终查看池内对象新建&销毁量, 需要看 createdCount 而不是 createCount 值. 当时有点儿得意忘形导致看错。

再去拉取线上其他机器上看了下，如下 create/borrow 比例将近70%。说明该问题并非偶然。按照之前文章参数，并不能实现稳态的连接池！里边的对象(连接)仍然是被反复销毁&重建的！

// 小流量地域borrowedCount: 670756createdCount: 468204destroyedCount: 467704destroyedByEvictorCount: 467704
// 大流量地域borrowedCount: 10308566createdCount: 3973975destroyedCount: 3973475destroyedByEvictorCount:  3973475

问题2: 为啥Jedis连接还是会反复销毁&重建连接?

仔细看如下参数值, destroyedCount与destroyedByEvictorCount的值相同, 也就是说这次全都是因为 Evictor 导致. 与上篇文章中解决的因为池子里Idle连接的数量导致销毁的原因是完全不同的. 那我们接下来分析下Evictor的逻辑:

destroyedCount: 467704destroyedByEvictorCount: 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**如下：

导致连接只要超过60秒空闲, 就会把这个连接给释放掉。

另外由于JedisPool默认是LIFO模式, 更是加剧了该问题. 在空闲时, 处于队尾的一堆Connection处于反复的 Create---> Idle>minIdle(60s) --> Destroy --> Create 循环中。

Borrow时, 始终从队首获取连接；
Return时, 根据是否是LIFO, 来判定是放在队首还是队尾：

如下 LIFO默认为true

但为啥如下关键参数未生效呢? 而是使用了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的作用:

Evictor机制

重新回顾下Evictor的流程:

总结下来, 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机制才使得连接池内可以将故障的连接删除&重建的:

结论: 不可行! Evictor不能删除，否则应用就失去了断线重连的机制。延长时间越久，断线的检测与重连也就延时越久。

引申: 一个有意思的讨论点

这里如果仔细思考，会引出一个非常有意思的讨论点：为啥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 这种高级的方式来扩展实现这些参数的注入。

因此最终我们采用了方案4, 详细代码实现可以参见issue:Provide more configuration properties for Jedis's connection pool · Issue #33814 · spring-projects/spring-boot[3]

效果验证

JedisConnection维持稳态, 不再重复销毁&创建

select * from org.springframework.data.redis.connection.jedis.JedisConnectionFactory

如下, 这次是真的维持了稳态:

压测导致的超时现象消失

如下, 每天22:00固定压测引发的超时已经完全消失。

连接获取等待时间回归正常

如下，连接等待时间也已经从之前的900ms+降低到了几十毫秒:

至此, 我们终于搞懂了这些原理, 也彻底解决了问题。

总结

总结1: 在SpringBoot下, 如何来创建一个固定的JedisPool?

即我们希望连接池里的连接创建之后就不要再被销毁, 只在真正RedisServer故障时进行连接重建。

步骤1: 配置SpringBoot支持的核心Pool参数

spring.redis.jedis.pool.max-active=500 // 线上稳定保有4台, 4*500=2000, 仍然远小于Redis规格支持的3wspring.redis.jedis.pool.max-idle=500spring.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

posted @ 2023-09-19 09:57 papering 阅读(201) 评论(0) 编辑收藏举报

会员力量，点亮园子希望

刷新页面返回顶部