1 2 Previous Next 20 Replies Latest reply on May 28, 2008 10:25 AM by manik

    State transfer errors

    fungrim

      Hi,

      We have an issue regarding state transfer within our system. We basically assume that given two clustered caches A and B, cache A can be used and accessed safely while cache B is starting without and risk of data loss when cache B is successfully started and accessed. This, however, does not seem to be the case all the time.

      You will find a test case here, with source and configuration files: http://www.cubeia.com/misc/statetransfer/src.zip

      The test stresses the state transfer. The test class is documented, but inshort, it sets up:


      • Two caches, but starts only the first.
      • Fifty objects with a "counter", mapped by id within cache one.
      • Fifty threads associated with one object each (by id) and cache one.

        The test then goes like this:

        • The threads are started. Each thread accesses its associated object, checks that the counter is correct (ie. can correctly be incremented by one without loosing intermediate states), increment the counter and repeats.
        • Cache two is started.
        • Half of the threads are re-associated with cache two instead of cache one, however, their execution is not halted.

          The test fails on either JBoss Cache exceptions or 1) sequence errors (ie. lost intermediate states); or 2) missing state (ie. attempt to access an object in cache two which has not been replicated at all). We have tested the following setup in differend permutations: REPL_SYNC/REPL_ASYNCH, user transaction/no user transaction, and buddy replication enabled or disabled. So far our results looks somewhat like this (and they do match what we're seeing in our main system:

          SYNCH + TRANS + NO BUDDY
          Fail to replicate to cahce two with a replication exception caused by a suspetced member exception.

          ASYNCH + TRANS + NO BUDDY
          Sequence errors. Is this expected?

          SYNCH + NO TRANS + NO BUDDY
          Success.

          ASYNCH + NO TRANS + NO BUDDY
          Sequence errors. Is this expected? There's also "cache not in started state" errors on shutdown.

          SYNCH + TRANS + BUDDY
          Failure with time out exception. + A subsequent load of exceptions.

          ASYNCH + NO TRANS + BUDDY
          Sequence errors. Is this expected? Object not found (!). Also, depending on whether "loopback" is set in the jgroups stack or not you get slightly different behaviour. With loopback=true you get time out exceptions on buddy backup nodes. With loopback=false you get "cache not in started state" errors on shutdown.

          ASYNCH + TRANS + BUDDY
          (see above, adding a user transaction does not change the behaviour)

          We're primarily interested in getting REPL_ASYNC to work with user transactions and buddy replication (however, we're aware that asynchronous replication might not work in this scenario so synchronous would be ok). So, a few initial questions:

          1) Is our understanding of the cache correct (see first paragraph)? If not, what prerequisites are needed to safely start a new node in a cluster?

          2) If our understanding is somewhat ok, is the test correct? Obviously I may very well have screwed up somewhere in the code :-)

          If 1 && 2: Then the test seems to point out, at least, unexpected behaviour.

          Also, I'm aware of that this might be taxing and time consuming questions to answer or indeed even verify - even if there's no issue involved - so please indicate if there's any support agreement or service which would enable us to proceed faster, better or at all :-) You can reach me by PM or emailing me at (my name as written below, first name, middle initial and surname in lower case without spaces but separated by dots)@cubeia.com.

          Cheers -
          Lars J. Nilsson
          www.cubeia.com


        • 1. Re: State transfer errors
          fungrim

          Oh, and: This was with JBoss Cache 2.1.1.GA on an Intel dual core/Linux 2.6.22.

          • 2. Re: State transfer errors
            manik

            Will have a look and report back

            • 3. Re: State transfer errors
              manik

              BTW, I really appreciate the tests that you send to try and reproduce these issues, but in future could I ask you to check out the JBC srcs, and write your test as a TestNG unit test so I could just drop it in to the src tree and run it/analyse it rather than rewriting it first?

              I know this is cheeky of me but it would make things much faster. :-)

              • 4. Re: State transfer errors
                fungrim

                Weeeeell.... That could... possibly work. After all, I doubt setting up TestNG will take a significant amount of time for us comparing to write the damn stuff in the first place :-)

                • 5. Re: State transfer errors
                  manik

                  There's not much setup involved - just chk out the JBC sources and you should be able to run the existing tests in your IDE (IntelliJ supports TestNG out of the box; Eclipse may need a separate plugin).

                  If you can run existing tests from your IDE, all you'll need thereafter is to create a new test which encapsulates your test logic. :-)

                  • 6. Re: State transfer errors
                    fredrikj

                    Did you ever find something out regarding this?

                    • 7. Re: State transfer errors
                      manik

                      Sorry, no - I've been tied down with 2.2.0.CR1 release work. This should be released today.

                      Do you see the problem with 2.2.0.Beta1 or a snapshot from SVN, by the way?

                      • 8. Re: State transfer errors
                        fungrim

                        I've testng'd this now.

                        Here: http://www.cubeia.com/misc/statetransfer/src2.zip

                        This uses the available buddy replication config in the test resources, so it tests REPL_SYNC with buddy replication with and without user transactions.

                        I can also confirm that it fails on all JBC versions I have available at the moment. Ie. 2.0.0.GA, 2.1.0.GA, 2.1.1.GA and 2.2.0.BETA1.

                        Regards /Lars

                        • 9. Re: State transfer errors
                          manik

                          Sorry for being so slow with this.

                          I don't see a problem here. Yes, your test fails, but that is due to a few minor issues.

                          1. Make sure you have the following enabled in your buddy replication config:

                           <autoDataGravitation>true</autoDataGravitation>
                          


                          2. After starting cache2, the BR organisation code takes a short while to assign buddies, etc. So calling switchCache() immediately after starting is a problem. You could either (1) wait for a short while, or much better, (2) register a listener on cache2 so you know when it has been assigned to a buddy group. I created a listener like:

                          private void doTest()
                          {
                          ...
                           final CountDownLatch latch = new CountDownLatch(1);
                           cache2.addCacheListener(new BRListener(latch));
                           cache2.start();
                           latch.await();
                          
                           switchCache(OBJECTS / 2, OBJECTS, workers);
                          ...
                          }
                          
                          @CacheListener
                          public static class BRListener
                          {
                           CountDownLatch latch;
                          
                           public BRListener(CountDownLatch latch)
                           {
                           this.latch = latch;
                           }
                          
                           @BuddyGroupChanged
                           public void releaseLatch(BuddyGroupChangedEvent event)
                           {
                           latch.countDown();
                           }
                          }
                          
                          


                          HTH,
                          Manik


                          • 10. Re: State transfer errors
                            fungrim

                            Hum... You'll pardon me for thinking that that listener/latch solution feels a bit like black magic eh? :-)

                            But if it works I won't beat it.

                            However, it doesn't seem to work for me. Without transactions we're still failing 15-20% of all runs (I increased repetitions to 5 or 10 to check this) with sequence errors. But perhaps that is to be expected without a transaction?

                            The transaction test produces aprox. 2.6M of logs. The test does go through, but thats only because the error count is not increased on exceptions, so changing the workers catch clause to...

                            } catch(Throwable e) {
                             log.error("Unexpected error", e);
                             errorCount.incrementAndGet();
                             /*
                             * Roll back transaction, if it exists
                             */
                             checkRollbackTransaction(tx);
                            }

                            ... (ie. increasing the error count on unexpected throwables). We fail horribly again.

                            Excerpts from the exceptions follows further down.

                            It does work by manually throttling the access (forcing a 50ms sleep for all workers in the main iterations seems to do it), however that does not really feel like an option for us.

                            So, does the test go through without errors for you? And if not, how can we make it work?

                            Some exception encountered:

                            2008-05-22 12:21:10,051 - ERROR - Caught TimeoutException acquiring locks on region /
                            org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/36/36, caller=Thread[AsyncViewChangeHandlerThread,192.168.1.109:7800,5,main], lock=write owner=GlobalTransaction:<192.168.1.109:7800>:140223 (activeReaders=0, activeWriter=Thread[Thread-308,5,main], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
                             at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:530)
                             at org.jboss.cache.lock.IdentityLock.acquireAll(IdentityLock.java:551)
                             at org.jboss.cache.lock.IdentityLock.acquireAll(IdentityLock.java:559)
                             at org.jboss.cache.lock.IdentityLock.acquireAll(IdentityLock.java:559)
                             at org.jboss.cache.statetransfer.StateTransferManager.acquireLocksForStateTransfer(StateTransferManager.java:244)
                             at org.jboss.cache.statetransfer.StateTransferManager.getState(StateTransferManager.java:93)
                             at org.jboss.cache.buddyreplication.BuddyManager.generateState(BuddyManager.java:938)
                             at org.jboss.cache.buddyreplication.BuddyManager.acquireState(BuddyManager.java:870)
                             at org.jboss.cache.buddyreplication.BuddyManager.addBuddies(BuddyManager.java:792)
                             at org.jboss.cache.buddyreplication.BuddyManager.reassignBuddies(BuddyManager.java:416)
                             at org.jboss.cache.buddyreplication.BuddyManager.access$8(BuddyManager.java:363)
                             at org.jboss.cache.buddyreplication.BuddyManager$AsyncViewChangeHandlerThread.handleEnqueuedViewChange(BuddyManager.java:1137)
                             at org.jboss.cache.buddyreplication.BuddyManager$AsyncViewChangeHandlerThread.run(BuddyManager.java:1081)
                             at java.lang.Thread.run(Thread.java:595)
                            Caused by: org.jboss.cache.lock.TimeoutException: read lock for /36/36 could not be acquired by Thread[AsyncViewChangeHandlerThread,192.168.1.109:7800,5,main] after 400 ms. Locks: Read lock owners: []
                            Write lock owner: GlobalTransaction:<192.168.1.109:7800>:140223
                            , lock info: write owner=GlobalTransaction:<192.168.1.109:7800>:140223 (activeReaders=0, activeWriter=Thread[Thread-308,5,main], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
                             at org.jboss.cache.lock.IdentityLock.acquireReadLock0(IdentityLock.java:328)
                             at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:272)
                             at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:495)
                             ... 13 more


                            And...
                            008-05-22 12:21:19,681 - ERROR - prepare method invocation failed
                            org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/_BUDDY_BACKUP_/192.168.1.109_7800, caller=GlobalTransaction:<192.168.1.109:7800>:137593, lock=write owner=GlobalTransaction:<192.168.1.109:7800>:137592 (activeReaders=0, activeWriter=Thread[Incoming,192.168.1.109:7801,5,Thread Pools], waitingReaders=1, waitingWriters=0, waitingUpgrader=0)
                             at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:530)
                             at org.jboss.cache.lock.LockManager.acquireNodeLock(LockManager.java:235)
                             at org.jboss.cache.lock.LockManager.lock(LockManager.java:143)
                             at org.jboss.cache.lock.LockManager.acquireLocksWithTimeout(LockManager.java:71)
                             at org.jboss.cache.interceptors.PessimisticLockInterceptor.handlePutCommand(PessimisticLockInterceptor.java:112)
                             at org.jboss.cache.interceptors.PessimisticLockInterceptor.handlePutKeyValueCommand(PessimisticLockInterceptor.java:89)
                             at org.jboss.cache.interceptors.base.PostProcessingCommandInterceptor.visitPutKeyValueCommand(PostProcessingCommandInterceptor.java:63)
                             at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:99)
                             at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142)
                             at org.jboss.cache.interceptors.ReplicationInterceptor.handleCrudMethod(ReplicationInterceptor.java:124)
                             at org.jboss.cache.interceptors.ReplicationInterceptor.visitPutKeyValueCommand(ReplicationInterceptor.java:81)
                             at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:99)
                             at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142)
                             at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:157)
                             at org.jboss.cache.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:29)
                             at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:99)
                             at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142)
                             at org.jboss.cache.interceptors.TxInterceptor$ModificationsReplayVisitor.handleDefault(TxInterceptor.java:640)
                             at org.jboss.cache.interceptors.TxInterceptor$ModificationsReplayVisitor.handleDataVersionCommand(TxInterceptor.java:677)
                             at org.jboss.cache.interceptors.TxInterceptor$ModificationsReplayVisitor.visitPutKeyValueCommand(TxInterceptor.java:654)
                             at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:99)
                             at org.jboss.cache.commands.AbstractVisitor.visitCollection(AbstractVisitor.java:147)
                             at org.jboss.cache.interceptors.TxInterceptor.handlePessimisticPrepare(TxInterceptor.java:546)
                             at org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:376)
                             at org.jboss.cache.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:115)
                             at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:39)
                             at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142)
                             at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:157)
                             at org.jboss.cache.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:99)
                             at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:39)
                             at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142)
                             at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:144)
                             at org.jboss.cache.interceptors.InvocationContextInterceptor.visitPrepareCommand(InvocationContextInterceptor.java:77)
                             at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:39)
                             at org.jboss.cache.interceptors.InterceptorChain.invokeRemote(InterceptorChain.java:266)
                             at org.jboss.cache.commands.remote.ReplicateCommand.processSingleCommand(ReplicateCommand.java:116)
                             at org.jboss.cache.commands.remote.ReplicateCommand.perform(ReplicateCommand.java:92)
                             at org.jboss.cache.marshall.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:173)
                             at org.jboss.cache.marshall.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:133)
                             at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:624)
                             at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:533)
                             at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:365)
                             at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:746)
                             at org.jgroups.JChannel.up(JChannel.java:1154)
                             at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:402)
                             at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:370)
                             at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.up(STREAMING_STATE_TRANSFER.java:242)
                             at org.jgroups.protocols.FRAG2.up(FRAG2.java:205)
                             at org.jgroups.protocols.FC.up(FC.java:408)
                             at org.jgroups.protocols.pbcast.GMS.up(GMS.java:780)
                             at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
                             at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:729)
                             at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167)
                             at org.jgroups.protocols.FD.up(FD.java:285)
                             at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:300)
                             at org.jgroups.protocols.MERGE2.up(MERGE2.java:145)
                             at org.jgroups.protocols.Discovery.up(Discovery.java:245)
                             at org.jgroups.protocols.MPING.up(MPING.java:218)
                             at org.jgroups.protocols.TP.passMessageUp(TP.java:1126)
                             at org.jgroups.protocols.TP.access$100(TP.java:48)
                             at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1637)
                             at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1611)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
                             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
                             at java.lang.Thread.run(Thread.java:595)
                            Caused by: org.jboss.cache.lock.TimeoutException: read lock for /_BUDDY_BACKUP_/192.168.1.109_7800 could not be acquired by GlobalTransaction:<192.168.1.109:7800>:137593 after 10000 ms. Locks: Read lock owners: []
                            Write lock owner: GlobalTransaction:<192.168.1.109:7800>:137592
                            , lock info: write owner=GlobalTransaction:<192.168.1.109:7800>:137592 (activeReaders=0, activeWriter=Thread[Incoming,192.168.1.109:7801,5,Thread Pools], waitingReaders=1, waitingWriters=0, waitingUpgrader=0)
                             at org.jboss.cache.lock.IdentityLock.acquireReadLock0(IdentityLock.java:328)
                             at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:272)
                             at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:495)
                             ... 64 more


                            Etc...

                            Cheers /Lars

                            • 11. Re: State transfer errors
                              manik

                              No black magic at all - just a simple callback to tell you once a buddy has fully joined a buddy group. :-)

                              Regarding your exceptions, they look like standard lock acquisition timeouts. Your access pattern is very write-heavy. Write-heavy patterns will always have a lot of contention on write locks, and you should either increase your lock acquisition timeout (and deal with the waiting!) or catch the occasional exception and retry. Remember, caches are not designed to be write-heavy.

                              • 12. Re: State transfer errors
                                fungrim

                                Mmm. A few questions.

                                1) The lock contention occurs on data gravitation only, correct? As we're only updating attributes on nodes, the only time we need to content on lock (the "/" lock, or the buddy backup lock) is when adding something on a cache, ie. on data gravitation?

                                2) If #1, is there anyway to introduce some kind of fairness, or priority, on the data gravitation? I'm thinking that this setup cannot be fair as gravitating the data shouldn't take more then a few milliseconds and in this test we're only having 50 objects (and threads), and yet threads timeout after 10 seconds.

                                3) Is there any way to force all data to be gravitated on cache.start()? And if so, would that solve the problem?

                                • 13. Re: State transfer errors
                                  manik

                                  No, in different places, not just gravitation.

                                  the first stack trace shows contention during a state transfer for the new buddy. There is stuff being written to cache1 while cache1 is trying to get state to send to cache2. And there is contention here. Perhaps increasing your lock acquisition timeout for getting state for the buddy would help - according to the stack trace, it is set to 400millis!!

                                  For the 2nd stack trace, the problem has to do with transactions and 2-phase commits which can happen when there are a lot of frequent writes to the same region. Set your configuration to use synchronous commit and rollbacks and you won't see this.

                                  • 14. Re: State transfer errors
                                    fungrim

                                    The first timeout is not configurable (at least not in JBC 2.2.0.BETA1). It is hard coded to a sequence of 400, 800, and 1600 milliseconds in BuddyManager.java:859 (again in JBC 2.2.0.BETA1).

                                    1 2 Previous Next