Loading...

XML

Word

Printable

Type: Bug
Resolution: Duplicate
Priority: Major
Fix Version/s: None
Affects Version/s: 12.1.7.Final
Component/s: Expiration, Loaders and Stores
Labels:
None

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.

duplicates

ISPN-11110 JdbcStringBasedStore Purge should not use FOR UPDATE to avoid excessive locking

Closed

Assignee:: Unassigned

Reporter:: Alexander Rieger (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Created:: 2022/06/02 8:45 AM

Updated:: 2022/06/03 4:29 PM

Resolved:: 2022/06/03 4:29 PM

Details

Description

Attachments

Issue Links

Easy Agile Planning Poker

Activity

People

Dates