播放框架连接超时问题

Question

我有一个播放框架 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

应用程序连接到在 localhost 上运行的 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    |
+--------------------------+-------+

有什么建议从哪里开始调试？

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

我无法让 JMX 或任何 c3p0 日志记录与 Play 1.2.5 一起工作。但是...我确实将以下方法添加到我的一个控制器中，这使我可以按需转储所有必要的 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 的顶层。然后你可以尝试一些 play1 没有传递到 c3p0 的 c3p0 配置，尤其是：

c3p0.unreturnedConnectionTimeout=5

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

请参阅c3p0 docs。

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

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

同样，c3p0 日志可以帮助您轻松追踪到这一点：我们可以验证 maxPoolSize 是否是您的想法，并查看 c3p0 是否遇到连接获取失败。但我们没有。

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

如果是连接泄漏，则代码中的错误可能在您的休眠会话被关闭（）但不在 finally 块中，或者它们在编写的 finally 块中被关闭（） Session.close() 之前的异常可能会跳过 finally 块中较早发生的异常。因此，您可能希望搜索代码库以查找休眠会话关闭（）的位置，并确保不可能创建会话，然后不会很快关闭（），而不是在 VM 退出以外的任何可能的情况下。

祝你好运！