Would there be more than one JDBC connection opened during indexing, and if there is, is there a governor for the upper limit? Today we observed the HSEARCH700083 being thrown during commit of a large batch process due to JDBC connections being exhausted.
We don’t open any additional connection during automatic indexing (the one that happens on commit).
During mass indexing, yes, there would be multiple connections opened.
See this section of the documentation for how to tune the mass indexer to use fewer threads or JDBC connections.
Today, we observed a large transaction proceed all the way to commit, and then during indexing this exception with Hibernate Search function calls in the stack trace was thrown. We were not using mass indexing, just a normal update of records.
Could you share the stack trace?
Upon further study, it wasn’t a commit() but a flush() that caused the indexing to begin. Earlier I assumed that I would not see indexing activity until the end of the transaction, but apparently that assumption is false based on the contents of the stack trace.
There were many calls to the entity manager prior to this point in the transaction, so I am surprised that another JDBC connection was needed. One way that may have happened would be for the container to evict a connection from the pool for some reason, but it would have to have done so magically without Hibernate noticing…
The workaround for this issue today on the production system was to split the transaction batch into two smaller sets, and this allowed each resulting smaller batch to finish without throwing this exception. The root cause therefore has some relation to resources, but as far as I know, only one connection should be used throughout the lifespan of a single JPA transaction.
Our next step is going to be to switch this large job into multiple JPA transactions, and that will probably make the problem go away, but since this is the first time we’ve seen this issue, and right after a major update of HS6, I thought I better communicate it. I even took a database backup and archived it so we could run this same transaction in the lab and recreate.
Absolutely!
HSEARCH700083: Exception while building document for entity ‘APInvoice#556079’: Unable to acquire JDBC Connection
org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2115)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2052)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2030)
at org.hibernate.loader.Loader.doQuery(Loader.java:956)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:357)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:327)
at org.hibernate.loader.Loader.loadCollection(Loader.java:2574)
at org.hibernate.loader.collection.plan.LegacyBatchingCollectionInitializerBuilder$LegacyBatchingCollectionInitializer.initialize(LegacyBatchingCollectionInitializerBuilder.java:92)
at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:710)
at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:76)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)
at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:2192)
at org.hibernate.collection.internal.AbstractPersistentCollection$4.doWork(AbstractPersistentCollection.java:595)
at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:264)
at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:591)
at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:149)
at org.hibernate.collection.internal.PersistentSet.iterator(PersistentSet.java:188)
at org.hibernate.search.mapper.pojo.extractor.builtin.impl.CollectionElementExtractor.extract(CollectionElementExtractor.java:27)
at org.hibernate.search.mapper.pojo.extractor.builtin.impl.CollectionElementExtractor.extract(CollectionElementExtractor.java:15)
at org.hibernate.search.mapper.pojo.extractor.impl.ContainerExtractingProcessor.process(ContainerExtractingProcessor.java:32)
at org.hibernate.search.mapper.pojo.processing.impl.PojoIndexingProcessorContainerElementNode.process(PojoIndexingProcessorContainerElementNode.java:54)
at org.hibernate.search.mapper.pojo.processing.impl.PojoIndexingProcessorPropertyNode.process(PojoIndexingProcessorPropertyNode.java:50)
at org.hibernate.search.mapper.pojo.processing.impl.PojoIndexingProcessorMultiNode.process(PojoIndexingProcessorMultiNode.java:49)
at org.hibernate.search.mapper.pojo.processing.impl.PojoIndexingProcessorOriginalTypeNode.process(PojoIndexingProcessorOriginalTypeNode.java:55)
at org.hibernate.search.mapper.pojo.work.impl.PojoDocumentContributor.contribute(PojoDocumentContributor.java:46)
at org.hibernate.search.backend.lucene.document.impl.LuceneIndexEntryFactory.create(LuceneIndexEntryFactory.java:28)
at org.hibernate.search.backend.lucene.work.execution.impl.LuceneIndexIndexingPlan.addOrUpdate(LuceneIndexIndexingPlan.java:76)
at org.hibernate.search.mapper.pojo.work.impl.PojoIndexedTypeIndexingPlan$IndexedEntityState.delegateAddOrUpdate(PojoIndexedTypeIndexingPlan.java:229)
at org.hibernate.search.mapper.pojo.work.impl.PojoIndexedTypeIndexingPlan$IndexedEntityState.sendCommandsToDelegate(PojoIndexedTypeIndexingPlan.java:174)
at java.util.LinkedHashMap$LinkedValues.forEach(LinkedHashMap.java:608)
at org.hibernate.search.mapper.pojo.work.impl.PojoIndexedTypeIndexingPlan.sendCommandsToDelegate(PojoIndexedTypeIndexingPlan.java:100)
at org.hibernate.search.mapper.pojo.work.impl.PojoIndexedTypeIndexingPlan.process(PojoIndexedTypeIndexingPlan.java:70)
at org.hibernate.search.mapper.pojo.work.impl.PojoIndexingPlanImpl.process(PojoIndexingPlanImpl.java:105)
at org.hibernate.search.mapper.orm.event.impl.HibernateSearchEventListener.onFlush(HibernateSearchEventListener.java:142)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1391)
at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1378)
at com.ibm.ws.jpa.management.JPATxEmInvocation.flush(JPATxEmInvocation.java:247)
at com.ibm.ws.jpa.management.JPAEntityManager.flush(JPAEntityManager.java:233)
at net.paradisesoftware.base.slb.GenericFlexBean.persist(GenericFlexBean.java:2305)
at net.paradisesoftware.pds.slb.APBean.createDisbursements(APBean.java:372)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.EJSContainer.invokeProceed(EJSContainer.java:4886)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:592)
at com.ibm.ws.cdi.ejb.impl.InterceptorChain.proceed(InterceptorChain.java:119)
at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.invokeInterceptors(EJBCDIInterceptorWrapper.java:131)
at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.aroundInvoke(EJBCDIInterceptorWrapper.java:54)
at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:189)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:577)
at net.paradisesoftware.base.interceptor.TracingInterceptor.logCall(TracingInterceptor.java:50)
at sun.reflect.GeneratedMethodAccessor971.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:189)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:577)
at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:72)
at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.aroundInvoke(WeldSessionBeanInterceptorWrapper.java:58)
at sun.reflect.GeneratedMethodAccessor70.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:189)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:577)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.doAroundInterceptor(InvocationContextImpl.java:298)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.doAroundInvoke(InvocationContextImpl.java:267)
at com.ibm.ejs.container.EJSContainer.invoke(EJSContainer.java:4788)
at net.paradisesoftware.pds.slb.EJSLocalNSLAPBean_8e2d4cd9.createDisbursements(EJSLocalNSLAPBean_8e2d4cd9.java)
at net.paradisesoftware.pds.slb.BatchBean.createDisbursements(BatchBean.java:279)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.EJSContainer.invokeProceed(EJSContainer.java:4886)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:592)
at com.ibm.ws.cdi.ejb.impl.InterceptorChain.proceed(InterceptorChain.java:119)
at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.invokeInterceptors(EJBCDIInterceptorWrapper.java:131)
at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.aroundInvoke(EJBCDIInterceptorWrapper.java:54)
at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:189)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:577)
at net.paradisesoftware.base.slb.GenericFlexBean.wrapExternalCall(GenericFlexBean.java:2046)
at net.paradisesoftware.base.interceptor.TracingInterceptor.logCall(TracingInterceptor.java:55)
at sun.reflect.GeneratedMethodAccessor971.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:189)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:577)
at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:81)
at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.aroundInvoke(WeldSessionBeanInterceptorWrapper.java:58)
at sun.reflect.GeneratedMethodAccessor70.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:189)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:577)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.doAroundInterceptor(InvocationContextImpl.java:298)
at com.ibm.ejs.container.interceptors.InvocationContextImpl.doAroundInvoke(InvocationContextImpl.java:267)
at com.ibm.ejs.container.EJSContainer.invoke(EJSContainer.java:4788)
at net.paradisesoftware.pds.slb.EJSLocalNSLBatchBean_98207eb4.createDisbursements(EJSLocalNSLBatchBean_98207eb4.java)
at net.paradisesoftware.pds.dao.APAssembler.createDisbursements(APAssembler.java:36)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at flex.messaging.services.remoting.adapters.JavaAdapter.invoke(JavaAdapter.java:404)
at net.paradisesoftware.messaging.JavaAdapter.invoke(JavaAdapter.java:18)
at flex.messaging.services.RemotingService.serviceMessage(RemotingService.java:183)
at flex.messaging.AsyncMessageBroker.in(AsyncMessageBroker.java:414)
at flex.messaging.MessageContext.doIn(MessageContext.java:295)
at flex.messaging.filters.AsyncMessageFilterChain.in(AsyncMessageFilterChain.java:205)
at flex.messaging.MessageContext.doIn(MessageContext.java:295)
at flex.messaging.endpoints.BaseSocketServerEndpoint.in(BaseSocketServerEndpoint.java:476)
at flex.messaging.MessageContext.doIn(MessageContext.java:295)
at flex.messaging.endpoints.RTMPConnection.handleTCCommandIn(RTMPConnection.java:886)
at flex.messaging.endpoints.RTMPConnection.in(RTMPConnection.java:1032)
at flex.messaging.endpoints.RTMPConnection.serviceTCMessage(RTMPConnection.java:1116)
at flex.messaging.endpoints.RTMPConnection.doRead(RTMPConnection.java:654)
at flex.messaging.endpoints.RTMPProtocolHandler.doRead(RTMPProtocolHandler.java:124)
at flex.messaging.socketserver.Connection$ConnectionReader.run(Connection.java:874)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Yes, that’s actually an improvement in Hibernate Search 6, the goal being to avoid LazyInitializationException when you use the “loop with periodic flush/clear” pattern.
See Hibernate Search 7.0.0.Final: Reference Documentation
Note that if you’re using transactions, Hibernate Search does not index on flush(); it only extracts data from your entities and puts documents in a buffer so that you can safely clear() your session (assuming you’re working on batches of strictly separate entities). The actual indexing still happens after commit.
Thanks. As you noticed, the problem seems to be in ORM rather than Search, since the connection was not acquired anymore when Hibernate Search started to process entities and needed to trigger lazy-loading.
It is odd, though; the only way I can see this happening is if you didn’t do anything with the connection before, i.e. if you didn’t do any actual entity loading nor flush, but only instantiated proxies (Session.getReference) and inserted new entities (Session.persist). Then, assuming the transaction is started lazily when the connection is acquired, it would seem normal that you didn’t need a connection until the flush.
A more unlikely, but still possible scenario is that you tweaked the connection handling mode and picked something exotic such as DELAYED_ACQUISITION_AND_RELEASE_AFTER_STATEMENT.
This is good to know. Will this buffer become invalidated if I do a refresh() on the object already in the buffer, or modify its collections which are embedded? Extracting too early means extraction will need to happen over and over again, every time a “child” entity is added to collections that are IndexedEmbedded, in order to buffer the new data, right? If we flush on each persist to allocate and retrieve the database generated @Id property, this might be slower now?
We’re always in a JTA transaction. In our application, we have a mixture of bean managed transactions, and container managed transactions. The application runs in WebSphere application server (Liberty, not the legacy edition), and all JDBC connections are handled by the container, using a connection pool.
The routine we are dealing with here does flush on persist so we can discover the id of the newly created record that is assigned by the IBM DB2 database, but clear is not used in this routine. We do have other routines that use the “loop with periodic flush/clear” pattern.
It does seem like ORM is letting go of a connection prematurely, or starting a new one when it shouldn’t be. Previous to our upgrade we did not see any of these JDBC errors.
The beginning of this routine starts off with a query written in HQL that executes, so we know that database activity has happened before this persist / flush in the stack trace. It doesn’t look good for ORM at this point. It’s almost like connections are leaking during large transactions to the point of exhausting the connection pool. As a test of this, I doubled the size of the connection pool earlier today, and this particular job still didn’t make it through to the end.
Thank you for the conversation. I’m going to study ORM further and maybe raise an issue over in that group after I have done more homework.
Here is more information about how automatic indexing works.
If more changes happen on the same entity, another document will be appended to the buffer, and that second document will always be indexed after the first one, “updating” it. We could introduce some mechanism to only send the latest document in the buffer and skip the first one, but that would require more checks, which are unnecessary in general and might hurt performance when they are not needed… Not sure it would be worth it 
It might; one more instance where performance had to be traded for correctness. Though if you’re flushing so often that this becomes a performance issue, you probably have similar performance issues with the database.
Please ping me if you do; this might be related to something I did to fix connection handling in Quarkus. Maybe it doesn’t work that well in WildFly; that was hard to know since WildFly is currently stuck on ORM 5.3.