记druid 连接池没满,但超时问题
GetConnectionTimeoutException active 5, maxActive 100
问题说明
线上服务突然出现报错,通过日志查找发现是因为服务升级导致压力集中到某个节点上,出现连接获取超时导致的。
从日志中也找到了异常。
异常信息:
com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 6000, active 5, maxActive 100
----
但是从这个异常信息的描述来看,跟常规的线程池满又不一样,通过异常信息来看,线程池没满(active<maxActive),但是获取连接超时,有点无头脑。
正常的应该差不多是这样:
com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 6000, active 100, maxActive 100
-----
排查思路
怀疑1
线程池满超时,可以增加线程池大小。
但是现在线程池没满,缺又出现超时,首先排查数据库是否不正常。
经过排查,数据库没有限制连接数,其它服务、客户端也能正常使用。
排除数据库问题。
怀疑2
整个环境中也只有该服务因为使用量多而出现,并发量少了之后又恢复正常。
排除锁问题(就算出现锁,也应该把线程池占满)
因为是线上环境,无法简单去更换线程池等操作,一下就陷入到僵持。
druid github上类似问题也有很多人出现,早好几年前就有人提了该问题,但直到今天也没有解决答案。
定位
在一个个浏览github上相关问题时,突然发现某一个大神指出来,通过分析源码,该问题属于BUG,是一个提示性BUG。原因解释:
出现 GetConnectionTimeoutException 就是代表获取线程池超时,线程池满了。
为什么提示又说线程池没满呢( active 5, maxActive 100 )?
这是因为异常的日志打印没有放在同步块中,使用的变量没有考虑多线程。
简单说就是,在打印日志时,变量(active)的值已被修改,所以不是异常发生时的值。
代码大概如下: DruidDataSource - 1394
---
- if (holder == null) {
- long waitNanos = waitNanosLocal.get();
-
- StringBuilder buf = new StringBuilder();
- buf.append("wait millis ")//
- .append(waitNanos / (1000 * 1000))//
- .append(", active ").append(activeCount)//
- .append(", maxActive ").append(maxActive)//
- .append(", creating ").append(creatingCount.get())//
;
---
问题重现
1. 在查询时特意的将时间延长,造成连接池被占用
2. 在异常打印日志之前增加一点延迟(比如打个断点)
结论
本身就是因为服务中出现了一些比较复杂耗时的SQL,导致长时间占用了连接。
但是druid打印le 会产生歧义的异常,误导了问题分析的方向,增加了复杂度。
当前使用的druid版本是1.1.5,特意去瞄了一眼最新的代码(1.2.5),该代码还是没改。