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

EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead random failures

    Details

      Description

      According to the code comments, the test is supposed to block the put(evicted-key) operation before releasing the orderer, but because of operationCheckPoint.trigger(Mocks.BEFORE_RELEASE) it only blocks after releasing the orderer. This means the eviction triggered by put(other-key) and the activation triggered later by get(evicted-key) are not blocked.

      All three operations eventually call operationCheckPoint.awaitStrict(Mocks.BEFORE_RELEASE). The test triggers that event twice, so it unblocks put(evicted-key) and one of put(other-key)/get(evicted-key). The two unblocked operations then compete for a single Mocks.AFTER_RELEASE event.

      If put(evicted-key) receives the Mocks.AFTER_RELEASE event, the test passes, because the other operations can finish without waiting for the activation/passivation to finish. (It just needs to be queued in )

      Because CheckPoint doesn't guarantee waiters receive events in the queueing order, either put(other-key, "value", or get(evicted-key) could receive the AFTER_RELEASE event from put(evicted-key, "value"), making it time out.

      19:53:59,795 TRACE (ForkThread-1,Test:[]) [InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=evicted-key, value=value, flags=[SKIP_CACHE_LOAD], commandInvocationId=CommandInvocation:<local>:37070, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{version=null, lifespan=-1, maxIdle=-1}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:<local>:37070}]
      19:53:59,807 TRACE (non-blocking-thread-Test-NodeK-p23146-t1:[]) [DataOperationOrderer] Ordered future java.util.concurrent.CompletableFuture@76d1e6bc[Not completed] is completed for key evicted-key from op WRITE
      19:53:59,811 TRACE (non-blocking-thread-Test-NodeK-p23146-t1:[]) [CheckPoint] Waiting for event post_released * 1
      

      ^ put(evicted-key) is blocked

      19:53:59,807 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=other-key, value=other-value, flags=[], commandInvocationId=CommandInvocation:<local>:37073, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{version=null, lifespan=-1, maxIdle=-1}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:<local>:37073}]
      19:53:59,816 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [AbstractInternalDataContainer] Store other-key=ImmortalCacheEntry{key=other-key, value=other-value, internalMetadata=null} in container
      19:53:59,817 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [DataOperationOrderer] Ordering upcoming future java.util.concurrent.CompletableFuture@32541e18[Not completed] for key evicted-key to run after null
      

      ^ put(other-key) is not blocked here

      19:53:59,818 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [PassivationManagerImpl] Passivating entry evicted-key
      19:53:59,818 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [PersistenceManagerImpl] Writing to all stores for id 67588
      19:53:59,841 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CompletionStages] Continuing execution of id 67588
      19:53:59,844 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CheckPoint] Waiting for event pre_released * 1
      

      ^ put(other-key) blocks in the checkpoint

      19:53:59,956 TRACE (testng-Test:[]) [CheckPoint] Triggering event pre_released * 1 (available = 1, total = 2)
      19:53:59,956 TRACE (testng-Test:[]) [CheckPoint] Triggering event post_released * 1 (available = 1, total = 1)
      19:53:59,956 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CheckPoint] Received event pre_released * 1 (available = 0, total = 2)
      

      ^ put(other-key) is unblocked, put(evicted-key) stays blocked

      19:54:09,998 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.eviction.impl.EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead
      java.util.concurrent.TimeoutException: null
      	at java.util.concurrent.FutureTask.get(FutureTask.java:204) ~[?:?]
      	at org.infinispan.eviction.impl.EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead(EvictionWithPassivationAndConcurrentOperationsTest.java:99) ~[test-classes/:?]
      

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                dan.berindei Dan Berindei
                Reporter:
                dan.berindei Dan Berindei
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: