[alibaba/druid]1%概率出现GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1

2025-11-10 729 views
1
用的druid 1.2.3(有自己包装后写了个datasourceProxy,但目前分析的情况看来关系不大) 设置的maxActive=60,没有开removeabandon 使用的是mybatis和spring,没有自己去管理connection的关闭等

线上应用偶发会出现GetConnectionTimeoutException(全都是active=0),并且一出现就有点停不下来(有时候持续几分钟,有时候持续几个小时)出现这个问题都比较偶然,跟流量大小似乎关系不大。而且出现这个问题后在这段时间内的getconnection()有1%的概率会出现这个超时(这个比例貌似和分库有关,但还不确定),与其同时其他的getConnection情况正常。 另外我有实现FilterEventAdapter,发现connection_connect的时候是很快的(都在5ms左右)。

现在这几个问题非常费解

active=0证明现在应该没有其他线程在用,也就是busy=0,但从数据上看这个datasource获取连接并不是一定失败的。 持续出现这个情况很奇怪,尤其是看监控似乎池子也没用满 connect速度很快,应该不会阻塞这么久 connect的次数很平缓(1分钟只有十次左右),如果连接不够用应该会一直在创建才对? 看到https://github.com/alibaba/druid/pull/4726 这个问题了,不过我的是mysql,而且connect的时候也没有任何异常,所以不是一个问题? Cause: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1, createElapseMillis 7051063

; wait millis 5000, active 0, maxActive 60, creating 1, createElapseMillis 7051063; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1, createElapseMillis 7051063 at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:120) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)

com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1, createElapseMillis 7051063 at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1738) at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1408) at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5059) at com.xx.xx.xx.druid.filter.XxxDruidMonitorFilter.dataSource_getConnection(BcfDruidMonitorFilter.java:52)

回答

4

+1,同样的问题,也有datasourceProxy ,版本 1.2.5

7

通常是每台客户端的maxActive设置太大了,全部客户端加起来的active连接总数超过了数据库服务端配置的最大连接数,获取连接一直等到超时也没有等到可用的连接。

9

通常是每台客户端的maxActive设置太大了,全部客户端加起来的active连接总数超过了数据库服务端配置的最大连接数,获取连接一直等到超时也没有等到可用的连接。

服务端那边也问了,说是没有特别大的压力。而且客户端这边进行创建连接的时候是成功的,这个监控是有的

2

通常是每台客户端的maxActive设置太大了,全部客户端加起来的active连接总数超过了数据库服务端配置的最大连接数,获取连接一直等到超时也没有等到可用的连接。

在控制台看了MySQL的配置,目前最大消耗连接数4000左右,数据库支持最大连接50000个,肯定没超过数据库最大连接数。

1

不是数据库自己配多少就行的,操作系统的tcp配置参数是否能支持这么多,不是数据库自己就确定的,需要tcpdump抓包分析数据库连接tcp报文,不是简单执行以下top看看cpu和内存就能判定的事情。

9

不是数据库自己配多少就行的,操作系统的tcp配置参数是否能支持这么多,不是数据库自己就确定的,需要tcpdump抓包分析数据库连接tcp报文,不是简单执行以下top看看cpu和内存就能判定的事情。

