Data gravitation synchronization issue

[fungrim]

Hi,

We have isolated what we think is a synchronization issue during data gravitation over multiple nodes using buddy replication.We have a unit test demonstrating the issue which I can send to anyone interested.

What appears to happen is this: When two nodes are involved in a data gravitation sometimes multiple data gravitation cleanup commands are issued of which one blocks the other. The calling node then times out after "buddyCommunicationTimeout" milliseconds (a timeout which is only logged as debug?) and returns null, making it look like the requested data does not exist in the cache. Further investigation reveals two global transactions on the data holding cache, one which holds an identity lock (write) for a backup data node and the other waiting to lock the same node.

Depending on "LockAcquisitionTimeout" the blocked request may continue, but we have seen several consequences of this depending on whether a user transaction is involved or not. Sometimes the lock seems to disappear and sometimes it doesn't and the application is in effect completely blocked (as the jgroup thread will be holding a lock on a NakReceiverWindow).

This behavior only occurs (as far as we've seen) when there's quite a bit of concurrent access, in particular: when data is added to one node but accessed immediately on another, ie. when addition and gravitation occurs immediately. We have tried disabling auto gravitation and generally playing around with the configuration but with no effect.

This seems like a synchronization issue and the unit test I can send along also shows that it is intermittent, sometimes the test will go through only to fail the next time and sometime a particular test fails when run standalone only to succeed if another test was run immediately before making it look like burn-in affects the result (which it of course may do).

Our unit test tries to model high concurrency in three different variations, one with a simple data gravitation, one with gravitation followed by a modification (subsequent put on the cache) and one with gravitation and modification within a user transaction. The last of these scenarios is basically what our real application is doing.

I've spent considerable time looking at this so feel free to ask questions. Also, tell me where to send the unit test if you want to have a look at it. The unit test repeatedly fails on a java5/linux/dual core/cache 2.5.0.GA setup.

Regards
/Lars J. Nilsson
www.cubeia.com

[fungrim]

Unit test can be downloaded here: http://www.cubeia.com/files/cache-lock-test.tar.gz

Regards
/Lars J. Nilsson
www.cubeia.com

[fungrim]

* bump *

It would be nice to know if anyone has been able to duplicate this problem. This is a major blocker for our development at the moment.

[manik]

Sorry for not responding sooner. Keep in mind that session affinity is a requirement when you use buddy replication and data gravitation.

I wouldn't expect a gravitation event to occur if the primary (or even the backup!) is still being written to (i.e., has a write lock on either the primary or buddy backup node).

Could you tell me a little more about the access patterns involved? How do you choose which instances in the cluster to speak to?

[fungrim]

The UnitTest models our real application. It goes like this: It is an application processing events for units (areas) where the area is an object stored in the cache and session affinity is enforced by a message bus. Sometimes during the lifetime of the application new areas will be added by a coordinator (which is restricted to one of the nodes, ie. new areas are only ever added at one node).

The message bus acts as a load balancer and will distribute events for areas, using a sticky algorithm so that session affinity is honored. So:

1. 
   
2. The coordinator adds an area object to the cache.
   
3. The message bus is notified (by jboss cache listener methods) of the new area. It then selects a node in the cluster for processing.
   
4. The working (event sending) threads are notified of the new area and starts sending events.
   
   The problem appears, as I originally wrote, when the events arrive at their deignated node and a data gravitation occurs. And as far as I have seen only on the backup node. For example:
   
   1. 
      
   2. Node A is coordinator and adds an area (X).
      
   3. Node B becomes buddy backup for X.
      
   4. The message bus assigns X to node C.
      
   5. When messages arrive at node C a data gravitation occurs.
      
   6. Node B receives two consecutive data gravitation cleanup commands, one of which doesn't seem to let go of its identity lock.
      
   7. After "buddyCommunicationTimeout" (logged as debug) node C get null from the cache and fails.
      
      This is loosely modeled in the UnitTest. In the test worker threads are assigned areas statically, areas are added in one cache after which the workers are notified of their new area and attempts to access it. If any of the worker threads gets a null from the cache the test fails as we know the area should exist (ie. the worker is not notified of its new area until it has already been added).

[manik]

what version of JBoss Cache do you use? There have been some issues with data gravitation finding state that may already have been evicted (JBCACHE-1192) which is fixed in 2.1.0.BETA1.

Does your setup involve any eviction configuration?

[fungrim]

We're using version 2.0.0 GA (with JGroups 2.5). There's no eviction policy configured.

[manik]

Have you tried with 2.1.0.BETA1? This needs JGroups 2.6.BETA1 as well (packaged with JBoss Cache)

[fredrikj]

I have also seen this behaviour in our application. Buddy replication does not seem to work under concurrent load and/or usage.

Just from starting up (no load applied) I get this in the logs:

2007-10-23 14:25:52,664 Incoming Thread,TableSpace,172.16.0.5:7500 ERROR jboss.cache.interceptors.TxInterceptor - method invocation failed
org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/5, caller=GlobalTransaction:<172.16.0.7:7500>:1, lock=write owner=GlobalTransaction:<172.16.0.6:7500>:2 (activeReaders=0, activeWriter=Thread[Incoming Thread,TableSpace,
172.16.0.5:7500,5,Incoming], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
 at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:528)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor$LockManager.acquire(PessimisticLockInterceptor.java:579)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.acquireNodeLock(PessimisticLockInterceptor.java:393)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:329)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:187)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:34)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:32)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:298)
 at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:131)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:123)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:62)
 at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3939)
 at org.jboss.cache.CacheImpl._dataGravitationCleanup(CacheImpl.java:3055)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
 at org.jboss.cache.interceptors.CallInterceptor.invoke(CallInterceptor.java:49)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.DataGravitatorInterceptor.invoke(DataGravitatorInterceptor.java:167)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:37)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:203)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:34)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:32)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.TxInterceptor.replayModifications(TxInterceptor.java:511)
 at org.jboss.cache.interceptors.TxInterceptor.handlePessimisticPrepare(TxInterceptor.java:394)
 at org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:254)
 at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:100)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:123)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:62)
 at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3939)
 at org.jboss.cache.CacheImpl._replicate(CacheImpl.java:2853)
 at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
 at org.jboss.cache.marshall.InactiveRegionAwareRpcDispatcher.handle(InactiveRegionAwareRpcDispatcher.java:77)
 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:736)
 at org.jgroups.JChannel.up(JChannel.java:1063)
 at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:325)
 at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:406)
 at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.up(STREAMING_STATE_TRANSFER.java:255)
 at org.jgroups.protocols.FRAG2.up(FRAG2.java:197)
 at org.jgroups.protocols.pbcast.GMS.up(GMS.java:722)
 at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
 at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:596)
 at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167)
 at org.jgroups.protocols.FD.up(FD.java:322)
 at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:298)
 at org.jgroups.protocols.MERGE2.up(MERGE2.java:145)
 at org.jgroups.protocols.Discovery.up(Discovery.java:220)
 at org.jgroups.protocols.MPING.up(MPING.java:218)
 at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1486)
 at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1435)
 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: write lock for /5 could not be acquired after 5000 ms. Locks: Read lock owners: []
