记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

时间:2024-04-09 07:00:43

问题出现:

运维小伙伴反馈系统某应用出现cpu爆了,同时报Mysql、Redis异常,如下图所示:

记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

 记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

问题排查:

遇到问题,马上去看日志,报错如下:

DUBBO Thread pool is EXHAUSTED 

Could not get JDBC Connection

 记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

意思是dubbo线程满了。但是啥原因造成线程满的呢?继续排查,因为我们不知道是在哪里报的错。这时候我们需要通过JVM去排查问题了。

step 1:

top 命令观察 JAVA进程cpu。由于没有及时截图,所以,没有截图了,只能字面描述下。当时这个应用的cpu约为120%左右。接下来 top -H -p (应用线程ID),发现里面的进程都是呈现稳定的部分是 2.0% ,1.7% ,0.7% 等,并没有说哪个进程特别高。

step 2:

jstack -l (应用线程ID) > (应用线程ID).txt 

打开日志一看。没有发现死锁的异常报错,但是发现大量的 BLOCKED ,如图:

记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

同时看到是Redis的报错,然后可以初步锁定问题点集中在Redis,先从它入手。接下来再调用dubbo-jstack日志,如图所示:

记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

大家可以看到,当前 12 、13的进程都在等待 304 这个进程。那么304这个进程做了什么?这是又去看下代码。

 记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

 大家可以看到这里用到Redis缓存,那么究竟发生什么事导致它影响了别的进程在等待呢?是什么报错,都是在等待它呢?我继续往前看dubbo-jstack日志,发现除了304,还有别的在等待,如下图的 18、19 在等待 257。

记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

那么 257 、304发生了什么?这是我想起了最初的报错。 

 redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool 

这时候,我焕然大悟,我接着去看配置,如图:

记一次JVM调优排查 DUBBO Thread pool is EXHAUSTED!

Redis链接超时时间为3秒。豁然开朗。 

总结问题原因:

综上所示,首先是系统发生了并发的请求,读取Redis 最大连接数是500。这时连接请求数大于500,因此出现了有个进程如257拿不到Redis资源,他会等待三秒,由于Redis是单线程原理,那么别的进程执行到这一步,就会被锁住,等待257执行,这时候 257  三秒超时了。报错: redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool  。三秒内,就会有很多进程在等待了。Redis一有资源就会被其他进程去获取,刚好到304,Redis pool 又满了,因此又出现上述的情况。在等待的进程是Dubbo 进程,由于它们在等待,所以得不到资源释放,因此出现了 DUBBO Thread pool is EXHAUSTED。 由于Redis拿不到资源,那么程序就会去读数据库,又不释放数据库资源,导致Could not get JDBC Connection。所以,这一系列连锁反应的Dubbo pool ,JDBC的问题,都是源于并发下,Redis 连接池的资源不够。

解决办法:

1、调大Redis 连接池的大小。(但是不建议这么做,一般Redis连接池都是够用) 

2、调整业务逻辑。(排查到这里,已经给到相应的负责人去定位了。譬如:封装200条数据作为一次请求Dubbo,从请求Dubbo200次降到一次去实现)