java.net.SocketTimeoutException: Read timed out

[dark...@gmail.com]

Hey everyone,

I'm using the HAPI FHIR Server 2.4 (with DSTU2) to do some local testing of an app that consumes FHIR data, but the server frequently becomes unresponsive when being used. The Web UI sometimes still loads will displays this error:

Warning!

Failed to load conformance statement, error was: ca.uhn.fhir.rest.client.exceptions.FhirClientConnectionException: Encountered IOException when performing GET to URL http://localhost:8081/baseDstu2/metadata?_pretty=true - java.net.SocketTimeoutException: Read timed out

And I can see a related stack trace in the console where the server is running:

ca.uhn.fhir.rest.client.exceptions.FhirClientConnectionException: Encountered IOException when performing GET to URL http://localhost:8081/baseDstu2/metadata?_pretty=true - java.net.SocketTimeoutException: Read timed out

at ca.uhn.fhir.rest.client.BaseClient.invokeClient(BaseClient.java:333)

at ca.uhn.fhir.rest.client.BaseClient.invokeClient(BaseClient.java:183)

at ca.uhn.fhir.rest.client.GenericClient.conformance(GenericClient.java:203)

at ca.uhn.fhir.to.BaseController.loadAndAddConfDstu2(BaseController.java:397)

at ca.uhn.fhir.to.BaseController.loadAndAddConf(BaseController.java:321)

at ca.uhn.fhir.to.BaseController.addCommonParams(BaseController.java:97)

at ca.uhn.fhir.to.Controller.actionResource(Controller.java:320)

at sun.reflect.GeneratedMethodAccessor254.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)

at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)

at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116)

at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)

at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)

at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)

at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)

at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)

at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)

at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)

at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1650)

at org.ebaysf.web.cors.CORSFilter.handleNonCORS(CORSFilter.java:437)

at org.ebaysf.web.cors.CORSFilter.doFilter(CORSFilter.java:172)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1629)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)

at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)

at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:219)

at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

at org.eclipse.jetty.server.Server.handle(Server.java:564)

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:317)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:110)

at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)

at org.eclipse.jetty.util.thread.Invocable.invokePreferred(Invocable.java:128)

at org.eclipse.jetty.util.thread.Invocable$InvocableExecutor.invoke(Invocable.java:222)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:294)

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:199)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:673)

at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:591)

at java.lang.Thread.run(Thread.java:745)

Caused by: java.net.SocketTimeoutException: Read timed out

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)

at java.net.SocketInputStream.read(SocketInputStream.java:171)

at java.net.SocketInputStream.read(SocketInputStream.java:141)

at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)

at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)

at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282)

at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)

at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)

at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)

at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)

at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:167)

at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)

at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)

at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:271)

at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184)

at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88)

at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)

at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)

at ca.uhn.fhir.rest.client.apache.ApacheHttpRequest.execute(ApacheHttpRequest.java:63)

at ca.uhn.fhir.rest.client.BaseClient.invokeClient(BaseClient.java:240)

... 57 common frames omitted

There are no other errors in the log or any indications of what is wrong with the server. REST calls made to the FHIR API just hang before timing out. I'm seeing this behavior when running in either Jetty or Tomcat, both locally on a Mac and in a Linux container on AWS. Has anyone else seen anything like this? 

[James Agnew]

Hi there,

Can you try this with HAPI FHIR 2.5 first, just to make sure this isn't a bug that is already fixed?

Can you take a thread dump of the server when it's in this state, and post it here?

Cheers,

James

--
You received this message because you are subscribed to the Google Groups "HAPI FHIR" group.
To unsubscribe from this group and stop receiving emails from it, send an email to hapi-fhir+unsubscribe@googlegroups.com.
To post to this group, send email to hapi...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/hapi-fhir/a41ccd9e-2708-4761-b71a-d6bf10a02308%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[dark...@gmail.com]

Hey James,

