9 Replies Latest reply on May 22, 2012 12:50 PM by galder.zamarreno

    Lost update in infinispan tree cache

    martinluene

      In following scenario, i observe a lost update with Infinispan 5.1.2.FINAL (within JBoss7.1.1 standalone):

       

      Two asynchronous executions are started concurrently by the same event

      Thread1 performs

          org.infinispan.tree.TreeCache treeCache = ...; configured MyCache programmatically before

          treeCache.put("EntryArea/635007/635011/1", myKey, value);

      Thread2 performs around the same time on the same treeCache:

          treeCache.put("EntryArea/635007/635011/2", myKey, otherValue);

         

      Later a further thread retrieves the subtree below "EntryArea/635007".

         Node<String, Object> node = getNode("EntryArea/635007");

         Set<Node<String, Object>> childNodes = node.getChildren();

      Only one child is found.

       

      Both nodes themself are in the cache, independent of the structure part:

          getNode("EntryArea/635007/635011/1"); yields the expected result with the stored "myKey - value".

          getNode("EntryArea/635007/635011/2"); yields the expected result with the stored "myKey - otherValue".

         

      What can be wrong with my scenario?

      Any hints are welcome.

       

      Martin

        • 1. Re: Lost update in infinispan tree cache
          galder.zamarreno

          Sounds like a bug. I'd suggest:

           

          1. Try with latest release, 5.1.4.FINAL

          2. If that fails, can you create a test case? Our maven archetypes can help.

          • 2. Re: Lost update in infinispan tree cache
            martinluene

            I tried with JBoss7.1 nightly build from Monday. 7.May.2012, which contains Infinispan 5.1.4.FINAL and the lost update still occurs:

            Only one node is found via the structure part, but both nodes are in the cache.

             

            I will look now for the maven archetypes.

            Is there a similar test case, which i can reuse for this scenario?

            • 4. Re: Lost update in infinispan tree cache
              martinluene

              I installed maven and setup the infinispan testcase-archetype which is at this stage about infinispan without the infinispan-tree adapter.

              It looks great, but now i'm a bit confused, because i get a lost update, even without using the infinispan-tree.

              My testclass is added below.

              With optimistic locking my thread1 commit finally succeeds, although thread2 changed and committed the same entry in between.

              By this the change of thread2 is lost, the expected concurrency exception in thread1 has not occurred!

               

              In the pom.xml i found the transaction manager property, and changed it to get real transactions:

                      <infinispan.test.jta.tm>jbosstm</infinispan.test.jta.tm>

              But this doesn't change the behaviour of my test.

                     

              With LockingMode.PESSIMISTIC i can avoid the lost update:

                  Using cache.withFlags(Flag.FORCE_WRITE_LOCK).get(key) the second thread is blocked and gets the value as changed by the other thread.

                  But we think optimisitc locking is also supported by infinispan.

                     

              What else to adapt, to see an exception about a concurrent access violation?

              Or is my configuration still incomplete? Is there a test for optimistic concurreny?

               

              Here the log from the maven console and below my test class with the cache configuration.

               

              Thanks,

              Martin

               

              2012-05-15 12:18:36,302 INFO  [org.infinispan.test.fwk.UnitTestTestNGListener] (testng-SampleUnitTest) Starting test testParallelAccess(org.infinispan.SampleUnitTest)

              2012-05-15 12:18:36,333 INFO  [org.infinispan.SampleUnitTest] (testng-SampleUnitTest)  testParallelAccess: with transaction management=jbosstm

              2012-05-15 12:18:36,333 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-1219597201) Thread1 BeginTx      key=oneOxK%fKey value=base

              2012-05-15 12:18:36,333 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-1219597201) Thread1 Put          key=oneOxK%fKey value=baseModify1

              2012-05-15 12:18:36,333 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-1219597201) Thread1 AfterPut     key=oneOxK%fKey value=baseModify1

              2012-05-15 12:18:36,445 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-552561490) Thread2 BeginTx      key=oneOxK%fKey value=base

              2012-05-15 12:18:36,445 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-552561490) Thread2 Put          key=oneOxK%fKey value=baseModify2

              2012-05-15 12:18:36,445 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-552561490) Thread2 AfterPut     key=oneOxK%fKey value=baseModify2

              2012-05-15 12:18:36,445 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-552561490) Thread2 BeforeCommit key=oneOxK%fKey value=baseModify2

              2012-05-15 12:18:36,445 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-552561490) Thread2 AfterCommit  key=oneOxK%fKey value=baseModify2

              2012-05-15 12:18:37,662 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-552561490) Thread2 ReRead       key=oneOxK%fKey value=baseModify2

              2012-05-15 12:18:39,379 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-1219597201) Thread1 BeforeCommit key=oneOxK%fKey value=baseModify1

              2012-05-15 12:18:39,379 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-1219597201) Thread1 AfterCommit  key=oneOxK%fKey value=baseModify1

              2012-05-15 12:18:39,583 INFO  [org.infinispan.SampleUnitTest] (ForkThread-SampleUnitTest-1219597201) Thread1 ReRead       key=oneOxK%fKey value=baseModify1

              2012-05-15 12:18:39,583 ERROR [org.infinispan.test.fwk.UnitTestTestNGListener] (testng-SampleUnitTest) Method testParallelAccess(org.infinispan.SampleUnitTest) threw an exception

              java.lang.AssertionError: Was expecting 'baseModify2' but saw 'baseModify1' instead!

                  at org.infinispan.SampleUnitTest.testParallelAccess(SampleUnitTest.java:118)

                 

               

              ---Begin---------------------- src/test/java/org/infinispan/SampleUnitTest.java ----------------

              package org.infinispan;

               

              import org.infinispan.context.Flag;

              import org.infinispan.configuration.cache.CacheMode;

              import org.infinispan.configuration.cache.ConfigurationBuilder;

              import org.infinispan.manager.EmbeddedCacheManager;

              import org.infinispan.test.SingleCacheManagerTest;

              import org.infinispan.test.fwk.TestCacheManagerFactory;

              import org.infinispan.test.fwk.TransactionSetup;

              import org.infinispan.transaction.LockingMode;

              import org.infinispan.util.concurrent.IsolationLevel;

              import org.testng.annotations.AfterMethod;

              import org.testng.annotations.BeforeMethod;

              import org.testng.annotations.Test;

               

              // ****************************************************************************************

              // This sample test should be used as a starting point when writing tests for Infinispan.

              //

              // See http://community.jboss.org/wiki/ParallelTestSuite for more information.

              // Moved, now see https://docs.jboss.org/author/display/ISPN/Contributing+to+Infinispan#ContributingtoInfinispan-TheParallelTestSuite

              // ****************************************************************************************

               

              @Test(groups = "unit", testName = "SampleUnitTest")

              public class SampleUnitTest extends SingleCacheManagerTest {

                  //    TreeCache<K, V>

                  static String resultThread1 = "";

                  static String resultThread2 = "";

               

                  @Override

                  protected EmbeddedCacheManager createCacheManager() throws Exception {

                      // Activate transactions

                      ConfigurationBuilder builder = getDefaultStandaloneCacheConfig(true); // transactional

                      builder.transaction().lockingMode(LockingMode.OPTIMISTIC);

              //        builder.transaction().lockingMode(LockingMode.PESSIMISTIC); // expected behaviour gained with code adaption below.

                      builder.locking().isolationLevel(IsolationLevel.READ_COMMITTED);

                      builder.locking().lockAcquisitionTimeout(5000);

                      builder.invocationBatching().enable();

                      builder.clustering().cacheMode(CacheMode.LOCAL);

                      EmbeddedCacheManager cm = TestCacheManagerFactory.createCacheManager(builder);

                      return cm;

                  }

               

                  @BeforeMethod

                  public void setUp() {

                  }

               

                  @AfterMethod

                  public void tearDown() {

                  }

               

                  public class CacheWorker implements Runnable {

                      String key;

                      int threadNumber;

               

                      public CacheWorker(int threadNumber, String key) {

                          this.key = key;

                          this.threadNumber = threadNumber;

                      }

               

                      @Override

                      public void run() {

                          String prefix = "Thread" + threadNumber;

                          try {

                              tm().begin();

                              log.info(prefix + " BeginTx     " + " key=" + key + " value=" + cache.get(key));

                              String oldValue = (String) cache.get(key); // optimistic

                              // For pessimistic locking, using the following line avoids the lost update:

              //                String oldValue = (String) cache.getAdvancedCache().withFlags(Flag.FORCE_WRITE_LOCK).get(key);

                              String value = oldValue + "Modify" + threadNumber;

                              log.info(prefix + " Put         " + " key=" + key + " value=" + value);

                              cache.put(key, value);

                              log.info(prefix + " AfterPut    " + " key=" + key + " value=" + cache.get(key));

                              // First thread 1 begins transaction and puts its value and waits.

                              if (threadNumber == 1) {

                                  Thread.sleep(3000);

                              }

                              log.info(prefix + " BeforeCommit" + " key=" + key + " value=" + cache.get(key));

                              tm().commit();

                              log.info(prefix + " AfterCommit " + " key=" + key + " value=" + cache.get(key));

                              Thread.sleep(200);

                              // Thread 2 starts delayed (see below), begins transaction, puts its value, commits.

                              if (threadNumber == 2) {

                                  Thread.sleep(1000); // Wait two times the lockAcquisitionTimeout, but no lock seems to be present.

                              }

                              // Then thread 1 commits and finally both threads check the value finally in the cache.

                              log.info(prefix + " ReRead      " + " key=" + key + " value=" + cache.get(key));

                          } catch (Exception e) {

                              try {

                                  tm().rollback();

                              } catch (Exception e1) {

                                  // maybe rollback already done, continue with original exception.

                              }

                              e.printStackTrace();

                              log.info(prefix + " expected exception: " + e.getMessage());

                          }

                      }

                  }

               

                  public void testParallelAccess() throws Exception {

                      log.info(" testParallelAccess: with transaction management=" + TransactionSetup.JTA);

               

                      String key = "oneOxK%fKey";

               

                      cache.put(key, "base");

               

                      Runnable run1 = new CacheWorker(1, key);

                      Runnable run2 = new CacheWorker(2, key);

               

                      Thread thread1 = fork(run1, false);

                      Thread.sleep(100); // start thread2 after delay.

                      Thread thread2 = fork(run2, false);

               

                      thread1.join();

                      thread2.join();

               

                      // Expect value from thread2, because it commits first, thread1 shall get a concurrency exception.

                      Object result = cache.get(key);

                      assert "baseModify2".equals(result) : "Was expecting 'baseModify2' but saw '"

                              + String.valueOf(result) + "' instead!";

                  }

              }

              --End----------------------- src/test/java/org/infinispan/SampleUnitTest.java ----------------

              • 5. Re: Lost update in infinispan tree cache
                galder.zamarreno

                Your problem is Manik's reply on 2010/04/01 in http://architects.dzone.com/articles/infinispan-power-user-cache-mode

                 

                Basically, with READ_COMMITTED, it takes the last committed version. If you need this kind of concurrency issues to be detected with optimistic locking, either switch to REPEATABLE_READ, or enable writeSkew checks.

                • 6. Re: Lost update in infinispan tree cache
                  martinluene

                  Thanks, Galder, yes, i need writeSkew checks;

                  And since writeSkew checks require REPEATABLE_READ and versioning, i added that too:

                   

                  ConfigurationBuilder builder ...;

                  builder.locking().isolationLevel(IsolationLevel.REPEATABLE_READ);

                  builder.locking().writeSkewCheck(true);

                  builder.locking().versioning().enable();

                  builder.locking().versioning().scheme(VersioningScheme.SIMPLE);

                   

                  With this configuration, my test logs according messages: "org.infinispan.CacheException: Detected write skew."

                  But the transaction commits anyway, no exception arrives at my test program, here the last part of the error logs:

                   

                  2012-05-21 10:32:02,272 ERROR [DummyTransaction] (ForkThread-SampleUnitTest-410880172)

                  ISPN000109: beforeCompletion() failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false,

                  transaction=DummyTransaction{xid=DummyXid{id=2}, status=1}, lockedKeys=null, backupKeyLocks=null, viewId=-1}

                  org.infinispan.transaction.synchronization.SyncLocalTransaction@2} org.infinispan.transaction.synchronization.SynchronizationAdapter@21

                  org.infinispan.CacheException: Could not prepare.

                      at org.infinispan.transaction.synchronization.SynchronizationAdapter.beforeCompletion(SynchronizationAdapter.java:70)

                      at org.infinispan.transaction.tm.DummyTransaction.notifyBeforeCompletion(DummyTransaction.java:230)

                      at org.infinispan.transaction.tm.DummyTransaction.runPrepare(DummyTransaction.java:241)

                      at org.infinispan.transaction.tm.DummyTransaction.commit(DummyTransaction.java:86)

                      at org.infinispan.transaction.tm.DummyBaseTransactionManager.commit(DummyBaseTransactionManager.java:102)

                      at org.infinispan.SampleUnitTest$CacheWorker.run(SampleUnitTest.java:83)

                      at org.infinispan.test.AbstractInfinispanTest$RunnableWrapper.run(AbstractInfinispanTest.java:112)

                      at java.lang.Thread.run(Thread.java:662)

                  Caused by: javax.transaction.xa.XAException

                      at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:160)

                      at org.infinispan.transaction.TransactionCoordinator.prepare(TransactionCoordinator.java:122)

                      at org.infinispan.transaction.synchronization.SynchronizationAdapter.beforeCompletion(SynchronizationAdapter.java:68)

                      ... 7 more

                     

                  Is this a feature of DummyTransaction?

                  I found the exception is catched in DummyTransaction.notifyBeforeCompletion() and the status becomes STATUS_ROLLING_BACK,

                  Then, in DummyTransaction.runPrepare(), "false" is only returned, if an enlisted resource complains.

                  But if there is no resource, at the end of DummyTransaction.runPrepare the status is restored. ??

                   

                  Anyway, i will test the corrected configuration also in my JBoss7.1.1.FINAL installation.

                  • 7. Re: Lost update in infinispan tree cache
                    martinluene

                    Using the TreeCache package, i failed to configure versioning.

                    My configuration XML (with repeated versioning configuration):

                     

                       <default>

                          <locking isolationLevel="REPEATABLE_READ" lockAcquisitionTimeout="15000" writeSkewCheck="true"/>

                          <transaction transactionManagerLookupClass="org.infinispan.transaction.lookup.GenericTransactionManagerLookup" transactionMode="TRANSACTIONAL" lockingMode="OPTIMISTIC"/>

                          <invocationBatching enabled="true"/>

                          <versioning versioningScheme="SIMPLE" enabled="true" />

                          <clustering mode="LOCAL"/>

                       </default>

                       <namedCache name="JCoffeeSystemCache">

                          <versioning versioningScheme="SIMPLE" enabled="true" />

                       </namedCache>

                     

                    But this configuration is not recognized in infinispan:

                     

                    Caused by: org.infinispan.config.ConfigurationException: Write-skew checking requires versioning to be enabled and versioning scheme 'SIMPLE' to be configured

                            at org.infinispan.configuration.cache.LockingConfigurationBuilder.validate(LockingConfigurationBuilder.java:85) [infinispan-core-5.1.4.FINAL.jar:5.1.4.FINAL]

                            at org.infinispan.configuration.cache.ConfigurationBuilder.validate(ConfigurationBuilder.java:132) [infinispan-core-5.1.4.FINAL.jar:5.1.4.FINAL]

                            at org.infinispan.configuration.cache.ConfigurationBuilder.build(ConfigurationBuilder.java:145) [infinispan-core-5.1.4.FINAL.jar:5.1.4.FINAL]

                            at org.infinispan.configuration.cache.ConfigurationBuilder.build(ConfigurationBuilder.java:140) [infinispan-core-5.1.4.FINAL.jar:5.1.4.FINAL]

                            at org.infinispan.configuration.cache.LegacyConfigurationAdaptor.adapt(LegacyConfigurationAdaptor.java:487) [infinispan-core-5.1.4.FINAL.jar:5.1.4.FINAL]

                            at org.infinispan.CacheImpl.getCacheConfiguration(CacheImpl.java:399) [infinispan-core-5.1.4.FINAL.jar:5.1.4.FINAL]

                            at org.infinispan.tree.TreeCacheFactory.createTreeCache(TreeCacheFactory.java:53) [infinispan-tree-5.1.4.FINAL.jar:5.1.4.FINAL]

                            at ... 160 more

                     

                    Is versioning not propagated in org.infinispan.configuration.cache.LegacyConfigurationAdaptor?

                    • 8. Re: Lost update in infinispan tree cache
                      galder.zamarreno

                      Try with a proper transaction manager such as JBoss Transactions: https://docs.jboss.org/author/x/FAY5

                      • 9. Re: Lost update in infinispan tree cache
                        galder.zamarreno