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 

Приложение подключается к БД 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 | 
+--------------------------+-------+ 

Любые предложения, с которых начать отладку?

UPDATE: Благодаря ответ Стива ниже, я нашел & зафиксировал утечку соединения.

Мне не удалось получить JMX или любую запись c3p0, работающую с воспроизведением 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

Одна действительно страшная вещь игры 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. Если это утечка Connection, это будет неуклюже устранять проблему путем автоматической очистки подключений, которые были проверены более 5 секунд. Обычно я настоятельно рекомендую, чтобы c3p0.unreturnedConnectionTimeout был сопряжен с c3p0.debugUnreturnedConnectionStackTraces, который удаляет трассировку стека кода, который называется getConnection(), а затем просочился. Но, поскольку у вас нет записи c3p0, в этом есть мало смысла.

См. c3p0 docs.

Все, что сказано, то, что вы испытываете, будет нечетным видом утечки соединения/истощения бассейна, хотя, поскольку ваш пул никогда не попадает maxPoolSize. Он не может, поскольку ваш серверный макс составляет 150 соединений.

Но, похоже, вы так и не попали в него, вы используете максимум 127 соединений.Если у вас были журналы c3p0, вы можете посмотреть, есть ли в пуле Исключения, пытающиеся приобрести новые Подключения до ваших сбоев. Но у вас этого нет. Но может случиться так, что ваша СУБД значительно замедлится до того, как ударит этот предел. Если Threads_connected - это количество открытых подключений при обнаружении этих ошибок, трудно объяснить это как утечку соединения, так как ни c3p0, ни СУБД не должны быть обеспокоены 12 открытыми подключениями.

Опять же, c3p0-журнал поможет проследить это очень легко: мы можем подтвердить, что maxPoolSize - это то, что вы думаете, и посмотрите, не испытал ли c3p0 сбои при сборе соединения. Но у нас этого нет.

Если вы можете подключиться к данным JVM для JMX (например, VisualVM), вы можете посмотреть количество занятых соединений с течением времени. Если он неуклонно поднимается до отказа, это утечка соединения.

Если это утечка соединения, ошибка в вашем коде, вероятно, будет где-то, где ваши сеансы спящего режима будут закрыты() ed, но не в блоке finally, или они закрыты() в блоке finally, написанном так что исключение до Session.close() может быть пропущено из Исключения, произошедшего ранее в блоке finally. Таким образом, вы можете искать свою кодовую базу для того, где происходит сеанс hibernate Session close(), и убедитесь, что сеанс не может быть создан, а затем не скоро закрыть() ed, но не при любых возможных обстоятельствах, кроме выхода из VM.

Удачи вам!