Thanks for the response. I got the server in to this state again while I had jProfiler attached. It's showing me that there are 8 hung JDBC connections. 8 also happens to be the default dbcp pool size which explains why the server no longer responds to requests. I will try tweaking dbcp DataSource settings to see if I can get it to kill leaked connections, but I'd also like to find out why they are hanging. Below is a thread dump for one of the currently blocked threads (minus the Jetty stuff from the very top)- all of the blocked threads have a nearly identical dump. Does it make much sense to you? 

org.hibernate.id.enhanced.PooledOptimizer.generate(org.hibernate.id.enhanced.AccessCallback) (line: 70)
org.hibernate.id.enhanced.SequenceStyleGenerator.generate(org.hibernate.engine.spi.SharedSessionContractImplementor, java.lang.Object) (line: 432)
org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(java.lang.Object, java.lang.String, java.lang.Object, org.hibernate.event.spi.EventSource, boolean) (line: 105)
org.hibernate.jpa.event.internal.core.JpaPersistEventListener.saveWithGeneratedId(java.lang.Object, java.lang.String, java.lang.Object, org.hibernate.event.spi.EventSource, boolean) (line: 67)
org.hibernate.event.internal.DefaultPersistEventListener.entityIsTransient(org.hibernate.event.spi.PersistEvent, java.util.Map) (line: 189)
org.hibernate.event.internal.DefaultPersistEventListener.onPersist(org.hibernate.event.spi.PersistEvent, java.util.Map) (line: 132)
org.hibernate.event.internal.DefaultPersistEventListener.onPersist(org.hibernate.event.spi.PersistEvent) (line: 58)
org.hibernate.internal.SessionImpl.firePersist(org.hibernate.event.spi.PersistEvent) (line: 773)
org.hibernate.internal.SessionImpl.persist(java.lang.Object) (line: 758)
sun.reflect.GeneratedMethodAccessor149.invoke(java.lang.Object, java.lang.Object[ ])
sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[ ]) (line: 43)
java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[ ]) (line: 498)
org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 298)
com.sun.proxy.$Proxy88.persist(java.lang.Object)
org.springframework.data.jpa.repository.support.SimpleJpaRepository.save(java.lang.Object) (line: 506)
org.springframework.data.jpa.repository.support.SimpleJpaRepository.save(java.lang.Iterable) (line: 540)
org.springframework.data.jpa.repository.support.SimpleJpaRepository.save(java.lang.Iterable) (line: 72)
sun.reflect.GeneratedMethodAccessor237.invoke(java.lang.Object, java.lang.Object[ ])
sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[ ]) (line: 43)
java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[ ]) (line: 498)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.executeMethodOn(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 503)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(org.aopalliance.intercept.MethodInvocation) (line: 488)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 460)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 61)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation() (line: 99)
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(java.lang.reflect.Method, java.lang.Class, org.springframework.transaction.interceptor.TransactionAspectSupport$InvocationCallback) (line: 282)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 96)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 136)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 133)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 92)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 213)
com.sun.proxy.$Proxy113.save(java.lang.Iterable)
ca.uhn.fhir.jpa.dao.SearchBuilder.doSetPids(java.util.Collection) (line: 1596)
ca.uhn.fhir.jpa.dao.SearchBuilder.addPredicateDate(java.lang.String, java.util.List) (line: 184)
ca.uhn.fhir.jpa.dao.SearchBuilder.searchForIdsWithAndOr(ca.uhn.fhir.jpa.dao.SearchParameterMap, ca.uhn.fhir.rest.param.DateRangeParam) (line: 1883)
ca.uhn.fhir.jpa.dao.SearchBuilder.search(ca.uhn.fhir.jpa.dao.SearchParameterMap) (line: 1780)
ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao.search(ca.uhn.fhir.jpa.dao.SearchParameterMap) (line: 969)
sun.reflect.GeneratedMethodAccessor239.invoke(java.lang.Object, java.lang.Object[ ])
sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[ ]) (line: 43)
java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[ ]) (line: 498)
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 333)
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint() (line: 190)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 157)
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation() (line: 99)
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(java.lang.reflect.Method, java.lang.Class, org.springframework.transaction.interceptor.TransactionAspectSupport$InvocationCallback) (line: 282)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 96)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 213)
com.sun.proxy.$Proxy96.search(ca.uhn.fhir.jpa.dao.SearchParameterMap)
ca.uhn.fhir.jpa.rp.dstu2.AppointmentResourceProvider.search(javax.servlet.http.HttpServletRequest, ca.uhn.fhir.rest.method.RequestDetails, ca.uhn.fhir.rest.param.StringAndListParam, ca.uhn.fhir.rest.param.StringAndListParam, ca.uhn.fhir.rest.param.TokenAndListParam, ca.uhn.fhir.rest.param.TokenAndListParam, ca.uhn.fhir.rest.param.UriAndListParam, ca.uhn.fhir.rest.param.HasAndListParam, ca.uhn.fhir.rest.param.StringAndListParam, ca.uhn.fhir.rest.param.StringAndListParam, ca.uhn.fhir.rest.param.ReferenceAndListParam, ca.uhn.fhir.rest.param.DateRangeParam, ca.uhn.fhir.rest.param.TokenAndListParam, ca.uhn.fhir.rest.param.ReferenceAndListParam, ca.uhn.fhir.rest.param.TokenAndListParam, ca.uhn.fhir.rest.param.ReferenceAndListParam, ca.uhn.fhir.rest.param.ReferenceAndListParam, ca.uhn.fhir.rest.param.TokenAndListParam, java.util.Map, java.util.Set, ca.uhn.fhir.rest.param.DateRangeParam, java.util.Set, ca.uhn.fhir.rest.api.SortSpec, java.lang.Integer) (line: 147)
sun.reflect.GeneratedMethodAccessor244.invoke(java.lang.Object, java.lang.Object[ ])
sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[ ]) (line: 43)
java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[ ]) (line: 498)
ca.uhn.fhir.rest.method.BaseMethodBinding.invokeServerMethod(ca.uhn.fhir.rest.server.IRestfulServer, ca.uhn.fhir.rest.method.RequestDetails, java.lang.Object[ ]) (line: 258)
ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(ca.uhn.fhir.rest.server.IRestfulServer, ca.uhn.fhir.rest.method.RequestDetails, java.lang.Object[ ]) (line: 291)
ca.uhn.fhir.rest.method.SearchMethodBinding.invokeServer(ca.uhn.fhir.rest.server.IRestfulServer, ca.uhn.fhir.rest.method.RequestDetails, java.lang.Object[ ]) (line: 54)
ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.doInvokeServer(ca.uhn.fhir.rest.server.IRestfulServer, ca.uhn.fhir.rest.method.RequestDetails) (line: 306)
ca.uhn.fhir.rest.method.BaseResourceReturningMethodBinding.invokeServer(ca.uhn.fhir.rest.server.IRestfulServer, ca.uhn.fhir.rest.method.RequestDetails) (line: 258)
ca.uhn.fhir.rest.server.RestfulServer.handleRequest(ca.uhn.fhir.rest.api.RequestTypeEnum, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) (line: 676)
ca.uhn.fhir.rest.server.RestfulServer.doGet(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) (line: 1226)
ca.uhn.fhir.rest.server.RestfulServer.service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) (line: 1202)
javax.servlet.http.HttpServlet.service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) (line: 790)

