【工作日记】记录一次dubbo线程池用尽导致的连锁异常，跟踪问题与着手解决...

问题出现

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

问题排查

遇到问题，马上去看日志，报错如下：

“

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 ，如图：

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

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

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

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

“

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

”

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

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 次降到一次去实现）

耶！下班啦！

【您的福利】

免费测试你口头说的技术单词，面试官是否能听懂？

免费测试你口头说的技术单词，面试官是否能听懂？

免费测试你口头说的技术单词，面试官是否能听懂？

---

作者：呆滞的程序员

链接：

http://blog.csdn.net/taipoucha5799/article/details/106574932