记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),该代码还是没改。

GitHub 加速计划 / druid / druid
27.83 K
8.56 K
下载
阿里云计算平台DataWorks(https://help.aliyun.com/document_detail/137663.html) 团队出品,为监控而生的数据库连接池
最近提交(Master分支:3 个月前 )
f060c270 - 6 天前
1613a765 * Improve gaussdb ddl parser * fix temp table 8 天前
Logo

旨在为数千万中国开发者提供一个无缝且高效的云端环境,以支持学习、使用和贡献开源项目。

更多推荐