To unsubscribe from this group and stop receiving emails from it, send an email to hapi-fhir+...@googlegroups.com.

[James Agnew]

That stack trace does not appear to be the latest version of HAPI (the doSetPids method was removed in HAPI 2.4). Can you please try this with HAPI FHIR 2.5?

Cheers,

James

To unsubscribe from this group and stop receiving emails from it, send an email to hapi-fhir+unsubscribe@googlegroups.com.

To post to this group, send email to hapi...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/hapi-fhir/20620c56-4bd2-46df-b8df-ab2afc0ad1f3%40googlegroups.com.

[dark...@gmail.com]

I upgraded to 2.5, unfortunately I was still able to reproduce the issue. All 8 database threads are hung up with the same stack trace:

org.hibernate.id.enhanced.PooledOptimizer.generate(org.hibernate.id.enhanced.AccessCallback) (line: 70)
org.hibernate.id.enhanced.SequenceStyleGenerator.generate(org.hibernate.engine.spi.SharedSessionContractImplementor, java.lang.Object) (line: 432)
org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(java.lang.Object, java.lang.String, java.lang.Object, org.hibernate.event.spi.EventSource, boolean) (line: 105)
org.hibernate.jpa.event.internal.core.JpaPersistEventListener.saveWithGeneratedId(java.lang.Object, java.lang.String, java.lang.Object, org.hibernate.event.spi.EventSource, boolean) (line: 67)
org.hibernate.event.internal.DefaultPersistEventListener.entityIsTransient(org.hibernate.event.spi.PersistEvent, java.util.Map) (line: 189)
org.hibernate.event.internal.DefaultPersistEventListener.onPersist(org.hibernate.event.spi.PersistEvent, java.util.Map) (line: 132)
org.hibernate.event.internal.DefaultPersistEventListener.onPersist(org.hibernate.event.spi.PersistEvent) (line: 58)
org.hibernate.internal.SessionImpl.firePersist(org.hibernate.event.spi.PersistEvent) (line: 773)
org.hibernate.internal.SessionImpl.persist(java.lang.Object) (line: 758)