我这边主要是监控druid建立连接的时候没有异常,而且都很快,所以应该不是你说这种情况? @Override public ConnectionProxy connection_connect(FilterChain chain, Properties info) throws SQLException {

8
GetConnectionTimeoutException wait millis 5000说明当前线程获取连接执行了pollLast方法尝试获取连接,但返回值为null没获取到连接,没有获取连接说明进入pollLast方法时的poolingCount为0,等到超时没有等到notEmpty信号时的poolingCount依然为0。 active=0说明当前activeCount=0没有正在执行sql的线程。 creating=1说明当前createCount=1只有一个线程正在执行createPhysicalConnection创建连接操作,createPhysicalConnection方法内部会调用creatingCountUpdater#incrementAndGet让createCount增1,如果有多个线程并行创建,这个值会叠加上去,而不是1,连接创建成功后,这个值才会被减下去。 createPhysicalConnection会执行filter。 你应该关注那个正在执行createPhysicalConnection创建连接操作的线程为什么没有在5ms内完成创建,等了5秒也没完成创建。
3
GetConnectionTimeoutException wait millis 5000说明当前线程获取连接执行了pollLast方法尝试获取连接,但返回值为null没获取到连接,没有获取连接说明进入pollLast方法时的poolingCount为0,等到超时没有等到notEmpty信号时的poolingCount依然为0。 active=0说明当前activeCount=0没有正在执行sql的线程。 creating=1说明当前createCount=1只有一个线程正在执行createPhysicalConnection创建连接操作,createPhysicalConnection方法内部会调用creatingCountUpdater#incrementAndGet让createCount增1,如果有多个线程并行创建,这个值会叠加上去,而不是1,连接创建成功后,这个值才会被减下去。 createPhysicalConnection会执行filter。 你应该关注那个正在执行createPhysicalConnection创建连接操作的线程为什么没有在5ms内完成创建,等了5秒也没完成创建。

请问一下之前说的“filter之后没有重置filterChain的pos,filterchain只执行一次,你的filter统计值大概率只用了一次”这个问题是存在的吗?因为connect监控到的数据确实少。但我看大佬你后面编辑了,所以是不是有这个问题呢?因为连接一直很快所以很困惑. 另外我发现有陈年issue说statFilter有内存泄漏问题的,在1.2.3是不是可能碰到,如果然后connect时候我的filter没执行导致我看不到异常?

对于你说的“你应该关注那个正在执行createPhysicalConnection创建连接操作的线程为什么没有在5ms内完成创建,等了5秒也没完成创建。”,如果监控没问题的话,那就是createPhysicalConnection一直很快成功,可是却无法拿来使用。(active=0)所有的线程都在等这个连接却等不到,感觉说不通?所以如果createPhysicalConnection的filter chain是不是有问题呢?

5

我看了一下druid 1.2.3代码,没有filterchain执行次数的问题,所以我改了回复内容。 建议你用arthas之类的工具抓一下你的filterchain,设置一下执行超时阈值,比如1s,查一下执行慢的环节。 从你的日志内容分析,那个负责创建连接的线程执行缓慢,如果创建连接没有问题,大概率就要查一下你的filter代码了。

8

我看了一下druid 1.2.3代码,没有filterchain执行次数的问题,所以我改了回复内容。 建议你用arthas之类的工具抓一下你的filterchain,设置一下执行超时阈值,比如1s,查一下执行慢的环节。 从你的日志内容分析,那个负责创建连接的线程执行缓慢,如果创建连接没有问题,大概率就要查一下你的filter代码了。

这个问题最近两个月只出了2次,目前在本地没有重现。创建连接的task看起来很少日志,我全局搜了日志也没看到创建失败的,所以是不是可以认为创建就是没问题的?我的filter代码可以贴出来:

@Override
    public ConnectionProxy connection_connect(FilterChain chain, Properties info) throws SQLException {
        Transaction transaction = Cat.newTransaction(DATABASE, "connect");
        try {
            ConnectionProxy connection = chain.connection_connect(info);
            transaction.setSuccess();
            return connection;
        } catch (Throwable ex) {
            transaction.setStatus(ex);
            throw ex;
        } finally {
            transaction.complete();
        }
    }

    @Override
    public DruidPooledConnection dataSource_getConnection(FilterChain chain, DruidDataSource dataSource, long maxWaitMillis) throws SQLException {
        Transaction transaction = Cat.newTransaction(DATABASE, "getConnection");
        try {
            DruidPooledConnection conn = chain.dataSource_connect(dataSource, maxWaitMillis);
            long id = getConnectionId(conn);
            transaction.addData("id", id);
            if (id == 0L) {
                transaction.setFail();
            } else {
                transaction.setSuccess();
            }
            return conn;
        } catch (Throwable ex) {
            transaction.setStatus(ex);
            throw ex;
        } finally {
            transaction.complete();
        }
5

建议在Cat.newTransaction和Cat.newTransaction方法调用前后获取一下当前时间戳,计算一下方法调用的耗时,耗时超过100ms写一条告警日志吧。 也可以考虑升级一下druid版本看看,druid之前的连接池管理的确有一些缺陷。 两个月只出现两次,说明问题偶发因素很大,如果还保存有同时段的数据库服务端日志,可以查一下数据库日志,也存在数据库服务因为自身部署环境出现资源瓶颈没有及时处理请求连接的可能性。