一次访问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实际参数

参数行为解析

脉冲式请求引发的问题

我们把问题简化为如下序列, 即可发现问题所在. 在T2~T3内, 84个对象创建, 84个对象销毁. 造成了极大的损耗。

期望的行为模式

由于线上环境, Redis服务器配置较高, 为了能充分压榨性能, 同时应对容器场景下典型的突发峰值, 因此如下行为: 

连接池的最大数量=连接池的最小数量=连接池的稳定数量. 即不要临时去创建连接, 防止等待过久。

需要定时心跳保活与检测, 及时删除掉超时/无效的连接。

不要因为idle时间过久而重建连接(只因为连接失效而重建)。防止无意义的大规模连接重建。

效果验证

终于在20230413重新迎来了一波压测, 流量模型与上次相同。结果如下: 

maxBorrowWaitTimeMills 下降比例接近 80%

createdCount 也从之前的 11555次 下降到了 500次(即池子初始化的size)

业务侧整体性能也大幅提升, P50与P90均下降了将近60%, P99更是夸张地下降了70%。简直是amazing, 完结撒花!~