Write lock owner: GlobalTransaction:<172.16.0.6:7500>:2
 (caller=GlobalTransaction:<172.16.0.7:7500>:1, lock info: write owner=GlobalTransaction:<172.16.0.6:7500>:2 (activeReaders=0, activeWriter=Thread[Incoming Thread,TableSpace,172.16.0.5:7500,5,Incoming], waitingReaders=0, waitingWriters=0
, waitingUpgrader=0))
 at org.jboss.cache.lock.IdentityLock.acquireWriteLock0(IdentityLock.java:244)
 at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:167)
 at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:497)
 ... 72 more

Which is related to datagravition cleanup. We need horizontal scalability while running multiple nodes, and without buddy replication it is not really possible. I will try to apply 2.1.0 BETA1 and see if things are better. I assume that it will be for testpurposes only since we do not want to rely on a beta release for a soon-to-be production system. =)

[fredrikj]

Using 2.1 beta does not solve the problem. I still get timeout exceptions from unsuccesful lock acquisition when enabling buddy replication.

JBoss Cache version: JBossCache 'Alegrias' 2.1.0.BETA1[ $Id: Version.java 4592 2007-10-10 16:44:36Z [e-mail] $]
....
JGroups version: 2.6.0 beta-1
....
Incoming Thread,TableSpace,172.16.0.5:7500 ERROR jboss.cache.interceptors.TxInterceptor - method invocation failed
org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/5, caller=GlobalTransaction:<172.16.0.7:7500>:1, lock=write owner=GlobalTransaction:<172.16.0.6:7500>:2 (activeReaders=0, activeWriter=Thread[Incoming Thread,TableSpace,
172.16.0.5:7500,5,Incoming], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
 at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:528)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor$LockManager.acquire(PessimisticLockInterceptor.java:598)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.acquireNodeLock(PessimisticLockInterceptor.java:412)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:348)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:185)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:34)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:32)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:299)
 at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:131)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:123)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:62)
 at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3954)
 at org.jboss.cache.CacheImpl._dataGravitationCleanup(CacheImpl.java:3026)
....
Caused by: org.jboss.cache.lock.TimeoutException: write lock for /5 could not be acquired after 5000 ms. Locks: Read lock owners: []
Write lock owner: GlobalTransaction:<172.16.0.6:7500>:2
 (caller=GlobalTransaction:<172.16.0.7:7500>:1, lock info: write owner=GlobalTransaction:<172.16.0.6:7500>:2 (activeReaders=0, activeWriter=Thread[Incoming Thread,TableSpace,172.16.0.5:7500,5,Incoming], waitingReaders=0, waitingWriters=0
, waitingUpgrader=0))
 at org.jboss.cache.lock.IdentityLock.acquireWriteLock0(IdentityLock.java:244)
 at org.jboss.cache.lock.IdentityLock.acquireWriteLock(IdentityLock.java:167)
 at org.jboss.cache.lock.IdentityLock.acquire(IdentityLock.java:497)

[manik]

Just to understand the issue better, when you say from starting up, what has happened so far? Also, how many caches have you got in the cluster and how many buddy backups per cache?

I'm presuming the error occurs when you try and access the data on a node that is *not* the original data owner nor the buddy?

[manik]

Also, have you got data gravitation remove on find and search subtrees set to true?

[fredrikj]

I have been investigating the issue further and it seems like we actually access the node right after creating it. This causes concurrent access from both the server that currently owns the data and the server that is assigned to the node and this is what is triggering the lock-situation described above.

I understand that accessing a node this way is not desired (permitted?) when running buddy replication and I will change the usage pattern to avoid this. However, I don't see why the locks should hang and cause a timeout (if configured). Arguably the scenario should work functionally, but will of course be suboptimal. I would argue this mostly since the lock-issue could be symptomatic of a more generic lock problem at hand.

Anyway, it seems like we got buddy rep up and running now, which is great!

[manik]

Glad to hear you got it working (somewhat).

Correct that such an access pattern is not recommended. This is why we strongly stress the need for session affinity with BR.

We're working on some ideas to remove the need for session affinity (wiki - http://wiki.jboss.org/wiki/Wiki.jsp?page=JBossCachePartitioning and discussion thread - http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4061375)

Cheers,
Manik