服务项目背景:
一个二手房楼盘字典的服务,有三台服务,查询量大,用了redis缓存,用的缓存框架 jetcache,注解缓存
dubbo线程池配置 500个线程 dubbo.provider.threads=500
异常现象与初步分析
以为是底层服务,Cat疯狂告警,整个dashboard告警。dubbo 远程调用全部超时,查看poi.esf.fdd项目日志,只有一台机器dubbohandler线程一直处于爆满状态,其他两台偶有50-100ms的慢SQL
Cat上GC没有任何异常 初步认为是慢SQL导致,但是慢SQL也不是慢的离谱的
快速解决恢复
-
保护现场
dump 当前线程状况 jstack > xxxx.txt
dump 当前内存 jmap -dump:live,format=b,file=xxx.hprof pid
如果系统没有内存执行jmap,强制执行 jmap -dump:live,format=b,file=xxx.hprof -F pid -
恢复服务,因为没有服务器发布权限,kill -9 12 杀进程
分析日志
- grep -c ‘DubboServerHandler’ xxx.txt =====> 500
grep -A 1 ‘DubboServerHandler’ xxx.txt =====> 所有的线程都是 waiting (parking),也就是被挂起的线程 - 接着看日志,发现堆栈信息中有redis相关的代码
翻看源码,发现所有的waiting(parking)线程是在从redis连接池中获取,因为池中无可用的连接,所以等待队列AQS将线程parking住了
- 怀疑是线程获取到了redis连接,因为数据比较大,socket一直连接数据等待。
jetcache的jedis pool配置:
jetcache.remote.default.timeout=3000
jetcache.remote.default.poolConfig.minIdle=5
jetcache.remote.default.poolConfig.maxIdle=30
jetcache.remote.default.poolConfig.maxTotal=500
分析: 最大都有500个数据连接,也不至于500个连接全都不行,而且也设置了超时时间,这种情况也排除了(没有线上运维redis的权限,无法查看redis是否有慢查询)
4、换个思路
会不会是redis 连接池中的连接泄漏了,因为redis连接的回收都是框架回收的,有异常也是会catch回收的,看看了jetcache携带的jedis版本是2.9.0,github上对于这个问题已经在2.10.2版本进行了修复,就是连接泄漏了,没有回收给redispool,导致后面的线程都拿不到getresource (此时日志中应该也有 can not get redisresoure,设置的timeout稍微长了点,dubbo日志疯狂打,也没看到)
5、分析内存
6、源码分析
jeidis 2.9
JedisSentinelPool.getResource()
jedis.close()
分析:
In the case of concurrency
Thread A return an object but not run to “this.dataSource = null” yet
Thread B borrow an object and set dataSource to this;
And Then Thread A run this.dataSource = null;
Finally Thread A will never returnResource because dataSource is null
简化版本: 线程A先将连接还给了连接池,最后对象置为null,如果在 A线程归还给线程池时,B线程瞬间获取到此连接,随后线程A将此连接置为null,就永远不会被回收给线程池
官方解读:
官方修订版
升级方案
<dependencies>
<dependency>
<groupId>redis.clients</groupId>
<artifactId>jedis</artifactId>
<version>2.10.2</version>
</dependency>
</dependencies>