java - JPA 应用程序在运行多个小时后不会从对 JPA 存储库的调用返回

Question

我正在开发一个应用程序，在 Windows 10 上使用 spring boot jpa 和 mysql 数据库。

应用程序通常运行良好，但有时，运行几个小时后无法从对 jpa 存储库的调用返回。

Process Explorer 显示最少的 cpu/io Activity 。应用程序中的其他线程继续访问数据库，不会出现问题。

我几乎不知道从哪里开始寻找问题，欢迎提出任何建议。

我的存储库定义是:

@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 1/2 小时，卡在不同的地方:

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

Answer 1

这似乎是由我使用的 Spring Boot 包中的下层 hikari 和/或 jdbc 驱动程序引起的。更新 Hikari 时出现了有关 jdbc 无法检查连接是否仍然有效的警告，而更新驱动程序则使该警告消失。从那时起，我在测试中就没有遇到任何困难(到目前为止......)。