1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

...
Caused by: org.hibernate.exception.GenericJDBCException: Could not open connection
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:221)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:157)
    at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:550)
    at org.springframework.orm.hibernate4.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:426)
    ... 9 more
Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
    at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114)
    at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
    at org.hibernate.service.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:141)
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:292)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:214)
    ... 12 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
    at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1174)
    at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
    ... 16 more

有关JVM内存转储方式的说明见 JVM内存分析：Tomcat内存泄漏 。

在本案例应用（约定称为「应用A」）的使用过程中偶尔会在前端弹出 Timeout waiting for idle object 的异常提示框。经过查看完整的异常堆栈（看上面）可发现，异常发生在从连接池获取 Connection 时，在对 GenericObjectPool 源码分析后可初步确定是因为连接池已满而无法分配新的 Connection 造成的。

为进一步确认该问题，将应用A的内存转储（ sudo -u tomcat jmap -dump:format=b,file=heap-dump.bin <java_pid> ）并通过 Eclipse Memory Analyzer - MAT 对其内存进行分析。

点击工具栏中的 OQL 图标，这里需要通过 OQL 进行一些复杂的过滤查询（OQL： SELECT OBJECTS ds FROM org.apache.commons.dbcp.BasicDataSource ds ）：

从图中可以看到，连接池 org.apache.commons.pool.impl.GenericObjectPool 的 _numActive 为 749 ，而在应用中为其分配的最大活跃连接数（ maxActive ）为 750 。因此，可以进一步确定连接池的确已达到分配上限，在并发情况下将不会再分配更多连接，从而导致等待超时并抛出异常。

再看看内存中是否存在未被释放的MySQL连接。

由于MAT默认不分析 unreachable 对象，所以，在开始前需通过其自带的工具 ParseHeapDump.sh （或 ParseHeapDump.bat ） 分析不可达对象 ：

1
2

# 运行该命令前需删除dump文件所在目录中由MAT生成的分析文件
$ ParseHeapDump.sh -keep_unreachable_objects heap-dump.bin

点击MAT的菜单 File -> Open Heap Dump 选择文件 heap-dump.bin 载入转储分析文件，然后，通过OQL（ SELECT cn, cn.isClosed, cn.io.mysqlConnection, cn.io.mysqlConnection.closed FROM INSTANCEOF com.mysql.jdbc.JDBC4Connection cn ）得到MySQL Connection对象如下：

点击工具栏中的分组图标可按照Class Loader对结果进行分组；
在MySQL驱动中的 Connection 所引用的相关对象为：

可以发现，在36个连接中仅有2个是正常关闭的，其余的 Connection 未被关闭，但对应的 Socket 连接却处于关闭状态。这里可以假设出以下两种可能的情形：

对于第一种情形， Socket 的异常关闭势必会抛出异常，并最终在使用方拦截到该异常并关闭 Connection ，而这里的 Connection 为非关闭状态，说明使用方并未准确做资源的释放处理。第二种情形，自然也是因为资源未被及时释放了。

因此， Connection 没有被及时、准确地释放是相当肯定的事情了。

但这里依然有个疑问，为啥连接池里记录分配的连接为 749 ，而实际查到的 Connection 对象只有30多个，其余的哪儿去了？

针对上述问题，限于基本功的问题，目前还没有确切的定论，但大致可推断是MySQL驱动中的 com.mysql.jdbc.AbandonedConnectionCleanupThread 对弱引用的 com.mysql.jdbc.JDBC4Connection 对象做了资源 主动回收 处理：

com.mysql.jdbc.NonRegisteringDriver.ConnectionPhantomReference 为虚引用类 java.lang.ref.PhantomReference 的扩展类，其将在 java.lang.ref.Reference.ReferenceHandler#run 中等待JVM启动GC时进行清理活动。

Java引用相关的知识可阅读 详解java.lang.ref包中的4种引用 。

既然得到了看似很有道理的分析结论，那就应该有方法复现当前的问题。

首先，通过IDE工具查找应用中主动获取 Connection 对象而未释放的代码位置，最终找出以下几处：

经过调用分析后，可找到以下几个相关的Web API以用于复现验证：

需要注意的是，一般MySQL服务端会限定并发连接数，为了快速复现当前问题，可通过以下语句调整MySQL的默认最大连接数（重启后将失效）：

1
2

-- 查看默认配置： show variables like '%connect%';
SET GLOBAL max_connections = 850;

在登录应用A后，在浏览器控制台中执行以下代码便可复现最开始提到的异常问题：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

var ctx = '/a';
var urls = [
    ctx + '/xx/queryXx.mvc',
    ctx + '/xx/countXx.mvc'
];
var waitTime = 0.1 * 1000;

function doRequest(urls, index) {
    if (!urls || urls.length === 0) return;

    var i = index || 0;
    var url = urls[0];
    $.ajax({url: url, success: function () {
        console.log(i, url, arguments);
        setTimeout(function() {
            doRequest(urls.slice(1), i + 1);
        }, waitTime);
    }});
}

var requestCount = 800;
var requestURLs = [];
for (var i = 0; i < requestCount / urls.length; i++) {
    requestURLs = requestURLs.concat(urls);
}
doRequest(requestURLs);

解决方案

找到了根本原因，解决方案就很简单了：