-
Bug
-
Resolution: Duplicate
-
Major
-
None
-
13.0.2.Final
-
None
There appears to be a deadlock in expiration of entries from the JDBC store. A minimal reproduction looks like this:
final Configuration configuration = new ConfigurationBuilder() .memory().maxCount(5) .expiration().lifespan(30, SECONDS) .persistence() .addStore(JdbcStringBasedStoreConfigurationBuilder.class) .table() .createOnStart(true) .tableNamePrefix("infinispan_cache") .idColumnName("id").idColumnType("VARCHAR(255)") .dataColumnName("data").dataColumnType("BYTEA") .timestampColumnName("entry_timestamp").timestampColumnType("BIGINT") .segmentColumnName("segment").segmentColumnType("INT") .connectionPool() .driverClass("org.h2.Driver") .connectionUrl("jdbc:h2:mem:test") .username("sa") .password("") .build(); final GlobalConfiguration globalConfiguration = new GlobalConfigurationBuilder().defaultCacheName("default-cache").build(); try (EmbeddedCacheManager cacheManager = new DefaultCacheManager(globalConfiguration, configuration)) { Cache<String, String> cache = cacheManager.getCache(); for (int i = 0; i < 10; i++) { cache.put("key" + i, "value" + i); } for (int i = 0; i < 10; i++) { String v = cache.get("key" + i); log.debug("value = {}", v); } // Let's see what happens if we try to access the cache once the expiration process deadlocks the database System.in.read(new byte[1]); for (int i = 0; i < 10; i++) { String v = cache.computeIfAbsent("key" + i, key -> "value" + key); log.debug("value = {}", v); } }
After waiting for the eviction thread to run:
"expiration-thread--p5-t1" #27 daemon prio=5 os_prio=0 cpu=15.62ms elapsed=62.37s tid=0x000001e0d6e58510 nid=0x4534 waiting on condition [0x000000c7dfdfe000]"expiration-thread--p5-t1" #27 daemon prio=5 os_prio=0 cpu=15.62ms elapsed=62.37s tid=0x000001e0d6e58510 nid=0x4534 waiting on condition [0x000000c7dfdfe000] java.lang.Thread.State: TIMED_WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@17/Native Method) - parking to wait for <0x0000000623e78100> (a java.util.concurrent.CompletableFuture$Signaller) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17/LockSupport.java:252) at java.util.concurrent.CompletableFuture$Signaller.block(java.base@17/CompletableFuture.java:1866) at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17/ForkJoinPool.java:3463) at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17/ForkJoinPool.java:3434) at java.util.concurrent.CompletableFuture.timedGet(java.base@17/CompletableFuture.java:1939) at java.util.concurrent.CompletableFuture.get(java.base@17/CompletableFuture.java:2095) at org.infinispan.util.concurrent.CompletableFutures.await(CompletableFutures.java:126) at org.infinispan.util.concurrent.CompletionStages.join(CompletionStages.java:83) at org.infinispan.expiration.impl.ExpirationManagerImpl.processExpiration(ExpirationManagerImpl.java:122) at org.infinispan.expiration.impl.ExpirationManagerImpl$ScheduledTask.run(ExpirationManagerImpl.java:278) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17/Executors.java:539) at java.util.concurrent.FutureTask.runAndReset(java.base@17/FutureTask.java:305) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@17/ScheduledThreadPoolExecutor.java:305) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17/ThreadPoolExecutor.java:1136) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17/ThreadPoolExecutor.java:635) at java.lang.Thread.run(java.base@17/Thread.java:833)
We see the Future it is waiting for running on a background thread:
"blocking-thread--p3-t1" #28 daemon prio=5 os_prio=0 cpu=156.25ms elapsed=69.76s tid=0x0000015d017e0970 nid=0x8c70 in Object.wait() [0x00000039025fd000]"blocking-thread--p3-t1" #28 daemon prio=5 os_prio=0 cpu=156.25ms elapsed=69.76s tid=0x0000015d017e0970 nid=0x8c70 in Object.wait() [0x00000039025fd000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(java.base@17/Native Method) - waiting on <0x0000000623c311b0> (a org.h2.mvstore.tx.Transaction) at org.h2.mvstore.tx.Transaction.waitForThisToEnd(Transaction.java:804) - locked <0x0000000623c311b0> (a org.h2.mvstore.tx.Transaction) at org.h2.mvstore.tx.Transaction.waitFor(Transaction.java:773) at org.h2.mvstore.tx.TransactionMap.set(TransactionMap.java:314) at org.h2.mvstore.tx.TransactionMap.lock(TransactionMap.java:263) at org.h2.mvstore.db.MVPrimaryIndex.lockRow(MVPrimaryIndex.java:230) at org.h2.mvstore.db.MVPrimaryIndex.lockRow(MVPrimaryIndex.java:224) at org.h2.mvstore.db.MVTable.lockRow(MVTable.java:567) at org.h2.command.dml.Delete.update(Delete.java:116) at org.h2.command.CommandContainer.update(CommandContainer.java:198) at org.h2.command.Command.executeUpdate(Command.java:251) - locked <0x0000000623c63488> (a org.h2.engine.Session) at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:191) - locked <0x0000000623c63488> (a org.h2.engine.Session) at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:152) at io.agroal.pool.wrapper.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:88) at org.infinispan.persistence.jdbc.common.sql.BaseTableOperations.deleteEntry(BaseTableOperations.java:107) at org.infinispan.persistence.jdbc.common.impl.BaseJdbcStore.lambda$delete$5(BaseJdbcStore.java:160) at org.infinispan.persistence.jdbc.common.impl.BaseJdbcStore$$Lambda$410/0x0000000800f7b888.get(Unknown Source) at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlockingOperation(BlockingManagerImpl.java:139) at org.infinispan.util.concurrent.BlockingManagerImpl.supplyBlocking(BlockingManagerImpl.java:130) at org.infinispan.persistence.jdbc.common.impl.BaseJdbcStore.delete(BaseJdbcStore.java:156) at org.infinispan.persistence.manager.PersistenceManagerImpl.deleteFromAllStores(PersistenceManagerImpl.java:678) at org.infinispan.expiration.impl.ExpirationManagerImpl.deleteFromStoresAndNotify(ExpirationManagerImpl.java:211) at org.infinispan.expiration.impl.ExpirationManagerImpl.lambda$handleInStoreExpirationInternal$1(ExpirationManagerImpl.java:176) at org.infinispan.expiration.impl.ExpirationManagerImpl$$Lambda$416/0x0000000800f7f838.compute(Unknown Source) at org.infinispan.container.impl.AbstractInternalDataContainer.lambda$compute$1(AbstractInternalDataContainer.java:229) at org.infinispan.container.impl.AbstractInternalDataContainer$$Lambda$400/0x0000000800f78970.apply(Unknown Source) at com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$remap$16(BoundedLocalCache.java:2505) at com.github.benmanes.caffeine.cache.BoundedLocalCache$$Lambda$401/0x0000000800f79170.apply(Unknown Source) at java.util.concurrent.ConcurrentHashMap.compute(java.base@17/ConcurrentHashMap.java:1916) - locked <0x0000000623c3ecb0> (a java.util.concurrent.ConcurrentHashMap$ReservationNode) at com.github.benmanes.caffeine.cache.BoundedLocalCache.remap(BoundedLocalCache.java:2500) at com.github.benmanes.caffeine.cache.BoundedLocalCache.compute(BoundedLocalCache.java:2452) at com.github.benmanes.caffeine.cache.LocalCache.compute(LocalCache.java:95) at org.infinispan.commons.util.AbstractDelegatingMap.compute(AbstractDelegatingMap.java:81) at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:228) at org.infinispan.container.impl.AbstractInternalDataContainer.compute(AbstractInternalDataContainer.java:245) at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:172) at org.infinispan.expiration.impl.ExpirationManagerImpl.handleInStoreExpirationInternal(ExpirationManagerImpl.java:168) at org.infinispan.persistence.manager.PersistenceManagerImpl.lambda$purgeExpired$25(PersistenceManagerImpl.java:616) at org.infinispan.persistence.manager.PersistenceManagerImpl$$Lambda$414/0x0000000800f7e440.apply(Unknown Source) at io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:226) at io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.onNext(FlowableConcatMapCompletable.java:117) at io.reactivex.rxjava3.processors.UnicastProcessor.drainRegular(UnicastProcessor.java:309) at io.reactivex.rxjava3.processors.UnicastProcessor.drain(UnicastProcessor.java:384) at io.reactivex.rxjava3.processors.UnicastProcessor.onNext(UnicastProcessor.java:444) at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.lambda$purgeExpired$0(JdbcStringBasedStore.java:291) at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore$$Lambda$415/0x0000000800f7f618.run(Unknown Source) at org.infinispan.util.concurrent.BlockingManagerImpl.lambda$runBlockingOperation$2(BlockingManagerImpl.java:120) at org.infinispan.util.concurrent.BlockingManagerImpl$$Lambda$334/0x0000000800e97978.run(Unknown Source) at java.util.concurrent.CompletableFuture$AsyncRun.run(java.base@17/CompletableFuture.java:1804) at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377) at java.lang.Thread.run(java.base@17/Thread.java:833)
Looking at JdbcStringBasedStore.java:291 we can see it has an open connection having run the following SQL on line 262.
SELECT data, id FROM "infinispan_cache_default_cache" WHERE entry_timestamp < $1 AND entry_timestamp > 0 FOR UPDATE
Down the stack through BaseJdbcStore.java:160 we can see another connection is acquired, and on BaseTableOperations.java:107 we can see the following SQL is executed:
DELETE FROM "infinispan_cache_default_cache" WHERE id = cast($1 as VARCHAR(255))
That second query can't complete due to the lock in the first connection.
Am I missing something fundamental?
- relates to
-
ISPN-11110 JdbcStringBasedStore Purge should not use FOR UPDATE to avoid excessive locking
- Closed