У меня есть приложение в разработке, использующее весеннюю загрузку jpa с базой данных mysql, все на windows 10.
Приложение обычно работает нормально, но иногда, после многочасового запуска, не удается вернуться из вызова крепозиторий jpa.
Process Explorer показывает минимальную активность процессора / io.Другие потоки в приложении продолжают обращаться к базе данных без проблем.
Я в значительной степени растерялся, с чего начать поиск проблемы здесь, любые предложения приветствуются.
Мое определение репозитория::
@Repository
public interface TradeRepository extends JpaRepository<TradeDbo, Long>{
...
@Query("select t.tradeId from TradeDbo t where t.currencyPair.id = :currencyPairId")
HashBag<String> getTradeIdListByCurrencyPairId(@Param("currencyPairId") Long currencyPairId);
}
Код вызова:
log.trace("Entering tradeRepository.getTradeIdListByCurrencyPairId");
Bag<String> tradeIdsInDb = tradeRepository.getTradeIdListByCurrencyPairId(currencyPairId);
log.trace("Back from tradeRepository.getTradeIdListByCurrencyPairId");
Обычная запись в журнале:
2018-09-30 00:34:12,458 TRACE [TradesFetcher-Gdax] [CoinDbService.java:484] biz.ianw.coindatabase.services.data.CoinDbService - Entering tradeRepository.getTradeIdListByCurrencyPairId
2018-09-30 00:34:20,509 TRACE [TradesFetcher-Gdax] [CoinDbService.java:486] biz.ianw.coindatabase.services.data.CoinDbService - Back from tradeRepository.getTradeIdListByCurrencyPairId
Но когда он зависает, я получаю что-то вроде:
2018-09-30 00:34:22,732 TRACE [TradesFetcher-Gdax] [CoinDbService.java:484] biz.ianw.coindatabase.services.data.CoinDbService - Entering tradeRepository.getTradeIdListByCurrencyPairId
2018-09-30 01:05:37,626 INFO [coinLister-gdax] [CoinListerTask.java:170] biz.ianw.coindatabase.services.CoinListerTask - coinLister-gdax starting...
...
до тех пор, пока я не сломаю его (^ C), а затем не получу:
2018-09-30 05:11:13,441 WARN [TradesFetcher-Gdax] [ProxyConnection.java:161] com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Connection com.mysql.jdbc.JDBC4Connection@57ee5254 marked as broken because of SQLSTATE(08S01), ErrorCode(0)
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 16,604,912 milliseconds ago. The last packet sent successfully to the server was 16,610,693 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:990)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3562)
at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2088)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1992)
at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3413)
at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:471)
at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3115)
at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2344)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2739)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
at net.sf.log4jdbc.sql.jdbcapi.PreparedStatementSpy.executeQuery(PreparedStatementSpy.java:780)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2168)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1931)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1893)
at org.hibernate.loader.Loader.doQuery(Loader.java:938)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341)
at org.hibernate.loader.Loader.doList(Loader.java:2692)
at org.hibernate.loader.Loader.doList(Loader.java:2675)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2507)
at org.hibernate.loader.Loader.list(Loader.java:2502)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:502)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:392)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1489)
at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1445)
at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1414)
at org.hibernate.query.Query.getResultList(Query.java:146)
at org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:129)
at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:91)
at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:136)
at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:125)
at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:590)
at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:578)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:59)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:294)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:135)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy146.getTradeIdListByCurrencyPairId(Unknown Source)
at biz.ianw.coindatabase.services.data.CoinDbService.addLatestTradesGdax(CoinDbService.java:485)
at biz.ianw.coindatabase.services.data.CoinDbService$$FastClassBySpringCGLIB$$264af1e2.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
...
2018-09-30 05:11:13,456 ERROR [TradesFetcher-Gdax] [Slf4jSpyLogDelegator.java:135] jdbc.audit - 918447. PreparedStatement.executeQuery() select tradedbo0_.trade_id as col_0_0_ from trade tradedbo0_ where tradedbo0_.currency_pair_id=21185892
2018-09-30 05:11:13,472 ERROR [TradesFetcher-Gdax] [Slf4jSpyLogDelegator.java:154] jdbc.sqltiming - 918447. PreparedStatement.executeQuery() FAILED! select tradedbo0_.trade_id as col_0_0_ from trade tradedbo0_ where tradedbo0_.currency_pair_id=21185892
{FAILED after 16610724 msec}
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
Последние строки, показывающие выполнение подготовленного оператора и трассировку стека ввремя уничтожения наводит на мысль о некоторой проблеме в выполнении оператора, но мне не ясно, является ли это ошибкой или некоторым истощением ресурсов.
Обновление
Сегодняшнее тестирование получило ошибку в другом месте, сохранение, после запуска менее чем за 2 часа:
2018-10-01 11:40:33,458 INFO [TradesFetcher-Gdax] [CoinDbService.java:504] biz.ianw.coindatabase.services.data.CoinDbService - Saving...
2018-10-01 17:28:11,066 INFO [Thread-6] [Shutdown.java:12] biz.ianw.coindatabase.Shutdown - TradesFetcher-Gdax: shutdown hook started
log.info("Saving...");
currencyPairRepository.save(currencyPairDboToProcess);
log.info("Save complete");
Это тестирование также включало добавление 60-секундного тайм-аута, без эффекта:
@Transactional(readOnly=false, rollbackFor=Exception.class, timeout=60)
Я включил опции log4jdbc:
logging.level.jdbc.sqlonly=info
logging.level.jdbc.connection=info
и я снова бегу посмотреть, что, если что-нибудь я смогу извлечь из этого ...
Обновление
Очень мало, очевидно.Пробежал 3 с половиной часа, завис в другом месте:
03:35:44.208 INFO [TradesFetcher-Gdax] [Slf4jSpyLogDelegator.java:228] jdbc.sqlonly - insert into trade (creation_date, last_modified_date, currency_pair_id, original_amount, price,
timestamp, trade_id, type, version, id) values ('10/02/2018 03:35:40.806', '10/02/2018 03:35:40.806',
21185896, '0.69562553', '133.33000000', 1521469001403, '2893530', 'BID', 0, 34504324)
06:03:46.589 INFO [Thread-6] [Shutdown.java:12] biz.ianw.coindatabase.Shutdown - TradesFetcher-Gdax: shutdown hook started