JVM内存分析:数据库连接池耗尽

提要

由于数据库连接十分耗时,采取即需即连的方式会导致应用响应缓慢,因此,在Java应用中均采用数据库连接池统一维护一定数量的Connection对象,连接池中的Connection均保持与数据库的长连接,这样,该连接将随时可用,从而提高应用响应和处理速度。

但是,在普遍的使用不当的情形中,最多的问题便是没有及时释放连接,这里的释放是指将Connection对象归还连接池。若连接未被释放,则连接池将被很快耗尽(Exhausted),从而无法提供新的连接,最终导致应用不能进行数据库操作,并在尝试获取新的连接时出现以下异常:

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):

  • OQL的语法可从MAT的Help -> Help Contents菜单中进入帮助手册查询到;
  • org.apache.commons.dbcp.BasicDataSource为应用中使用的DataSource的实现类,其内部引用org.apache.commons.dbcp.PoolingDataSource,并在PoolingDataSource中负责从连接池申请新的连接;

从图中可以看到,连接池org.apache.commons.pool.impl.GenericObjectPool_numActive749,而在应用中为其分配的最大活跃连接数(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所引用的相关对象为:

  • com.mysql.jdbc.JDBC4Connection#io:com.mysql.jdbc.MysqlIO
  • com.mysql.jdbc.MysqlIO#mysqlConnection:java.net.Socket
  • java.net.Socket#closed:boolean

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

  • Connection使用时出现网络中断,导致Socket非正常关闭;
  • 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对象而未释放的代码位置,最终找出以下几处:

  • xx/xx/xx/XxQueryImpl.java @r74605: L357, L1607

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

  • /a/xx/queryXx.mvc
  • /a/xx/countXx.mvc

需要注意的是,一般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);

解决方案

找到了根本原因,解决方案就很简单了:

  • try {...} finally {...}语句的finally块中关闭主动获取Connection对象。

而本案例中的业务需求似乎比较特殊,具体方案需根据实际业务需求确定,但必须坚持以下原则:

  • finally块中释放主动获取的Connection对象;
  • 数据库类型无关:尽可能避免在代码中根据数据库类型做条件判断,首选HQL所支持的数据库无关的查询语句和表达式

参考

文章作者: flytreeleft
文章链接: https://flytreeleft.github.io/the-jvm-dump-analyse-for-connection-pool-exhausted/
版权声明: 本博客所有文章除特别声明外,均采用 知识共享署名 4.0 国际许可协议 许可协议。转载请注明来自 flytreeleft's Blog