Im facing this problem on a Productive system, and I don't know where to look next:
Context: a webapp with REST API, Java, Spring, Hibernate on a Tomcat serer.
- A random method (triggered by a user calling my REST API) freezes about 15min, then returns normally. No ERROR, No Exception.
- Not reproducible, it can happen at any time.
- It can happen on very simple methods: it happened on a one-liner where I call a Spring JPA Repositoy method (so implemented by Spring, not myself).
- I have Javamelody, so I monitor the Database respone times: it is not the Database, not the SQL!
- I have Spring monitoring pointcuts (org.springframework.aop.interceptor.PerformanceMonitorInterceptor) so I know that it "hangs" inside of the webapp. As I said earlyer, I see no pattern. It can hang anywhere.
How to go on?
- How can I find out if this is an infrastructure problem or not?
- How can I see what is hanging?
- The funny thing is the similar time: always about 933000ms or about 15min. This sounds like a timeout, but which one because there is no error! Is there any known default timeout of 15min?
Many thanks or your help. Remy
Edit from 25.11.2016
The time seems to be lost aquiring the connection:
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener - catalina-exec-31 admin 10.226.17.28 - Session Metrics {
929967181162 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
929967495527 nanoseconds spent preparing 1 JDBC statements;
449250 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}
The hanging thread is doing "getConnection":
catalina-exec-31
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
java.net.SocketInputStream.read(SocketInputStream.java:170)
java.net.SocketInputStream.read(SocketInputStream.java:141)
java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
java.io.BufferedInputStream.read(BufferedInputStream.java:345)
org.mariadb.jdbc.internal.packet.read.ReadPacketFetcher.getReusableBuffer(ReadPacketFetcher.java:166)
org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.getResult(AbstractQueryProtocol.java:900)
org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:604)
org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:261)
org.mariadb.jdbc.MariaDbStatement.executeQuery(MariaDbStatement.java:383)
org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:208)
org.apache.commons.dbcp.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:658)
org.apache.commons.dbcp.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:635)
org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1205)
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63)
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1885)
org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862)
org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1839)
org.hibernate.loader.Loader.doQuery(Loader.java:910)
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:355)
org.hibernate.loader.Loader.doList(Loader.java:2554)
org.hibernate.loader.Loader.doList(Loader.java:2540)
org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2370)
org.hibernate.loader.Loader.list(Loader.java:2365)
org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:497)
org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387)
org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:236)
org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264)
org.hibernate.internal.QueryImpl.list(QueryImpl.java:103)
org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:573)
org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:449)
org.hibernate.jpa.criteria.compile.CriteriaQueryTypeQueryAdapter.getResultList(CriteriaQueryTypeQueryAdapter.java:67)
sun.reflect.GeneratedMethodAccessor159.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:362)
com.sun.proxy.$Proxy146.getResultList(Unknown Source)
org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:110)
org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:74)
org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:97)
org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:88)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:395)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:373)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.data.repository.core.support.RepositoryFactorySupport$DefaultMethodInvokingMethodInterceptor.invoke(RepositoryFactorySupport.java:486)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodIntercceptor.invoke(CrudMethodMetadataPostProcessor.java:122)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
com.sun.proxy.$Proxy94.findByType(Unknown Source)
sun.reflect.GeneratedMethodAccessor171.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
org.springframework.aop.interceptor.PerformanceMonitorInterceptor.invokeUnderTrace(PerformanceMonitorInterceptor.java:62)
org.springframework.aop.interceptor.AbstractTraceInterceptor.invoke(AbstractTraceInterceptor.java:112)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
com.sun.proxy.$Proxy124.findByType(Unknown Source)
