1%概率出现GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1 #5492

Bughue · 2023-11-20T06:29:13Z

用的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分钟只有十次左右），如果连接不够用应该会一直在创建才对？
看到shrink connections by recording living connection #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)

xiaomagor · 2023-11-23T02:31:37Z

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

zrlw · 2023-11-27T14:57:00Z

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

Bughue · 2023-11-28T02:31:51Z

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

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

xiaomagor · 2023-11-28T03:21:22Z

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

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

zrlw · 2023-11-28T10:27:45Z

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

Bughue · 2023-11-28T11:50:13Z

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

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

zrlw · 2023-11-28T22:48:26Z

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秒也没完成创建。

Bughue · 2023-12-05T11:47:22Z

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是不是有问题呢？

zrlw · 2023-12-05T15:55:48Z

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

Bughue · 2023-12-06T10:39:37Z

我看了一下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();
        }

zrlw · 2023-12-06T13:01:02Z

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

Bughue · 2023-12-12T06:11:27Z

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

Cat.newTransaction就是new一个对象而已，目前看来没什么开销的。“druid之前的连接池管理的确有一些缺陷”能具体说说吗

zrlw · 2023-12-12T09:16:27Z

并发线程数多了会出现锁竞争，获取连接和返还连接都会变慢，受当前设计框架所限，druid适合的场景是每个客户端只有20个以下的并发数据库连接需求（maxActive < 20)，像你这种60个线程的，本身就不适合采用druid。
另外当前master分支的版本做了很多优化，尽量在现有框架体系下提高连接池响应速度，如果你的maxActive能调到20之内，或许可以试试最新的master分支。

a97659096 · 2023-12-22T07:42:12Z

我也遇到了同样的问题，不知道为什么重启服务后就好了，也是偶发性

Bughue · 2023-12-22T07:45:01Z

我也遇到了同样的问题，不知道为什么重启服务后就好了，也是偶发性

你是什么版本？也是active=0吗？

a97659096 · 2023-12-22T07:54:39Z

我也遇到了同样的问题，不知道为什么重启服务后就好了，也是偶发性

你是什么版本？也是active=0吗？
不太确定是否跟我连多个数据源有关系，默认连接的数据源没出现过问题，其他三个数据源会偶发性的出现这个错误，重启服务就又可以获取到连接了，druid版本是1.2.6

Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 40, creating 1, createElapseMillis 1633095
at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1749)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1419)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5059)
at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:689)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5055)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1397)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1389)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:100)
at com.baomidou.dynamic.datasource.ds.ItemDataSource.getConnection(ItemDataSource.java:56)
at com.baomidou.dynamic.datasource.ds.AbstractRoutingDataSource.getConnection(AbstractRoutingDataSource.java:48)
at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:159)
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:117)
at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80)
... 110 common frames omitted

Bughue · 2023-12-22T07:56:27Z

我也遇到了同样的问题，不知道为什么重启服务后就好了，也是偶发性

你是什么版本？也是active=0吗？
不太确定是否跟我连多个数据源有关系，默认连接的数据源没出现过问题，其他三个数据源会偶发性的出现这个错误，重启服务就又可以获取到连接了，druid版本是1.2.6

Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 40, creating 1, createElapseMillis 1633095 at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1749) at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1419) at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5059) at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:689) at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5055) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1397) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1389) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:100) at com.baomidou.dynamic.datasource.ds.ItemDataSource.getConnection(ItemDataSource.java:56) at com.baomidou.dynamic.datasource.ds.AbstractRoutingDataSource.getConnection(AbstractRoutingDataSource.java:48) at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:159) at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:117) at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) ... 110 common frames omitted

amazing 简直一样。而且这个active=0应该是不准确的，因为我能检测到不停的有连接创建和回收，而且testwhileIdle的日志也有

13462249457 · 2024-04-20T09:44:37Z

