Uploaded image for project: 'Infinispan'
  1. Infinispan
  2. ISPN-13487

Deadlock in JDBC Store expiration

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: Major Major
    • None
    • 13.0.2.Final
    • Loaders and Stores
    • 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?

              wburns@redhat.com Will Burns
              developusmaximus James Baxter (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: