Play Framework Connection Timeout问题

Question

我有一个播放框架Java应用程序(播放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

该应用程序连接到在localhost上运行的MySQL数据库.MySQL配置最多150个连接.

来自MySQL的统计信息是:mysql> show status like'%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的一个非常糟糕的事情是它的源代码中有这个:

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.如果是连接泄漏,这将通过自动清理已签出超过5秒的连接,匆忙地解决问题.通常我强烈建议c3p0.unreturnedConnectionTimeout配对c3p0.debugUnreturnedConnectionStackTraces,它会转储调用getConnection()的代码的堆栈跟踪然后泄漏它.但是,由于您没有c3p0日志记录,因此没有什么意义.

请参阅c3p0文档.

所有这些都说,你所经历的将是一种奇怪的连接泄漏/池耗尽,但是,因为你的池永远不会打maxPoolSize.它不能,因为您的服务器端最大值是150个连接.

但是,看起来好像你从来没有打过它,你最多使用127个连接.如果您有c3p0日志,则可以查看池是否遇到异常,尝试在失败之前获取新的Connections.但你没有那个.但可能是你的DBMS在达到这个限制之前急剧减速.如果Threads_connected是您看到这些错误时打开的连接数,则很难将其解释为连接泄漏,因为c3p0和DBMS都不应该被12个打开的连接困扰.

同样,c3p0日志可以很容易地帮助跟踪它:我们可以验证maxPoolSize你的想法,看看c3p0是否经历了连接获取失败.但我们没有那个.

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

如果它是一个连接泄漏,你的代码中的错误很可能是你的休眠Sessions被关闭()编辑的地方,但不是在finally块中,或者它们在写入的finally块中是close()ed,以便异常优先到Session.close()可能会跳过一个异常的早期finally块中发生.因此,您可能希望在代码库中搜索hibernate会话close()es发生的位置,并确保无法创建Session,然后不能很快关闭()ed,而不是在VM退出之外的任何可能情况下.

祝好运!