GetConnectionTimeoutException 这个问题解决了吗？我也遇到了同样的问题，错误信息如下：
Cause: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 200, creating 1, createElapseMillis 7209773

Bughue · 2024-04-22T01:28:11Z

GetConnectionTimeoutException 这个问题解决了吗？我也遇到了同样的问题，错误信息如下： Cause: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 200, creating 1, createElapseMillis 7209773

没解决呢，最近好像发生概率比较低，你也是偶发的吗，什么版本？

georgecao · 2024-07-19T12:56:26Z

记录一个类似的情况，应用启动的时候获取不到连接，MySQL服务端连接数查过远没有到上限。不过通过设置initialSize=1貌似能缓解一下。

Druid version: 1.2.22

12:03:22  Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 13, active 0, maxActive 20, creating 1, createElapseMillis 114
12:03:22  
12:03:22  	at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1896)
12:03:22  
12:03:22  	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1498)
12:03:22  
12:03:22  	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5074)
12:03:22  
12:03:22  	at com.alibaba.druid.filter.FilterAdapter.dataSource_getConnection(FilterAdapter.java:2759)
12:03:22  
12:03:22  	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5070)
12:03:22  
12:03:22  	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1473)
12:03:22  
12:03:22  	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1463)
12:03:22  
12:03:22  	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:83)
12:03:22  
12:03:22  	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:160)
12:03:22  
12:03:22  	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:118)
12:03:22  
12:03:22  	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:81)
12:03:22  
12:03:22  	... 34 common frames omitted

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

1%概率出现GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1 #5492

1%概率出现GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1 #5492

Bughue commented Nov 20, 2023 •

edited

Loading

xiaomagor commented Nov 23, 2023

zrlw commented Nov 27, 2023

Bughue commented Nov 28, 2023

xiaomagor commented Nov 28, 2023 •

edited

Loading

zrlw commented Nov 28, 2023

Bughue commented Nov 28, 2023

zrlw commented Nov 28, 2023 •

edited

Loading

Bughue commented Dec 5, 2023 •

edited

Loading

zrlw commented Dec 5, 2023

Bughue commented Dec 6, 2023

zrlw commented Dec 6, 2023

Bughue commented Dec 12, 2023

zrlw commented Dec 12, 2023

a97659096 commented Dec 22, 2023

Bughue commented Dec 22, 2023

a97659096 commented Dec 22, 2023

Bughue commented Dec 22, 2023

13462249457 commented Apr 20, 2024

Bughue commented Apr 22, 2024

georgecao commented Jul 19, 2024 •

edited

Loading

1%概率出现GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1 #5492

1%概率出现GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1 #5492

Comments

Bughue commented Nov 20, 2023 • edited Loading

Cause: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 0, maxActive 60, creating 1, createElapseMillis 7051063

xiaomagor commented Nov 23, 2023

zrlw commented Nov 27, 2023

Bughue commented Nov 28, 2023

xiaomagor commented Nov 28, 2023 • edited Loading

zrlw commented Nov 28, 2023

Bughue commented Nov 28, 2023

zrlw commented Nov 28, 2023 • edited Loading

Bughue commented Dec 5, 2023 • edited Loading

zrlw commented Dec 5, 2023

Bughue commented Dec 6, 2023

zrlw commented Dec 6, 2023

Bughue commented Dec 12, 2023

zrlw commented Dec 12, 2023

a97659096 commented Dec 22, 2023

Bughue commented Dec 22, 2023

a97659096 commented Dec 22, 2023

Bughue commented Dec 22, 2023

13462249457 commented Apr 20, 2024

Bughue commented Apr 22, 2024

georgecao commented Jul 19, 2024 • edited Loading

Bughue commented Nov 20, 2023 •

edited

Loading

xiaomagor commented Nov 28, 2023 •

edited

Loading

zrlw commented Nov 28, 2023 •

edited

Loading

Bughue commented Dec 5, 2023 •

edited

Loading

georgecao commented Jul 19, 2024 •

edited

Loading