Details
-
Bug
-
Resolution: Duplicate
-
Major
-
None
-
12.1.7.Final
-
None
Description
I'm using Infinispan local cache with jdbc store and have got the following error in the server.log after upgrading from Wildfly 11 to 25:
2022-06-01 15:15:00,308 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (blocking-thread--p20-t4) [bcID=;user=;device=] IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@20d82c00[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@716863d7 connection handles=1 lastReturned=1654089240200 lastValidated=1654089179375 lastCheckedOut=1654089240290 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@5e45d337 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@2f5b2574[pool=lisaDS] xaResource=LocalXAResourceImpl@4bb64d92[connectionListener=20d82c00 connectionManager=113c891f warned=false currentXid=null productName=Oracle productVersion=Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production Version 19.6.0.0.0 jndiName=java:jboss/datasources/lisaDS] txSync=null]: java.sql.SQLRecoverableException: I/O-Fehler: Socket read timed out at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:993) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1205) at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3666) at oracle.jdbc.driver.T4CPreparedStatement.executeInternal(T4CPreparedStatement.java:1426) at oracle.jdbc.driver.OraclePreparedStatement.executeLargeUpdate(OraclePreparedStatement.java:3756) at oracle.jdbc.driver.OraclePreparedStatement.executeUpdate(OraclePreparedStatement.java:3736) at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeUpdate(OraclePreparedStatementWrapper.java:1063) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:537) at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.delete(JdbcStringBasedStore.java:569) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.delete(JdbcStringBasedStore.java:552) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.lambda$delete$10(NonBlockingStoreAdapter.java:227) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlockingOperation(BlockingManagerImpl.java:139) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlocking(BlockingManagerImpl.java:130) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.delete(NonBlockingStoreAdapter.java:226) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.manager.PersistenceManagerImpl.lambda$deleteFromAllStores$30(PersistenceManagerImpl.java:724) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onNext(FlowableFlatMapSingle.java:118) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFilter$FilterSubscriber.tryOnNext(FlowableFilter.java:74) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$IteratorConditionalSubscription.fastPath(FlowableFromIterable.java:321) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:129) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.request(BasicFuseableSubscriber.java:153) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onSubscribe(FlowableFlatMapSingle.java:106) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.onSubscribe(BasicFuseableSubscriber.java:67) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:66) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFilter.subscribeActual(FlowableFilter.java:37) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle.subscribeActual(FlowableFlatMapSingle.java:53) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15814) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableReduceSeedSingle.subscribeActual(FlowableReduceSeedSingle.java:50) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.single.SingleUsing.subscribeActual(SingleUsing.java:83) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribeWith(Single.java:4863) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.toCompletionStage(Single.java:5635) [rxjava-3.0.13.jar:] at org.infinispan.persistence.manager.PersistenceManagerImpl.deleteFromAllStores(PersistenceManagerImpl.java:729) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.deleteFromStoresAndNotify(ExpirationManagerImpl.java:229) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.lambda$handleInStoreExpirationInternal$1(ExpirationManagerImpl.java:194) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.lambda$compute$1(AbstractInternalDataContainer.java:229) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$remap$16(BoundedLocalCache.java:2507) [caffeine-2.8.8.jar:] at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1853) [rt.jar:1.8.0_275] at com.github.benmanes.caffeine.cache.BoundedLocalCache.remap(BoundedLocalCache.java:2502) [caffeine-2.8.8.jar:] at com.github.benmanes.caffeine.cache.BoundedLocalCache.compute(BoundedLocalCache.java:2454) [caffeine-2.8.8.jar:] at com.github.benmanes.caffeine.cache.LocalCache.compute(LocalCache.java:95) [caffeine-2.8.8.jar:] at org.infinispan.commons.util.AbstractDelegatingMap.compute(AbstractDelegatingMap.java:81) [infinispan-commons-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:228) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:245) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:190) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:186) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.manager.PersistenceManagerImpl.lambda$purgeExpired$24(PersistenceManagerImpl.java:676) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:187) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.mixed.ConcatMapXMainSubscriber.onNext(ConcatMapXMainSubscriber.java:104) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.drainFused(UnicastProcessor.java:349) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.drain(UnicastProcessor.java:382) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.onNext(UnicastProcessor.java:444) [rxjava-3.0.13.jar:] at org.infinispan.persistence.support.NonBlockingStoreAdapter$1.entryPurged(NonBlockingStoreAdapter.java:172) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.purge(JdbcStringBasedStore.java:603) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.spi.SegmentedAdvancedLoadWriteStore.purge(SegmentedAdvancedLoadWriteStore.java:182) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.lambda$purgeExpired$2(NonBlockingStoreAdapter.java:179) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1640) [rt.jar:1.8.0_275] at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.as.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49) at org.jboss.as.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:70) at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_275] Caused by: oracle.net.ns.NetException: Socket read timed out at oracle.net.ns.Packet.receive(Packet.java:359) at oracle.net.ns.DataPacket.receive(DataPacket.java:128) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) at oracle.net.ns.NetInputStream.read(NetInputStream.java:257) at oracle.net.ns.NetInputStream.read(NetInputStream.java:177) at oracle.net.ns.NetInputStream.read(NetInputStream.java:95) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:132) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:88) at oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:395) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:410) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:269) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:655) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:270) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:91) at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:970) ... 67 more2022-06-01 15:15:00,314 INFO [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (blocking-thread--p20-t4) [bcID=;user=;device=] IJ000302: Unregistered handle that was not registered: org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@6fabd58f for managed connection: org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@716863d7 2022-06-01 15:15:00,316 ERROR [org.infinispan.PERSISTENCE] (blocking-thread--p20-t4) [bcID=;user=;device=] ISPN008025: Error while removing string keys from database: java.sql.SQLRecoverableException: I/O-Fehler: Socket read timed out at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:993) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1205) at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3666) at oracle.jdbc.driver.T4CPreparedStatement.executeInternal(T4CPreparedStatement.java:1426) at oracle.jdbc.driver.OraclePreparedStatement.executeLargeUpdate(OraclePreparedStatement.java:3756) at oracle.jdbc.driver.OraclePreparedStatement.executeUpdate(OraclePreparedStatement.java:3736) at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeUpdate(OraclePreparedStatementWrapper.java:1063) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:537) at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.delete(JdbcStringBasedStore.java:569) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.delete(JdbcStringBasedStore.java:552) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.lambda$delete$10(NonBlockingStoreAdapter.java:227) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlockingOperation(BlockingManagerImpl.java:139) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlocking(BlockingManagerImpl.java:130) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.delete(NonBlockingStoreAdapter.java:226) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.manager.PersistenceManagerImpl.lambda$deleteFromAllStores$30(PersistenceManagerImpl.java:724) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onNext(FlowableFlatMapSingle.java:118) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFilter$FilterSubscriber.tryOnNext(FlowableFilter.java:74) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$IteratorConditionalSubscription.fastPath(FlowableFromIterable.java:321) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:129) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.request(BasicFuseableSubscriber.java:153) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onSubscribe(FlowableFlatMapSingle.java:106) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.onSubscribe(BasicFuseableSubscriber.java:67) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:66) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFilter.subscribeActual(FlowableFilter.java:37) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle.subscribeActual(FlowableFlatMapSingle.java:53) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15814) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableReduceSeedSingle.subscribeActual(FlowableReduceSeedSingle.java:50) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.single.SingleUsing.subscribeActual(SingleUsing.java:83) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribeWith(Single.java:4863) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.toCompletionStage(Single.java:5635) [rxjava-3.0.13.jar:] at org.infinispan.persistence.manager.PersistenceManagerImpl.deleteFromAllStores(PersistenceManagerImpl.java:729) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.deleteFromStoresAndNotify(ExpirationManagerImpl.java:229) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.lambda$handleInStoreExpirationInternal$1(ExpirationManagerImpl.java:194) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.lambda$compute$1(AbstractInternalDataContainer.java:229) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$remap$16(BoundedLocalCache.java:2507) [caffeine-2.8.8.jar:] at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1853) [rt.jar:1.8.0_275] at com.github.benmanes.caffeine.cache.BoundedLocalCache.remap(BoundedLocalCache.java:2502) [caffeine-2.8.8.jar:] at com.github.benmanes.caffeine.cache.BoundedLocalCache.compute(BoundedLocalCache.java:2454) [caffeine-2.8.8.jar:] at com.github.benmanes.caffeine.cache.LocalCache.compute(LocalCache.java:95) [caffeine-2.8.8.jar:] at org.infinispan.commons.util.AbstractDelegatingMap.compute(AbstractDelegatingMap.java:81) [infinispan-commons-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:228) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:245) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:190) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:186) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.manager.PersistenceManagerImpl.lambda$purgeExpired$24(PersistenceManagerImpl.java:676) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:187) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.mixed.ConcatMapXMainSubscriber.onNext(ConcatMapXMainSubscriber.java:104) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.drainFused(UnicastProcessor.java:349) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.drain(UnicastProcessor.java:382) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.onNext(UnicastProcessor.java:444) [rxjava-3.0.13.jar:] at org.infinispan.persistence.support.NonBlockingStoreAdapter$1.entryPurged(NonBlockingStoreAdapter.java:172) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.purge(JdbcStringBasedStore.java:603) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.spi.SegmentedAdvancedLoadWriteStore.purge(SegmentedAdvancedLoadWriteStore.java:182) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.lambda$purgeExpired$2(NonBlockingStoreAdapter.java:179) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1640) [rt.jar:1.8.0_275] at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.as.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49) at org.jboss.as.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:70) at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_275] Caused by: oracle.net.ns.NetException: Socket read timed out at oracle.net.ns.Packet.receive(Packet.java:359) at oracle.net.ns.DataPacket.receive(DataPacket.java:128) at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) at oracle.net.ns.NetInputStream.read(NetInputStream.java:257) at oracle.net.ns.NetInputStream.read(NetInputStream.java:177) at oracle.net.ns.NetInputStream.read(NetInputStream.java:95) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:132) at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:88) at oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:395) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:410) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:269) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:655) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:270) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:91) at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:970) ... 67 more2022-06-01 15:15:00,322 WARN [org.infinispan.PERSISTENCE] (blocking-thread--p20-t4) [bcID=;user=;device=] ISPN008022: Unexpected sql failure: java.sql.SQLRecoverableException: Getrennte Verbindung at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:3556) at oracle.jdbc.driver.OracleStatement.closeOrCache(OracleStatement.java:1478) at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1461) at oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:122) at oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:98) at org.jboss.jca.adapters.jdbc.WrappedStatement.internalClose(WrappedStatement.java:1481) at org.jboss.jca.adapters.jdbc.WrappedStatement.close(WrappedStatement.java:178) at org.infinispan.persistence.jdbc.JdbcUtil.safeClose(JdbcUtil.java:26) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.delete(JdbcStringBasedStore.java:574) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.delete(JdbcStringBasedStore.java:552) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.lambda$delete$10(NonBlockingStoreAdapter.java:227) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlockingOperation(BlockingManagerImpl.java:139) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlocking(BlockingManagerImpl.java:130) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.delete(NonBlockingStoreAdapter.java:226) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.manager.PersistenceManagerImpl.lambda$deleteFromAllStores$30(PersistenceManagerImpl.java:724) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onNext(FlowableFlatMapSingle.java:118) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFilter$FilterSubscriber.tryOnNext(FlowableFilter.java:74) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$IteratorConditionalSubscription.fastPath(FlowableFromIterable.java:321) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:129) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.request(BasicFuseableSubscriber.java:153) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onSubscribe(FlowableFlatMapSingle.java:106) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.onSubscribe(BasicFuseableSubscriber.java:67) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:66) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFilter.subscribeActual(FlowableFilter.java:37) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle.subscribeActual(FlowableFlatMapSingle.java:53) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15868) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15814) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.flowable.FlowableReduceSeedSingle.subscribeActual(FlowableReduceSeedSingle.java:50) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.single.SingleUsing.subscribeActual(SingleUsing.java:83) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.subscribeWith(Single.java:4863) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.core.Single.toCompletionStage(Single.java:5635) [rxjava-3.0.13.jar:] at org.infinispan.persistence.manager.PersistenceManagerImpl.deleteFromAllStores(PersistenceManagerImpl.java:729) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.deleteFromStoresAndNotify(ExpirationManagerImpl.java:229) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.lambda$handleInStoreExpirationInternal$1(ExpirationManagerImpl.java:194) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.lambda$compute$1(AbstractInternalDataContainer.java:229) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$remap$16(BoundedLocalCache.java:2507) [caffeine-2.8.8.jar:] at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1853) [rt.jar:1.8.0_275] at com.github.benmanes.caffeine.cache.BoundedLocalCache.remap(BoundedLocalCache.java:2502) [caffeine-2.8.8.jar:] at com.github.benmanes.caffeine.cache.BoundedLocalCache.compute(BoundedLocalCache.java:2454) [caffeine-2.8.8.jar:] at com.github.benmanes.caffeine.cache.LocalCache.compute(LocalCache.java:95) [caffeine-2.8.8.jar:] at org.infinispan.commons.util.AbstractDelegatingMap.compute(AbstractDelegatingMap.java:81) [infinispan-commons-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:228) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:245) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:190) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:186) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.manager.PersistenceManagerImpl.lambda$purgeExpired$24(PersistenceManagerImpl.java:676) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:187) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.internal.operators.mixed.ConcatMapXMainSubscriber.onNext(ConcatMapXMainSubscriber.java:104) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.drainFused(UnicastProcessor.java:349) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.drain(UnicastProcessor.java:382) [rxjava-3.0.13.jar:] at io.reactivex.rxjava3.processors.UnicastProcessor.onNext(UnicastProcessor.java:444) [rxjava-3.0.13.jar:] at org.infinispan.persistence.support.NonBlockingStoreAdapter$1.entryPurged(NonBlockingStoreAdapter.java:172) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.purge(JdbcStringBasedStore.java:603) [infinispan-cachestore-jdbc-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.spi.SegmentedAdvancedLoadWriteStore.purge(SegmentedAdvancedLoadWriteStore.java:182) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at org.infinispan.persistence.support.NonBlockingStoreAdapter.lambda$purgeExpired$2(NonBlockingStoreAdapter.java:179) [infinispan-core-12.1.7.Final.jar:12.1.7.Final] at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1640) [rt.jar:1.8.0_275] at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377) [jboss-threads-2.4.0.Final.jar:2.4.0.Final] at org.jboss.as.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49) at org.jboss.as.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:70) at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_275]
My cache configuration is:
<local-cache name="config_cache"> <transaction locking="PESSIMISTIC" mode="NON_XA"/> <heap-memory size="10000"/> <expiration lifespan="-1" max-idle="5184000000"/> <jdbc-store data-source="lisaDS" dialect="ORACLE" passivation="false" preload="false" purge="false"> <table prefix="jboss"> <id-column name="ID" type="VARCHAR(4000)"/> <data-column name="DATA" type="BLOB"/> <timestamp-column name="TIMESTAMP" type="NUMBER"/> </table> </jdbc-store> </local-cache>
The error is reproducible, the are no network problems and other sql queries perform fine at the same time. Infinispan is using the same datasource definition as all other modules, so I assume it is not a configuration problem.
The trace log gives some details on what is happening:
15:14:00,200 TRACE [org.infinispan.expiration.impl.ExpirationManagerImpl] (expiration-thread--p22-t1) Purging data container of expired entries 15:14:00,205 TRACE [org.infinispan.expiration.impl.ExpirationManagerImpl] (expiration-thread--p22-t1) Purging data container completed in 2 milliseconds 15:14:00,207 TRACE [org.infinispan.persistence.manager.PersistenceManagerImpl] (expiration-thread--p22-t1) Purging entries from stores 15:14:00,254 TRACE [org.infinispan.persistence.keymappers.DefaultTwoWayKey2StringMapper] (blocking-thread--p20-t4) Get mapping for key: attachment.download.valid.content.type.list:mobile:lisa:-100000000000000 15:14:00,269 TRACE [org.infinispan.persistence.manager.PersistenceManagerImpl] (blocking-thread--p20-t4) Deleting entry for key attachment.download.valid.content.type.list:mobile:lisa:-100000000000000 from stores 15:14:00,275 TRACE [org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore] (blocking-thread--p20-t4) Running sql 'DELETE FROM "jboss_config_cache" WHERE ID = ?' on attachment.download.valid.content.type.list:mobile:lisa:-100000000000000
It seams to be the DELETE query running in a timeout of 1 minute. Further analysis on the Oracle database showed a row lock contention problem on the caching table:
OBJECT_NAME | LOCK_MODE | EVENT | WAIT_CLASS | USERNAME | WAIT_COUNT | FIRST_WAIT | LAST_WAIT | WAIT_TIME_MS -------------------+-----------+-------------------------------+-------------+------------+------------+-------------------------+-------------------------+------------- jboss_config_cache | Exclusive | enq: TX - row lock contention | Application | LISA_OWNER | 60 | 2022-05-31 16:22:20.285 | 2022-05-31 16:23:19.566 | 60037.08
The rows are locked by another query which belongs to the periodic expiration management process:
SELECT DATA, ID
FROM
"jboss_config_cache" WHERE TIMESTAMP < :1 AND TIMESTAMP > 0 FOR UPDATE
followed by
DELETE FROM "jboss_config_cache" WHERE ID = :1
The process takes more than 1 Min (for 7 entries) and blocks all other queries operating on the same rows.
SELECT DATA, ID
FROM
"jboss_config_cache" WHERE TIMESTAMP < :1 AND TIMESTAMP > 0 FOR UPDATE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 2 9 0
Fetch 1 0.00 0.00 0 14 0 7
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 16 9 7
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 149
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
7 7 7 FOR UPDATE (cr=2 pr=0 pw=0 time=342 us starts=1)
14 14 14 BUFFER SORT (cr=2 pr=0 pw=0 time=160 us starts=2)
7 7 7 FILTER (cr=2 pr=0 pw=0 time=128 us starts=1)
7 7 7 TABLE ACCESS BY INDEX ROWID BATCHED jboss_config_cache (cr=2 pr=0 pw=0 time=124 us starts=1 cost=2 size=1302 card=7)
7 7 7 INDEX RANGE SCAN IDX_jboss_config_cache (cr=1 pr=0 pw=0 time=66 us starts=1 cost=1 size=0 card=7)(object id 437545)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 60.08 60.10
PGA memory operation 4 0.00 0.00
********************************************************************************
It is the "SQL*Net message from client" which takes the time. I assume that there is a loop where all expired entries are deleted one by one and this loop is slow for some reason. The single DELETE statements are executed fast once transmitted to Oracle:
DELETE FROM "jboss_config_cache" WHERE ID = :1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.00 0 14 52 7 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 0.00 0.00 0 14 52 7
My attempt to disable the expiration thread by setting wakeup interval="-1" in cache definition (Wildfly) was unsuccessful, it seams that the parameter is simply ignored and the thread is running every minute.
Attachments
Issue Links
- duplicates
-
-
- Closed
-
