hibernate - Play 框架连接超时问题

Question

我有一个 Play Framework Java 应用程序( Play v1.2.5)，它可以正常工作大约一个月，然后产生以下错误:

An unexpected error occured caused by exception PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection

play.exceptions.UnexpectedException: Unexpected Error
        at play.Invoker$Invocation.onException(Invoker.java:244)
        at play.Invoker$Invocation.run(Invoker.java:286)
        at Invocation.HTTP Request(Play!)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1389)
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1317)
        at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1399)
        at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:63)
        at play.db.jpa.JPAPlugin.startTx(JPAPlugin.java:377)
        at play.db.jpa.JPAPlugin.beforeInvocation(JPAPlugin.java:345)
        at play.plugins.PluginCollection.beforeInvocation(PluginCollection.java:473)
        at play.Invoker$Invocation.before(Invoker.java:217)
        at play.Invoker$Invocation.run(Invoker.java:277)
        ... 1 more
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
        at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52)
        at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:449)
        at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
        at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
        at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
        at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
        at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:60)
        ... 6 more
Caused by: java.sql.SQLException: An attempt by a client to checkout a Connection has timed out.
        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
        at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:71)
        at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
        ... 11 more
Caused by: com.mchange.v2.resourcepool.TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@22811ae4 -- timeout at awaitAvailable()
        at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1317)
        at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
        at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
        ... 13 more

如果我重新启动 Play，它会在错误重复之前正常工作大约一个月。

我的 Play 设置是:

db.pool.timeout=10000
db.pool.maxSize=500
db.pool.minSize=10

该应用程序连接到在本地主机上运行的 MySQL 数据库。 MySQL 配置为最多 150 个连接。

MySQL的统计数据是:
mysql> 显示状态如 '%onne%';

+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| Aborted_connects         | 546   |
| Connections              | 33197 |
| Max_used_connections     | 127   |
| Ssl_client_connects      | 0     |
| Ssl_connect_renegotiates | 0     |
| Ssl_finished_connects    | 0     |
| Threads_connected        | 11    |
+--------------------------+-------+

任何建议从哪里开始调试？

更新:
感谢下面史蒂夫的回答，我发现并修复了连接泄漏。

我无法使用 Play 1.2.5 使 JMX 或任何 c3p0 日志记录工作。但是......我确实将以下方法添加到我的一个 Controller 中，这允许我按需转储所有必要的 c3p0 统计信息:

   public static void c3p0() {
        ComboPooledDataSource local = (ComboPooledDataSource) DB.datasource;
        try {
            Logger.info("===============C3P0 STATS================");

            Logger.info("MaxConnectionAge: " + local.getMaxConnectionAge());
            Logger.info("MaxPoolSize: " + local.getMaxPoolSize());
            Logger.info("NumConnectionsAllUsers: " + local.getNumConnectionsAllUsers());
            Logger.info("NumConnectionsDefaultUsers: " + local.getNumConnectionsDefaultUser());

            Logger.info("NumBusyConnectionsAllUsers: " + local.getNumBusyConnectionsAllUsers());
            Logger.info("NumBusyConnectionsDefaultUser: " + local.getNumBusyConnectionsDefaultUser());

            Logger.info("LastCheckinFailureDefaultUser: " + local.getLastCheckinFailureDefaultUser());
            Logger.info("NumFailedCheckinsDefaultUser: " + local.getNumFailedCheckinsDefaultUser());
            Logger.info("NumFailedCheckoutsDefaultUser: " + local.getNumFailedCheckoutsDefaultUser());

            Logger.info("NumIdleConnectionsAllUser: " + local.getNumIdleConnectionsAllUsers());
            Logger.info("NumIdleConnectionsDefaultUser: " + local.getNumIdleConnectionsDefaultUser());

            Logger.info("NumUnclosedOrphanedConnectionsAllUsers: " + local.getNumUnclosedOrphanedConnectionsAllUsers());
            Logger.info("NumUnclosedOrphanedConnectionsDefaultUsers: " + local.getNumUnclosedOrphanedConnectionsDefaultUser());
            Logger.info("===============END STATS================");
            ok();
        } 
        catch (Exception e) {
            error();
        }
    }

Answer 1

play 1.x 的一个真正可怕的地方是它在 its source code 中有这个。 :

System.setProperty("com.mchange.v2.log.MLog", "com.mchange.v2.log.FallbackMLog");
System.setProperty("com.mchange.v2.log.FallbackMLog.DEFAULT_CUTOFF_LEVEL", "OFF");

这基本上将所有 c3p0 日志发送到 /dev/null .因此，关于您的问题，您掌握的信息比应有的要少。

也就是说，这听起来很像不常见的连接泄漏。你可以做一件事来验证这个集合 db.pool.timeout=0 .那么您的应用程序最终应该只是挂起，而不是抛出您看到的异常。并不是这样更好。

另一种方法是定义一个 c3p0.properties文件并将其作为资源放在应用程序的顶层 CLASSPATH .然后你可以尝试一些 c3p0 配置，play1 不会传递到 c3p0，尤其是:

c3p0.unreturnedConnectionTimeout=5

该值应该远低于您的 db.pool.timeout。如果是连接泄漏，这将通过自动清理已 check out 超过 5 秒的连接来笨拙地解决问题。通常我强烈推荐 c3p0.unreturnedConnectionTimeout配对 c3p0.debugUnreturnedConnectionStackTraces ，它转储调用 getConnection() 的代码的堆栈跟踪，然后泄漏它。但是，由于您没有 c3p0 日志记录，因此没有什么意义。

见 c3p0 docs .

尽管如此，您所遇到的将是一种奇怪的连接泄漏/池耗尽，因为您的池从未达到 maxPoolSize .它不能，因为您的服务器端最大值是 150 个连接。

但是，看起来您也从未遇到过，您最多使用 127 个连接。如果您有 c3p0 日志，您可以查看池是否在尝试获取新连接之前遇到异常。但你没有那个。但可能是您的 DBMS 在达到该限制之前显着减慢。如 Threads_connected是您看到这些错误时打开的连接数，很难将其解释为连接泄漏，因为 c3p0 和 DBMS 都不应该受到 12 个打开连接的困扰。

同样，c3p0 日志将有助于很容易地追踪到这一点:我们可以验证 maxPoolSize就是你想的那样，看看c3p0有没有遇到Connection获取失败的情况。但我们没有那个。

如果您可以将 JMX 数据附加到您的 JVM(通过例如 VisualVM)，您可以查看一段时间内繁忙连接的数量。如果它稳定上升直到失败，那就是连接泄漏。

如果是连接泄漏，则您的代码中的错误可能位于您的 hibernate session 被 close() ed 的某处，但不在 finally 块中，或者它们在 finally 块中被 close() ed 写入以便异常优先到 Session.close()可能会跳过在 finally 块中较早发生的异常。因此，您可能希望在代码库中搜索 hibernate Session close()es 发生的位置，并确保 Session 不可能被创建，然后不会很快 close() ed，而不是在 VM 退出以外的任何可能情况下。

祝你好运!