播放框架连接超时问题
Play Framework Connection Timeout issue
我有一个 play 框架 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，它可以正常工作大约一个月，然后错误再次出现。
我的播放设置是：
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 日志记录工作。然而......我确实将以下方法添加到我的一个控制器中，这使我能够按需转储所有必要的 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();
}
}
玩 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 是否遇到过连接获取失败。但是我们没有。
如果您可以附加到您的 JVM 以获取 JMX 数据（例如通过 VisualVM），您可以查看一段时间内的繁忙连接数。如果它稳定上升直到失败，那就是连接泄漏。
如果是连接泄漏，代码中的 bug 可能出现在关闭休眠会话的某个地方，但不在 finally 块中，或者它们在编写的 finally 块中关闭（）这样 Session.close() 之前的异常可能会被 finally 块中较早发生的异常跳过。所以你可能想在你的代码库中搜索 hibernate Session close()es 发生的地方，并确保 Session 不可能被创建，然后不会很快关闭（），除了 VM 退出之外的任何可能情况下。
祝你好运！
我有一个 play 框架 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，它可以正常工作大约一个月，然后错误再次出现。
我的播放设置是：
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 日志记录工作。然而......我确实将以下方法添加到我的一个控制器中，这使我能够按需转储所有必要的 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();
}
}
玩 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 是否遇到过连接获取失败。但是我们没有。
如果您可以附加到您的 JVM 以获取 JMX 数据（例如通过 VisualVM），您可以查看一段时间内的繁忙连接数。如果它稳定上升直到失败，那就是连接泄漏。
如果是连接泄漏，代码中的 bug 可能出现在关闭休眠会话的某个地方，但不在 finally 块中，或者它们在编写的 finally 块中关闭（）这样 Session.close() 之前的异常可能会被 finally 块中较早发生的异常跳过。所以你可能想在你的代码库中搜索 hibernate Session close()es 发生的地方，并确保 Session 不可能被创建，然后不会很快关闭（），除了 VM 退出之外的任何可能情况下。
祝你好运！