sun.reflect.GeneratedMethodAccessor88.invoke(java.lang.Object, java.lang.Object[ ])

sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[ ]) (line: 43)
java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[ ]) (line: 498)
org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 298)

com.sun.proxy.$Proxy91.persist(java.lang.Object)
org.springframework.data.jpa.repository.support.SimpleJpaRepository.save(java.lang.Object) (line: 506)
sun.reflect.GeneratedMethodAccessor95.invoke(java.lang.Object, java.lang.Object[ ])

sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[ ]) (line: 43)
java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[ ]) (line: 498)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.executeMethodOn(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 503)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(org.aopalliance.intercept.MethodInvocation) (line: 488)
org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 460)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 61)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation() (line: 99)
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(java.lang.reflect.Method, java.lang.Class, org.springframework.transaction.interceptor.TransactionAspectSupport$InvocationCallback) (line: 282)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 96)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 136)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 133)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) (line: 92)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() (line: 179)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[ ]) (line: 213)

com.sun.proxy.$Proxy111.save(java.lang.Object)
ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl$SearchTask.doSaveSearch() (line: 530)
ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl$SearchTask.access$1200(ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl$SearchTask) (line: 431)
ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl$SearchTask$2.doInTransactionWithoutResult(org.springframework.transaction.TransactionStatus) (line: 618)
org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(org.springframework.transaction.TransactionStatus) (line: 34)
org.springframework.transaction.support.TransactionTemplate.execute(org.springframework.transaction.support.TransactionCallback) (line: 133)
ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl$SearchTask.saveSearch() (line: 615)
ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl$SearchTask.call() (line: 473)
ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl$SearchTask.call() (line: 431)
java.util.concurrent.FutureTask.run() (line: 266)
java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) (line: 1142)
java.util.concurrent.ThreadPoolExecutor$Worker.run() (line: 617)
java.lang.Thread.run() (line: 745)

[James Agnew]

Ah, is this against a MySQL database by any chance?

Hibernate has a bug (which they don't seem to entirely believe is a bug) when operating at heavy load on MySQL: https://hibernate.atlassian.net/browse/HHH-11825

The workaround to this seems to be to make sure you have fewer request threads in your application server threadpool than you do database connections in your DB connection pool. This is known to avoid this problem.

Cheers,

James

To unsubscribe from this group and stop receiving emails from it, send an email to hapi-fhir+unsubscribe@googlegroups.com.

To post to this group, send email to hapi...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/hapi-fhir/347f9a4f-86bc-4299-a735-e13bb5d54853%40googlegroups.com.

[dark...@gmail.com]

Yes we had the server connected to a MySQL database. I implemented a workaround (set the db pool size = request pool size + 1) and have now gone two days without seeing this behavior again... I think you nailed it! Thanks again James!