9 Replies Latest reply on Dec 3, 2009 1:14 PM by brian.stansberry

Can't acquire lock in 0 ms

rs1050 Nov 14, 2009 11:17 PM

Hi,

Version 3.2.1GA, problem happens with two processes working with cache at the same time. Both processes use JOTM for tx management. I am getting this message:

Nov 14 18:49:13,248 [OOB-1,192.168.1.104:61141] TRACE CacheMarshaller300:objectFromObjectStream:162 - Unmarshalled object org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/hphRTp4/0:0_2] after [0] milliseconds for requestor [Thread[Incoming-1,192.168.1.104:61140,10,Thread Pools]]! Lock held by [Thread[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-1,5,main]]

more detailed log:

Nov 14 18:49:13,32 [Incoming-1,192.168.1.104:61141] TRACE CacheMarshaller300:objectFromObjectStream:162 - Unmarshalled object ReplicateCommand{cmds=InvalidateCommand{fqn=/m/1:575}}
Nov 14 18:49:13,33 [Incoming-1,192.168.1.104:61141] TRACE CommandAwareRpcDispatcher:executeCommand:270 - Executing command: ReplicateCommand{cmds=InvalidateCommand{fqn=/m/1:575}} [sender=192.168.1.104:61140]
Nov 14 18:49:13,33 [Incoming-1,192.168.1.104:61141] TRACE CommandAwareRpcDispatcher:executeCommand:312 - This is a non-visitable command - so performing directly and not via the invoker.
Nov 14 18:49:13,33 [Incoming-1,192.168.1.104:61141] TRACE ComponentRegistry:invocationsAllowed:880 - Testing if invocations are allowed.
Nov 14 18:49:13,34 [Incoming-1,192.168.1.104:61141] TRACE ReplicateCommand:processSingleCommand:135 - Invoking command InvalidateCommand{fqn=/m/1:575}, with originLocal flag set to false.
Nov 14 18:49:13,34 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command InvalidateCommand{fqn=/m/1:575} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false, suppressPersistence=false, suppressEventNotification=false}, originLocal=false, bypassUnmarshalling=false}]
Nov 14 18:49:13,35 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
Nov 14 18:49:13,35 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
Nov 14 18:49:13,35 [Incoming-1,192.168.1.104:61141] TRACE MVCCLockManager:lockAndRecord:131 - Attempting to lock /m/1:575
Nov 14 18:49:13,35 [Incoming-1,192.168.1.104:61141] TRACE CallInterceptor:handleDefault:98 - Executing command: InvalidateCommand{fqn=/m/1:575}.
Nov 14 18:49:13,37 [Incoming-1,192.168.1.104:61141] TRACE ComponentRegistry:invocationsAllowed:880 - Testing if invocations are allowed.
Nov 14 18:49:13,38 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command GetNodeCommand{fqn=/m/1:575} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=0, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false, suppressPersistence=false, suppressEventNotification=false}, originLocal=false, bypassUnmarshalling=false}]
Nov 14 18:49:13,39 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
Nov 14 18:49:13,39 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
Nov 14 18:49:13,39 [Incoming-1,192.168.1.104:61141] TRACE MVCCNodeHelper:wrapNodeForReading:129 - Node /m/1:575 is not in context, fetching from container.
Nov 14 18:49:13,40 [Incoming-1,192.168.1.104:61141] TRACE CacheLoaderInterceptor:mustLoad:421 - Node [/m/1:575] is null in memory. Must load? true
Nov 14 18:49:13,41 [Incoming-1,192.168.1.104:61141] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /m/1:575 mustLoad=true
Nov 14 18:49:13,42 [Incoming-1,192.168.1.104:61141] TRACE TcpDelegatingCacheLoader:invokeWithRetries:129 - About to invoke operation protected boolean org.jboss.cache.loader.TcpDelegatingCacheLoader._exists(org.jboss.cache.Fqn) throws java.lang.Exception
Nov 14 18:49:13,32 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /rdp4
Nov 14 18:49:13,43 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,43 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,43 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,44 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/rdp1]. Queue size is 0
Nov 14 18:49:13,44 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /rdp1
Nov 14 18:49:13,44 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,44 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,44 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,48 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/rXY]. Queue size is 0
Nov 14 18:49:13,48 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /rXY
Nov 14 18:49:13,48 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,50 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,50 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,55 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/]. Queue size is 0
Nov 14 18:49:13,56 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /
Nov 14 18:49:13,56 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,56 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,56 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,57 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/rDCB]. Queue size is 0
Nov 14 18:49:13,57 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /rDCB
Nov 14 18:49:13,57 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,57 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,57 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,58 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/uF]. Queue size is 0
Nov 14 18:49:13,58 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /uF
Nov 14 18:49:13,58 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,58 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,58 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,59 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMLp5]. Queue size is 0
Nov 14 18:49:13,59 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMLp5
Nov 14 18:49:13,59 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,61 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,61 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,61 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,61 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,62 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRRp3]. Queue size is 0
Nov 14 18:49:13,62 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRRp3
Nov 14 18:49:13,62 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,62 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,62 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,63 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,63 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,63 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMLp4]. Queue size is 0
Nov 14 18:49:13,63 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMLp4
Nov 14 18:49:13,63 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,64 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,64 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,65 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/test]. Queue size is 0
Nov 14 18:49:13,65 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /test
Nov 14 18:49:13,65 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,65 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,65 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,66 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMVp2]. Queue size is 0
Nov 14 18:49:13,67 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMVp2
Nov 14 18:49:13,71 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,71 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,71 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,70 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:131 - Completed invocation of protected java.lang.Object org.jboss.cache.loader.TcpDelegatingCacheLoader._put(org.jboss.cache.Fqn,java.lang.Object,java.lang.Object) throws java.lang.Exception
Nov 14 18:49:13,72 [main] TRACE ReadCommittedNode:commitUpdate:136 - Updating node [/hphRTp3/0:0_2]. deleted=false valid=true changed=true created=false
Nov 14 18:49:13,73 [main] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/hphRTp3/0:0_2] for owner Thread[main,5,main]
Nov 14 18:49:13,73 [main] TRACE MVCCLockManager:unlock:145 - Attempting to unlock /hphRTp3/0:0_2
Nov 14 18:49:13,73 [main] DEBUG InvalidationInterceptor:handleWriteMethod:244 - Is a CRUD method
Nov 14 18:49:13,74 [main] DEBUG InvalidationInterceptor:invalidateAcrossCluster:381 - Cache [192.168.1.104:61141] replicating InvalidateCommand{fqn=/hphRTp3/0:0_2}
Nov 14 18:49:13,74 [main] TRACE InvalidationInterceptor:replicateCall:140 - Broadcasting call InvalidateCommand{fqn=/hphRTp3/0:0_2} to recipient list null
Nov 14 18:49:13,74 [main] TRACE InvalidationInterceptor:replicateCall:156 - Setting call recipients to null since the original list of recipients passed in is null.
Nov 14 18:49:13,77 [main] TRACE RPCManagerImpl:callRemoteMethods:736 - callRemoteMethods(): valid members are null methods: ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp3/0:0_2}} Using OOB? false modeToUse: 2
Nov 14 18:49:13,77 [main] TRACE CommandAwareRpcDispatcher:invokeRemoteCommands:205 - dests=null, command=ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp3/0:0_2}}, mode=2, timeout=15000
Nov 14 18:49:13,78 [main] TRACE CacheMarshaller300:objectToObjectStream:169 - Marshalling object ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp3/0:0_2}}
Nov 14 18:49:13,78 [main] TRACE CacheMarshaller300:objectToObjectStream:200 - Done serializing object: ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp3/0:0_2}}
Nov 14 18:49:13,79 [main] TRACE CommandAwareRpcDispatcher:castMessage:456 - real_dests=[192.168.1.104:61140]
Nov 14 18:49:13,71 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMLp3]. Queue size is 0
Nov 14 18:49:13,80 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMLp3
Nov 14 18:49:13,81 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,82 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,83 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,85 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRTp1]. Queue size is 0
Nov 14 18:49:13,85 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRTp1
Nov 14 18:49:13,85 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,89 [Incoming-1,192.168.1.104:61141] TRACE TcpDelegatingCacheLoader:invokeWithRetries:131 - Completed invocation of protected boolean org.jboss.cache.loader.TcpDelegatingCacheLoader._exists(org.jboss.cache.Fqn) throws java.lang.Exception
Nov 14 18:49:13,89 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,90 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,90 [Incoming-1,192.168.1.104:61141] TRACE MVCCNodeFactory:createChildNode:175 - Created new child with fqn [/m/1:575]
Nov 14 18:49:13,90 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,91 [Incoming-1,192.168.1.104:61141] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /m is already in context.
Nov 14 18:49:13,92 [Incoming-1,192.168.1.104:61141] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /m/1:575 is already in context.
Nov 14 18:49:13,91 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,92 [Incoming-1,192.168.1.104:61141] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/m/1:575}.
Nov 14 18:49:13,94 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/ibPREVIEW]. Queue size is 0
Nov 14 18:49:13,96 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /ibPREVIEW
Nov 14 18:49:13,96 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,96 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,97 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,97 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/mC]. Queue size is 0
Nov 14 18:49:13,97 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /mC
Nov 14 18:49:13,97 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,97 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,95 [Incoming-1,192.168.1.104:61141] TRACE GetNodeCommand:perform:70 - Found node, returning NodeReference{delegate=UnversionedNode[ /m/1:575]}
Nov 14 18:49:13,98 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,100 [Incoming-1,192.168.1.104:61141] TRACE RegionManagerImpl:getRegion:223 - Contents of RegionsRegistry: {/hphRRp1=RegionImpl{fqn=/hphRRp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /uN=RegionImpl{fqn=/uN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp2=RegionImpl{fqn=/rdp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp1=RegionImpl{fqn=/hphMRp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp4=RegionImpl{fqn=/hphRRp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp4=RegionImpl{fqn=/rdp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp1=RegionImpl{fqn=/rdp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rXY=RegionImpl{fqn=/rXY; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /=RegionImpl{fqn=/; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rDCB=RegionImpl{fqn=/rDCB; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /uF=RegionImpl{fqn=/uF; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp5=RegionImpl{fqn=/hphMLp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp3=RegionImpl{fqn=/hphRRp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp4=RegionImpl{fqn=/hphMLp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /test=RegionImpl{fqn=/test; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp2=RegionImpl{fqn=/hphMVp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp3=RegionImpl{fqn=/hphMLp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp1=RegionImpl{fqn=/hphRTp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /ibPREVIEW=RegionImpl{fqn=/ibPREVIEW; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /mC=RegionImpl{fqn=/mC; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /u=RegionImpl{fqn=/u; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp3=RegionImpl{fqn=/hphMVp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp5=RegionImpl{fqn=/hphRRp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp2=RegionImpl{fqn=/hphMLp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /v=RegionImpl{fqn=/v; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp2=RegionImpl{fqn=/hphMTp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp4=RegionImpl{fqn=/hphMRp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp1=RegionImpl{fqn=/hphMLp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /m=RegionImpl{fqn=/m; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=1}, /hphMVp4=RegionImpl{fqn=/hphMVp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp2=RegionImpl{fqn=/hphRTp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /i=RegionImpl{fqn=/i; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp1=RegionImpl{fqn=/hphMVp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp5=RegionImpl{fqn=/hphMRp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /cN=RegionImpl{fqn=/cN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /ibTHUMB=RegionImpl{fqn=/ibTHUMB; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp5=RegionImpl{fqn=/hphMVp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp2=RegionImpl{fqn=/hphMRp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /aC=RegionImpl{fqn=/aC; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /mR=RegionImpl{fqn=/mR; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp3=RegionImpl{fqn=/hphMTp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp5=RegionImpl{fqn=/hphRTp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=2}, /pN=RegionImpl{fqn=/pN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp5=RegionImpl{fqn=/hphMTp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp4=RegionImpl{fqn=/hphRTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=1}, /r=RegionImpl{fqn=/r; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp3=RegionImpl{fqn=/hphMRp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp3=RegionImpl{fqn=/rdp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp2=RegionImpl{fqn=/hphRRp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp3=RegionImpl{fqn=/hphRTp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=2}, /hphMTp4=RegionImpl{fqn=/hphMTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp1=RegionImpl{fqn=/hphMTp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp5=RegionImpl{fqn=/rdp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}}
Nov 14 18:49:13,101 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region /u]. Queue size is 0
Nov 14 18:49:13,103 [Incoming-1,192.168.1.104:61141] TRACE RegionManagerImpl:getRegion:271 - Trying next region /m and got RegionImpl{fqn=/m; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=1}
Nov 14 18:49:13,103 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /u
Nov 14 18:49:13,104 [Incoming-1,192.168.1.104:61141] TRACE EvictionInterceptor:registerEvictionEventToRegionManager:254 - Registering event VISIT_NODE_EVENT on node /m/1:575
Nov 14 18:49:13,104 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,105 [Incoming-1,192.168.1.104:61141] TRACE ReadCommittedNode:commitUpdate:136 - Updating node [/m/1:575]. deleted=false valid=true changed=true created=true
Nov 14 18:49:13,107 [Incoming-1,192.168.1.104:61141] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/m/1:575] for owner Thread[Incoming-1,192.168.1.104:61141,10,Thread Pools]
Nov 14 18:49:13,106 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,107 [Incoming-1,192.168.1.104:61141] TRACE MVCCLockManager:unlock:145 - Attempting to unlock /m/1:575
Nov 14 18:49:13,108 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,108 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
Nov 14 18:49:13,109 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMVp3]. Queue size is 0
Nov 14 18:49:13,109 [Incoming-1,192.168.1.104:61141] TRACE InvalidateCommand:perform:77 - Invalidating fqn:/m/1:575
Nov 14 18:49:13,109 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMVp3
Nov 14 18:49:13,111 [Incoming-1,192.168.1.104:61141] TRACE DataContainerImpl:evict:691 - removing NODE as it is a leaf: evict(/m/1:575)
Nov 14 18:49:13,111 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,112 [Incoming-1,192.168.1.104:61141] TRACE UnversionedNode:setValid:595 - Marking node /m/1:575 as invalid
Nov 14 18:49:13,112 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,113 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,113 [Incoming-1,192.168.1.104:61141] TRACE UnversionedNode:setValid:595 - Marking node /m/1:575 as invalid
Nov 14 18:49:13,113 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRRp5]. Queue size is 0
Nov 14 18:49:13,113 [Incoming-1,192.168.1.104:61141] TRACE MVCCLockingInterceptor:doAfterCall:350 - Nothing to do since there are no modifications in scope.
Nov 14 18:49:13,114 [Incoming-1,192.168.1.104:61141] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
Nov 14 18:49:13,114 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRRp5
Nov 14 18:49:13,114 [Incoming-1,192.168.1.104:61141] TRACE CommandAwareRpcDispatcher:handle:247 - Command : ReplicateCommand{cmds=InvalidateCommand{fqn=/m/1:575}} executed, result is: null
Nov 14 18:49:13,114 [OOB-1,192.168.1.104:61141] TRACE CacheMarshaller300:objectFromObjectStream:162 - Unmarshalled object null
Nov 14 18:49:13,116 [Incoming-1,192.168.1.104:61141] TRACE CacheMarshaller300:objectToObjectStream:169 - Marshalling object null
Nov 14 18:49:13,115 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,116 [Incoming-1,192.168.1.104:61141] TRACE CacheMarshaller300:objectToObjectStream:200 - Done serializing object: null
Nov 14 18:49:13,116 [main] TRACE CommandAwareRpcDispatcher:call:398 - responses: [sender=192.168.1.104:61140, retval=null, received=true, suspected=false]

Nov 14 18:49:13,117 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,117 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,118 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,118 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,117 [main] TRACE RPCManagerImpl:callRemoteMethods:748 - (192.168.1.104:61141): responses for method ReplicateCommand:
null
Nov 14 18:49:13,118 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMLp2]. Queue size is 0
Nov 14 18:49:13,118 [main] TRACE InvalidationInterceptor:replicateCall:167 - responses=[]
Nov 14 18:49:13,118 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMLp2
Nov 14 18:49:13,119 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,120 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,119 [main] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
Nov 14 18:49:13,120 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,120 [main] TRACE ComponentRegistry:invocationsAllowed:880 - Testing if invocations are allowed.
Nov 14 18:49:13,121 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,121 [main] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command GetNodeCommand{fqn=/hphRTp4/0:0_2} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false, suppressPersistence=false, suppressEventNotification=false}, originLocal=true, bypassUnmarshalling=false}]
Nov 14 18:49:13,121 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,122 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/v]. Queue size is 0
Nov 14 18:49:13,122 [main] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
Nov 14 18:49:13,122 [main] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
Nov 14 18:49:13,122 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /v
Nov 14 18:49:13,123 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,123 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,122 [main] TRACE MVCCNodeHelper:wrapNodeForReading:129 - Node /hphRTp4/0:0_2 is not in context, fetching from container.
Nov 14 18:49:13,123 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,123 [main] TRACE CacheLoaderInterceptor:mustLoad:421 - Node [/hphRTp4/0:0_2] is null in memory. Must load? true
Nov 14 18:49:13,123 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMTp2]. Queue size is 0
Nov 14 18:49:13,125 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMTp2
Nov 14 18:49:13,125 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,124 [main] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /hphRTp4/0:0_2 mustLoad=true
Nov 14 18:49:13,125 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,125 [main] TRACE MVCCLockManager:lockAndRecord:131 - Attempting to lock /hphRTp4/0:0_2
Nov 14 18:49:13,125 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,126 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:129 - About to invoke operation protected boolean org.jboss.cache.loader.TcpDelegatingCacheLoader._exists(org.jboss.cache.Fqn) throws java.lang.Exception
Nov 14 18:49:13,126 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMRp4]. Queue size is 0
Nov 14 18:49:13,127 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMRp4
Nov 14 18:49:13,127 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,127 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,127 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,127 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMLp1]. Queue size is 0
Nov 14 18:49:13,128 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMLp1
Nov 14 18:49:13,128 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,129 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,129 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,130 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,130 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,130 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/m]. Queue size is 2
Nov 14 18:49:13,130 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /m
Nov 14 18:49:13,130 [EvictionTimer-0] DEBUG BaseEvictionAlgorithm:processVisitedNodes:438 - Visiting node that was not added to eviction queues. Assuming that it has 1 element.
Nov 14 18:49:13,131 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:333 - Adding node /m/1:576 with 1 elements to eviction queue
Nov 14 18:49:13,131 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:359 - /m/1:576 added successfully to eviction queue
Nov 14 18:49:13,131 [EvictionTimer-0] DEBUG BaseEvictionAlgorithm:processVisitedNodes:438 - Visiting node that was not added to eviction queues. Assuming that it has 1 element.
Nov 14 18:49:13,131 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:333 - Adding node /m/1:575 with 1 elements to eviction queue
Nov 14 18:49:13,131 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:359 - /m/1:575 added successfully to eviction queue
Nov 14 18:49:13,131 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 2 node events
Nov 14 18:49:13,132 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,132 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,132 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,132 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 15
Nov 14 18:49:13,133 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMVp4]. Queue size is 0
Nov 14 18:49:13,133 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMVp4
Nov 14 18:49:13,134 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,134 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,135 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,135 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRTp2]. Queue size is 0
Nov 14 18:49:13,135 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRTp2
Nov 14 18:49:13,135 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,135 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,136 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,136 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,136 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,136 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region /i]. Queue size is 0
Nov 14 18:49:13,136 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /i
Nov 14 18:49:13,137 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,137 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,137 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,137 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,137 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 18
Nov 14 18:49:13,138 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMVp1]. Queue size is 0
Nov 14 18:49:13,138 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMVp1
Nov 14 18:49:13,138 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,140 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,140 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,140 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMRp5]. Queue size is 0
Nov 14 18:49:13,141 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMRp5
Nov 14 18:49:13,141 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,141 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,141 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,142 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/cN]. Queue size is 0
Nov 14 18:49:13,142 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /cN
Nov 14 18:49:13,142 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,142 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,142 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,143 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/ibTHUMB]. Queue size is 0
Nov 14 18:49:13,143 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /ibTHUMB
Nov 14 18:49:13,143 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,143 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,143 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,144 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,144 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 21
Nov 14 18:49:13,145 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMVp5]. Queue size is 0
Nov 14 18:49:13,145 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMVp5
Nov 14 18:49:13,145 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:131 - Completed invocation of protected boolean org.jboss.cache.loader.TcpDelegatingCacheLoader._exists(org.jboss.cache.Fqn) throws java.lang.Exception
Nov 14 18:49:13,146 [main] TRACE MVCCNodeFactory:createChildNode:175 - Created new child with fqn [/hphRTp4/0:0_2]
Nov 14 18:49:13,147 [main] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /hphRTp4 is already in context.
Nov 14 18:49:13,147 [main] TRACE MVCCNodeHelper:wrapNodeForReading:136 - Node /hphRTp4/0:0_2 is already in context.
Nov 14 18:49:13,147 [main] TRACE CallInterceptor:handleDefault:98 - Executing command: GetNodeCommand{fqn=/hphRTp4/0:0_2}.
Nov 14 18:49:13,148 [main] TRACE GetNodeCommand:perform:70 - Found node, returning NodeReference{delegate=UnversionedNode[ /hphRTp4/0:0_2]}
Nov 14 18:49:13,148 [main] TRACE RegionManagerImpl:getRegion:223 - Contents of RegionsRegistry: {/hphRRp1=RegionImpl{fqn=/hphRRp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /uN=RegionImpl{fqn=/uN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp2=RegionImpl{fqn=/rdp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp1=RegionImpl{fqn=/hphMRp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp4=RegionImpl{fqn=/hphRRp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp4=RegionImpl{fqn=/rdp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp1=RegionImpl{fqn=/rdp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rXY=RegionImpl{fqn=/rXY; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /=RegionImpl{fqn=/; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rDCB=RegionImpl{fqn=/rDCB; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /uF=RegionImpl{fqn=/uF; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp5=RegionImpl{fqn=/hphMLp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp3=RegionImpl{fqn=/hphRRp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp4=RegionImpl{fqn=/hphMLp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /test=RegionImpl{fqn=/test; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp2=RegionImpl{fqn=/hphMVp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp3=RegionImpl{fqn=/hphMLp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp1=RegionImpl{fqn=/hphRTp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /ibPREVIEW=RegionImpl{fqn=/ibPREVIEW; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /mC=RegionImpl{fqn=/mC; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /u=RegionImpl{fqn=/u; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp3=RegionImpl{fqn=/hphMVp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp5=RegionImpl{fqn=/hphRRp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp2=RegionImpl{fqn=/hphMLp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /v=RegionImpl{fqn=/v; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp2=RegionImpl{fqn=/hphMTp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp4=RegionImpl{fqn=/hphMRp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp1=RegionImpl{fqn=/hphMLp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /m=RegionImpl{fqn=/m; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp4=RegionImpl{fqn=/hphMVp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp2=RegionImpl{fqn=/hphRTp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /i=RegionImpl{fqn=/i; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp1=RegionImpl{fqn=/hphMVp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp5=RegionImpl{fqn=/hphMRp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /cN=RegionImpl{fqn=/cN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /ibTHUMB=RegionImpl{fqn=/ibTHUMB; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp5=RegionImpl{fqn=/hphMVp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp2=RegionImpl{fqn=/hphMRp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /aC=RegionImpl{fqn=/aC; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /mR=RegionImpl{fqn=/mR; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp3=RegionImpl{fqn=/hphMTp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp5=RegionImpl{fqn=/hphRTp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=2}, /pN=RegionImpl{fqn=/pN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp5=RegionImpl{fqn=/hphMTp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp4=RegionImpl{fqn=/hphRTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=1}, /r=RegionImpl{fqn=/r; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp3=RegionImpl{fqn=/hphMRp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp3=RegionImpl{fqn=/rdp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp2=RegionImpl{fqn=/hphRRp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp3=RegionImpl{fqn=/hphRTp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=2}, /hphMTp4=RegionImpl{fqn=/hphMTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp1=RegionImpl{fqn=/hphMTp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp5=RegionImpl{fqn=/rdp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}}
Nov 14 18:49:13,152 [main] TRACE RegionManagerImpl:getRegion:271 - Trying next region /hphRTp4 and got RegionImpl{fqn=/hphRTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=1}


Nov 14 18:49:13,152 [main] TRACE EvictionInterceptor:registerEvictionEventToRegionManager:254 - Registering event VISIT_NODE_EVENT on node /hphRTp4/0:0_2
Nov 14 18:49:13,153 [main] TRACE ReadCommittedNode:commitUpdate:136 - Updating node [/hphRTp4/0:0_2]. deleted=false valid=true changed=true created=true
Nov 14 18:49:13,153 [main] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/hphRTp4/0:0_2] for owner Thread[main,5,main]
Nov 14 18:49:13,153 [main] TRACE MVCCLockManager:unlock:145 - Attempting to unlock /hphRTp4/0:0_2
Nov 14 18:49:13,154 [main] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
Nov 14 18:49:13,154 [main] TRACE ComponentRegistry:invocationsAllowed:880 - Testing if invocations are allowed.
Nov 14 18:49:13,154 [main] TRACE InvocationContextInterceptor:handleAll:141 - Invoked with command PutKeyValueCommand{fqn=/hphRTp4/0:0_2, dataVersion=null, globalTransaction=null, key=d, value=null} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false, suppressPersistence=false, suppressEventNotification=false}, originLocal=true, bypassUnmarshalling=false}]
Nov 14 18:49:13,155 [main] TRACE InvocationContextInterceptor:setTransactionalContext:71 - Setting up transactional context.
Nov 14 18:49:13,156 [main] TRACE InvocationContextInterceptor:setTransactionalContext:72 - Setting tx as null and gtx as null
Nov 14 18:49:13,157 [main] TRACE MVCCNodeHelper:wrapNodeForReading:129 - Node /hphRTp4/0:0_2 is not in context, fetching from container.
Nov 14 18:49:13,157 [main] TRACE CacheLoaderInterceptor:mustLoad:454 - Must load node [/hphRTp4/0:0_2], uninitialized
Nov 14 18:49:13,157 [main] TRACE CacheLoaderInterceptor:loadIfNeeded:293 - load element /hphRTp4/0:0_2 mustLoad=true
Nov 14 18:49:13,147 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,158 [main] TRACE MVCCLockManager:lockAndRecord:131 - Attempting to lock /hphRTp4/0:0_2
Nov 14 18:49:13,158 [main] TRACE CacheLoaderInterceptor:loadData:509 - Attempting to load data for /hphRTp4/0:0_2
Nov 14 18:49:13,159 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:129 - About to invoke operation protected java.util.Map org.jboss.cache.loader.TcpDelegatingCacheLoader._get(org.jboss.cache.Fqn) throws java.lang.Exception
Nov 14 18:49:13,158 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,159 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,159 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMRp2]. Queue size is 0
Nov 14 18:49:13,160 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMRp2
Nov 14 18:49:13,160 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,161 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,161 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,161 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/aC]. Queue size is 0
Nov 14 18:49:13,161 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /aC
Nov 14 18:49:13,162 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,162 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,162 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,162 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/mR]. Queue size is 0
Nov 14 18:49:13,162 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /mR
Nov 14 18:49:13,163 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,163 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,163 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,163 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMTp3]. Queue size is 0
Nov 14 18:49:13,164 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMTp3
Nov 14 18:49:13,164 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,164 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,164 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,164 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRTp5]. Queue size is 2
Nov 14 18:49:13,165 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRTp5
Nov 14 18:49:13,165 [EvictionTimer-0] DEBUG BaseEvictionAlgorithm:processVisitedNodes:438 - Visiting node that was not added to eviction queues. Assuming that it has 1 element.
Nov 14 18:49:13,166 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:333 - Adding node /hphRTp5/0:0_2 with 1 elements to eviction queue
Nov 14 18:49:13,166 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:359 - /hphRTp5/0:0_2 added successfully to eviction queue
Nov 14 18:49:13,167 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 2 node events
Nov 14 18:49:13,167 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,167 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,167 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,168 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 3
Nov 14 18:49:13,168 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/pN]. Queue size is 0
Nov 14 18:49:13,168 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /pN
Nov 14 18:49:13,168 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,168 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,169 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,169 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,169 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,169 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMTp5]. Queue size is 0
Nov 14 18:49:13,170 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMTp5
Nov 14 18:49:13,170 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,170 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,170 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,174 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRTp4]. Queue size is 2
Nov 14 18:49:13,174 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRTp4
Nov 14 18:49:13,174 [EvictionTimer-0] DEBUG BaseEvictionAlgorithm:processVisitedNodes:438 - Visiting node that was not added to eviction queues. Assuming that it has 1 element.
Nov 14 18:49:13,176 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:333 - Adding node /hphRTp4/0:0_2 with 1 elements to eviction queue
Nov 14 18:49:13,177 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processAddedNodes:359 - /hphRTp4/0:0_2 added successfully to eviction queue
Nov 14 18:49:13,177 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 2 node events
Nov 14 18:49:13,177 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,177 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,177 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,178 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 3
Nov 14 18:49:13,178 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/r]. Queue size is 0
Nov 14 18:49:13,178 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /r
Nov 14 18:49:13,178 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,178 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,179 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,179 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMRp3]. Queue size is 0
Nov 14 18:49:13,179 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMRp3
Nov 14 18:49:13,179 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,179 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,182 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,182 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/rdp3]. Queue size is 0
Nov 14 18:49:13,182 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /rdp3
Nov 14 18:49:13,183 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,183 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,186 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,186 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRRp2]. Queue size is 0
Nov 14 18:49:13,186 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRRp2
Nov 14 18:49:13,186 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,187 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,188 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:131 - Completed invocation of protected java.util.Map org.jboss.cache.loader.TcpDelegatingCacheLoader._get(org.jboss.cache.Fqn) throws java.lang.Exception
Nov 14 18:49:13,188 [main] TRACE CacheLoaderInterceptor:loadData:512 - Node /hphRTp4/0:0_2 exists? true
Nov 14 18:49:13,188 [main] TRACE CacheLoaderInterceptor:setNodeState:469 - setNodeState node is UnversionedNode[ /hphRTp4/0:0_2]
Nov 14 18:49:13,189 [main] TRACE UnversionedNode:setValid:595 - Marking node /hphRTp4/0:0_2 as valid
Nov 14 18:49:13,189 [main] TRACE CacheLoaderInterceptor:setNodeState:502 - Setting dataLoaded to true
Nov 14 18:49:13,190 [main] TRACE PutKeyValueCommand:perform:76 - Perform('null', '/hphRTp4/0:0_2', k='d', v='null')
Nov 14 18:49:13,192 [main] TRACE PutKeyValueCommand:perform:88 - Old value is null, dataLoaded=true
Nov 14 18:49:13,189 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,192 [main] TRACE RegionManagerImpl:getRegion:223 - Contents of RegionsRegistry: {/hphRRp1=RegionImpl{fqn=/hphRRp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /uN=RegionImpl{fqn=/uN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp2=RegionImpl{fqn=/rdp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp1=RegionImpl{fqn=/hphMRp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp4=RegionImpl{fqn=/hphRRp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp4=RegionImpl{fqn=/rdp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp1=RegionImpl{fqn=/rdp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rXY=RegionImpl{fqn=/rXY; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /=RegionImpl{fqn=/; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rDCB=RegionImpl{fqn=/rDCB; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /uF=RegionImpl{fqn=/uF; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp5=RegionImpl{fqn=/hphMLp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp3=RegionImpl{fqn=/hphRRp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp4=RegionImpl{fqn=/hphMLp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /test=RegionImpl{fqn=/test; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp2=RegionImpl{fqn=/hphMVp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp3=RegionImpl{fqn=/hphMLp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp1=RegionImpl{fqn=/hphRTp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /ibPREVIEW=RegionImpl{fqn=/ibPREVIEW; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /mC=RegionImpl{fqn=/mC; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /u=RegionImpl{fqn=/u; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp3=RegionImpl{fqn=/hphMVp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp5=RegionImpl{fqn=/hphRRp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp2=RegionImpl{fqn=/hphMLp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /v=RegionImpl{fqn=/v; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp2=RegionImpl{fqn=/hphMTp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp4=RegionImpl{fqn=/hphMRp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMLp1=RegionImpl{fqn=/hphMLp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /m=RegionImpl{fqn=/m; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp4=RegionImpl{fqn=/hphMVp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp2=RegionImpl{fqn=/hphRTp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /i=RegionImpl{fqn=/i; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp1=RegionImpl{fqn=/hphMVp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp5=RegionImpl{fqn=/hphMRp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /cN=RegionImpl{fqn=/cN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /ibTHUMB=RegionImpl{fqn=/ibTHUMB; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMVp5=RegionImpl{fqn=/hphMVp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp2=RegionImpl{fqn=/hphMRp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /aC=RegionImpl{fqn=/aC; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /mR=RegionImpl{fqn=/mR; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp3=RegionImpl{fqn=/hphMTp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp5=RegionImpl{fqn=/hphRTp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /pN=RegionImpl{fqn=/pN; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp5=RegionImpl{fqn=/hphMTp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp4=RegionImpl{fqn=/hphRTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /r=RegionImpl{fqn=/r; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMRp3=RegionImpl{fqn=/hphMRp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp3=RegionImpl{fqn=/rdp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRRp2=RegionImpl{fqn=/hphRRp2; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphRTp3=RegionImpl{fqn=/hphRTp3; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=2}, /hphMTp4=RegionImpl{fqn=/hphMTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /hphMTp1=RegionImpl{fqn=/hphMTp1; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}, /rdp5=RegionImpl{fqn=/rdp5; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}}
Nov 14 18:49:13,194 [main] TRACE RegionManagerImpl:getRegion:271 - Trying next region /hphRTp4 and got RegionImpl{fqn=/hphRTp4; classloader=null; status=ACTIVE; eviction=true; evictionQueueSize=0}
Nov 14 18:49:13,194 [main] TRACE EvictionInterceptor:registerEvictionEventToRegionManager:254 - Registering event ADD_ELEMENT_EVENT on node /hphRTp4/0:0_2
Nov 14 18:49:13,194 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:129 - About to invoke operation protected java.lang.Object
org.jboss.cache.loader.TcpDelegatingCacheLoader._put(org.jboss.cache.Fqn,java.lang.Object,java.lang.Object) throws java.lang.Exception

Nov 14 18:49:13,192 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRTp3]. Queue size is 2
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRTp3
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 2 node events
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 3
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMTp4]. Queue size is 0
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMTp4
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMTp1]. Queue size is 0
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMTp1
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,202 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,203 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/rdp5]. Queue si

1. Re: Can't acquire lock in 0 ms

rs1050 Nov 14, 2009 11:19 PM (in response to rs1050)

apologies, the log was too long for forum. This is shorter version before the exception:

Nov 14 18:49:13,194 [main] TRACE EvictionInterceptor:registerEvictionEventToRegionManager:254 - Registering event ADD_ELEMENT_EVENT on node /hphRTp4/0:0_2
Nov 14 18:49:13,194 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:129 - About to invoke operation protected java.lang.Object
org.jboss.cache.loader.TcpDelegatingCacheLoader._put(org.jboss.cache.Fqn,java.lang.Object,java.lang.Object) throws java.lang.Exception

Nov 14 18:49:13,192 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 1
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphRTp3]. Queue size is 2
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphRTp3
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 2 node events
Nov 14 18:49:13,197 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE LRUAlgorithm:shouldEvictNode:64 - No idle or max time limit!
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 3
Nov 14 18:49:13,199 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMTp4]. Queue size is 0
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMTp4
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,200 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/hphMTp1]. Queue size is 0
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /hphMTp1
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,201 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,202 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0
Nov 14 18:49:13,203 [EvictionTimer-0] TRACE RegionImpl:processEvictionQueues:127 - Processing eviction queue for region [/rdp5]. Queue size is 0
Nov 14 18:49:13,203 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:process:142 - process(): region: /rdp5
Nov 14 18:49:13,203 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:processQueues:223 - processed 0 node events
Nov 14 18:49:13,203 [EvictionTimer-0] TRACE BaseEvictionAlgorithm:emptyRecycleQueue:522 - Recycle queue is empty
Nov 14 18:49:13,204 [EvictionTimer-0] TRACE LRUQueue:getNumberOfNodes:172 - LRUQUeue.size() = 0

Nov 14 18:49:13,206 [main] TRACE TcpDelegatingCacheLoader:invokeWithRetries:131 - Completed invocation of protected java.lang.Object org.jboss.cache.loader.TcpDelegatingCacheLoader._put(org.jboss.cache.Fqn,java.lang.Object,java.lang.Object) throws java.lang.Exception
Nov 14 18:49:13,207 [main] TRACE ReadCommittedNode:commitUpdate:136 - Updating node [/hphRTp4/0:0_2]. deleted=false valid=true changed=true created=false
Nov 14 18:49:13,208 [main] TRACE MVCCLockingInterceptor:cleanupLocks:374 - Releasing lock on [/hphRTp4/0:0_2] for owner Thread[main,5,main]

Nov 14 18:49:13,208 [main] TRACE MVCCLockManager:unlock:145 - Attempting to unlock /hphRTp4/0:0_2
Nov 14 18:49:13,208 [main] DEBUG InvalidationInterceptor:handleWriteMethod:244 - Is a CRUD method
Nov 14 18:49:13,209 [main] DEBUG InvalidationInterceptor:invalidateAcrossCluster:381 - Cache [192.168.1.104:61141] replicating InvalidateCommand{fqn=/hphRTp4/0:0_2}

Nov 14 18:49:13,209 [main] TRACE InvalidationInterceptor:replicateCall:140 - Broadcasting call InvalidateCommand{fqn=/hphRTp4/0:0_2} to recipient list null
Nov 14 18:49:13,213 [main] TRACE InvalidationInterceptor:replicateCall:156 - Setting call recipients to null since the original list of recipients passed in is null.
Nov 14 18:49:13,214 [main] TRACE RPCManagerImpl:callRemoteMethods:736 - callRemoteMethods(): valid members are null methods: ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp4/0:0_2}} Using OOB? false modeToUse: 2
Nov 14 18:49:13,215 [main] TRACE CommandAwareRpcDispatcher:invokeRemoteCommands:205 - dests=null, command=ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp4/0:0_2}}, mode=2, timeout=15000
Nov 14 18:49:13,216 [main] TRACE CacheMarshaller300:objectToObjectStream:169 - Marshalling object ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp4/0:0_2}}
Nov 14 18:49:13,217 [main] TRACE CacheMarshaller300:objectToObjectStream:200 - Done serializing object: ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp4/0:0_2}}
Nov 14 18:49:13,218 [main] TRACE CommandAwareRpcDispatcher:castMessage:456 - real_dests=[192.168.1.104:61140]


Nov 14 18:49:13,248 [OOB-1,192.168.1.104:61141] TRACE CacheMarshaller300:objectFromObjectStream:162 - Unmarshalled object org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/hphRTp4/0:0_2] after [0] milliseconds for requestor [Thread[Incoming-1,192.168.1.104:61140,10,Thread Pools]]! Lock held by [Thread[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-1,5,main]]

Nov 14 18:49:13,252 [main] TRACE CommandAwareRpcDispatcher:call:398 - responses: [sender=192.168.1.104:61140, retval=org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/hphRTp4/0:0_2] after [0] milliseconds for requestor [Thread[Incoming-1,192.168.1.104:61140,10,Thread Pools]]! Lock held by [Thread[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-1,5,main]], received=true, suspected=false]

Nov 14 18:49:13,252 [main] TRACE RPCManagerImpl:callRemoteMethods:748 - (192.168.1.104:61141): responses for method ReplicateCommand:
[sender=192.168.1.104:61140, retval=org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/hphRTp4/0:0_2] after [0] milliseconds for requestor [Thread[Incoming-1,192.168.1.104:61140,10,Thread Pools]]! Lock held by [Thread[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-1,5,main]], received=true, suspected=false]

Nov 14 18:49:13,253 [main] TRACE RPCManagerImpl:callRemoteMethods:775 - Recieved exception'org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/hphRTp4/0:0_2] after [0] milliseconds for requestor [Thread[Incoming-1,192.168.1.104:61140,10,Thread Pools]]! Lock held by [Thread[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-1,5,main]]' from 192.168.1.104:61140
Nov 14 18:49:13,254 [main] TRACE InvocationContextInterceptor:handleAll:208 - Resetting invocation-scope options
org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/hphRTp4/0:0_2] after [0] milliseconds for requestor [Thread[Incoming-1,192.168.1.104:61140,10,Thread Pools]]! Lock held by [Thread[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-1,5,main]]
 at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:159)
 at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodesRecursivelyForRemoval(MVCCNodeHelper.java:327)
 at org.jboss.cache.interceptors.MVCCLockingInterceptor.handleInvalidateCommand(MVCCLockingInterceptor.java:203)
 at org.jboss.cache.interceptors.base.PrePostProcessingCommandInterceptor.visitInvalidateCommand(PrePostProcessingCommandInterceptor.java:203)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:269)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:130)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.InterceptorChain.invokeRemote(InterceptorChain.java:316)
 at org.jboss.cache.commands.remote.ReplicateCommand.processSingleCommand(ReplicateCommand.java:139)
 at org.jboss.cache.commands.remote.ReplicateCommand.perform(ReplicateCommand.java:115)
 at org.jboss.cache.marshall.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:319)
 at org.jboss.cache.marshall.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:246)
 at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637)
 at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:545)
 at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:368)
 at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:775)
 at org.jgroups.JChannel.up(JChannel.java:1336)
 at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:454)
 at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:486)
 at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.up(STREAMING_STATE_TRANSFER.java:319)
 at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
 at org.jgroups.protocols.pbcast.GMS.up(GMS.java:820)
 at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:233)
 at org.jgroups.protocols.UNICAST.up(UNICAST.java:328)
 at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:895)
 at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:708)
 at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167)
 at org.jgroups.protocols.FD.up(FD.java:284)
 at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:307)
 at org.jgroups.protocols.MERGE2.up(MERGE2.java:144)
 at org.jgroups.protocols.Discovery.up(Discovery.java:264)
 at org.jgroups.protocols.PING.up(PING.java:273)
 at org.jgroups.protocols.TP.passMessageUp(TP.java:1273)
 at org.jgroups.protocols.TP.access$100(TP.java:49)
 at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1826)
 at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1805)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
 at java.lang.Thread.run(Thread.java:619)

Nov 14 18:49:13,265 [main] ERROR NewDataProcessor:main:45 -
org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/hphRTp4/0:0_2] after [0] milliseconds for requestor [Thread[Incoming-1,192.168.1.104:61140,10,Thread Pools]]! Lock held by [Thread[org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-1,5,main]]
 at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:159)
 at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodesRecursivelyForRemoval(MVCCNodeHelper.java:327)
 at org.jboss.cache.interceptors.MVCCLockingInterceptor.handleInvalidateCommand(MVCCLockingInterceptor.java:203)
 at org.jboss.cache.interceptors.base.PrePostProcessingCommandInterceptor.visitInvalidateCommand(PrePostProcessingCommandInterceptor.java:203)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:269)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
 at org.jboss.cache.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:130)
 at org.jboss.cache.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:90)
 at org.jboss.cache.commands.write.InvalidateCommand.acceptVisitor(InvalidateCommand.java:125)
 at org.jboss.cache.interceptors.InterceptorChain.invokeRemote(InterceptorChain.java:316)
 at org.jboss.cache.commands.remote.ReplicateCommand.processSingleCommand(ReplicateCommand.java:139)
 at org.jboss.cache.commands.remote.ReplicateCommand.perform(ReplicateCommand.java:115)
 at org.jboss.cache.marshall.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:319)
 at org.jboss.cache.marshall.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:246)
 at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637)
 at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:545)
 at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:368)
 at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:775)
 at org.jgroups.JChannel.up(JChannel.java:1336)
 at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:454)
 at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:486)
 at org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER.up(STREAMING_STATE_TRANSFER.java:319)
 at org.jgroups.protocols.FRAG2.up(FRAG2.java:188)
 at org.jgroups.protocols.pbcast.GMS.up(GMS.java:820)
 at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:233)
 at org.jgroups.protocols.UNICAST.up(UNICAST.java:328)
 at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:895)
 at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:708)
 at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167)
 at org.jgroups.protocols.FD.up(FD.java:284)
 at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:307)
 at org.jgroups.protocols.MERGE2.up(MERGE2.java:144)
 at org.jgroups.protocols.Discovery.up(Discovery.java:264)
 at org.jgroups.protocols.PING.up(PING.java:273)
 at org.jgroups.protocols.TP.passMessageUp(TP.java:1273)
 at org.jgroups.protocols.TP.access$100(TP.java:49)
 at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1826)
 at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1805)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
 at java.lang.Thread.run(Thread.java:619)
Nov 14 18:49:13,308 [Incoming-1,192.168.1.104:61141] TRACE CacheMarshaller300:objectFromObjectStream:162 - Unmarshalled object ReplicateCommand{cmds=InvalidateCommand{fqn=/hphRTp4/0:0_2}}

cache config:

<jbosscache xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="urn:jboss:jbosscache-core:config:3.0">


 <locking
 isolationLevel="READ_COMMITTED"
 lockParentForChildInsertRemove="false"
 lockAcquisitionTimeout="200000"
 nodeLockingScheme="mvcc"
 writeSkewCheck="false"
 concurrencyLevel="5000"/>

 <transaction
 transactionManagerLookupClass="org.jboss.cache.transaction.GenericTransactionManagerLookup"
 syncRollbackPhase="false"
 syncCommitPhase="false"/>

 <jmxStatistics
 enabled="false"/>

 <shutdown hookBehavior="DEFAULT"/>

 <listeners
 asyncPoolSize="1"
 asyncQueueSize="1000000"/>

 <invocationBatching
 enabled="false"/>

 <serialization
 objectInputStreamPoolSize="12"
 objectOutputStreamPoolSize="14"
 version="3.0.0"
 useLazyDeserialization="false"
 useRegionBasedMarshalling="false"/>

 <clustering mode="invalidation" clusterName="JBossCache-cluster">

 <stateRetrieval timeout="20000" fetchInMemoryState="false"/>

 <jgroupsConfig>

 <UDP discard_incompatible_packets="true" enable_bundling="false" enable_diagnostics="false" ip_ttl="2"
 loopback="false" max_bundle_size="64000" max_bundle_timeout="30" mcast_addr="228.10.10.10"
 mcast_port="45588" mcast_recv_buf_size="25000000" mcast_send_buf_size="640000"
 oob_thread_pool.enabled="true" oob_thread_pool.keep_alive_time="10000" oob_thread_pool.max_threads="4"
 oob_thread_pool.min_threads="1" oob_thread_pool.queue_enabled="true"
 oob_thread_pool.queue_max_size="10"
 oob_thread_pool.rejection_policy="Run" thread_naming_pattern="pl" thread_pool.enabled="true"
 thread_pool.keep_alive_time="30000" thread_pool.max_threads="25" thread_pool.min_threads="1"
 thread_pool.queue_enabled="true" thread_pool.queue_max_size="10" thread_pool.rejection_policy="Run"
 tos="8" ucast_recv_buf_size="20000000" ucast_send_buf_size="640000" use_concurrent_stack="true"
 use_incoming_packet_handler="true"/>
 <PING num_initial_members="3" timeout="2000"/>
 <MERGE2 max_interval="30000" min_interval="10000"/>
 <FD_SOCK/>
 <FD max_tries="5" shun="true" timeout="10000"/>
 <VERIFY_SUSPECT timeout="1500"/>
 <pbcast.NAKACK discard_delivered_msgs="true" gc_lag="0" retransmit_timeout="300,600,1200,2400,4800"
 use_mcast_xmit="false"/>
 <UNICAST timeout="300,600,1200,2400,3600"/>
 <pbcast.STABLE desired_avg_gossip="50000" max_bytes="400000" stability_delay="1000"/>
 <pbcast.GMS join_timeout="5000" print_local_addr="true" shun="false" view_ack_collection_timeout="5000"
 view_bundling="true"/>
 <FRAG2 frag_size="60000"/>
 <pbcast.STREAMING_STATE_TRANSFER/>
 <pbcast.FLUSH timeout="0"/>

 </jgroupsConfig>
 </clustering>

 <eviction wakeUpInterval="500">
 <default algorithmClass="org.jboss.cache.eviction.LRUAlgorithm" eventQueueSize="200000">
 <property name="maxNodes" value="5000"/>
 <property name="minTimeToLive" value="-1"/>
 </default>

 <region name="/test" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.test.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>


 <region name="/u" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.user.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/r" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.region.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/rXY" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.regionXY.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/m" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.media.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/aC" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.adCampaign.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/uF" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <!--as many as ad campaigns-->
 <property name="maxNodes" value="${cache.near.adCampaign.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/rDCB" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <!--as many as ad campaigns-->
 <property name="maxNodes" value="${cache.near.adCampaign.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/mC" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.mediaComments.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/mR" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.representativeMediaForRegion.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/i" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.image.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/v" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.video.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/cN" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.criticalNotification.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/pN" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.publicNotification.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/uN" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.userNotification.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/ibTHUMB" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.imageBytesThumb.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/ibPREVIEW" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.imageBytesPreview.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/hphRRp1" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionHighestRatedPaginationMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRRp2" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionHighestRatedPaginationInfo.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRRp3" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionHighestRatedInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRRp4" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionHighestRatedNotInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRRp5" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionHighestRatedMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/hphRTp1" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionMostTeleportedPaginationMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRTp2" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionMostTeleportedPaginationInfo.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRTp3" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionMostTeleportedInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRTp4" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionMostTeleportedNotInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphRTp5" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageRegionMostTeleportedMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/hphMLp1" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaLatestPaginationMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMLp2" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaLatestPaginationInfo.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMLp3" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaLatestInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMLp4" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaLatestNotInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMLp5" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaLatestMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/hphMVp1" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostViewedPaginationMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMVp2" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostViewedPaginationInfo.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMVp3" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostViewedInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMVp4" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostViewedNotInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMVp5" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostViewedMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/hphMTp1" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostVotedPaginationMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMTp2" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostVotedPaginationInfo.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMTp3" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostVotedInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMTp4" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostVotedNotInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMTp5" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaMostVotedMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/hphMRp1" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaHighestRatedPaginationMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMRp2" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaHighestRatedPaginationInfo.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMRp3" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaHighestRatedInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMRp4" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaHighestRatedNotInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/hphMRp5" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.homePageMediaHighestRatedMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <region name="/rdp1" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.regionDefaultPaginationMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/rdp2" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.regionDefaultPaginationInfo.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/rdp3" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.regionDefaultInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/rdp4" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.regionDefaultNotInlinedHtml.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>
 <region name="/rdp5" algorithmClass="org.jboss.cache.eviction.LRUAlgorithm">
 <property name="maxNodes" value="${cache.near.regionDefaultMediaIds.maxNodes}"/>
 <property name="timeToLive" value="-1"/>
 </region>

 <!--<region name="/org/jboss/data2" algorithmClass="org.jboss.cache.eviction.FIFOAlgorithm" eventQueueSize="100000">-->
 <!--<property name="maxNodes" value="3000"/>-->
 <!--<property name="minTimeToLive" value="4000"/>-->
 <!--</region>-->
 </eviction>

 <loaders passivation="false" shared="false">
 <loader class="org.jboss.cache.loader.TcpDelegatingCacheLoader"
 async="false"
 fetchPersistentState="false"
 ignoreModifications="false"
 purgeOnStartup="false">
 <properties>
 host=127.0.0.1
 port=7500
 timeout=1000000
 reconnectWaitTime=2000
 </properties>
 </loader>

 </loaders>

</jbosscache>

2. Re: Can't acquire lock in 0 ms

rs1050 Nov 16, 2009 9:06 PM (in response to rs1050)

Hi,

Any ideas as to what might be causing it this problem?

Thank you.
Actions
3. Re: Can't acquire lock in 0 ms

rs1050 Nov 17, 2009 8:21 PM (in response to rs1050)

I can't believe I am the only one facing this problem. There has to be some problem with the way jboss cache handles JTA transactions. I was able to get the same problem with running one instance inside resin and enother on jotm.
Actions

4. Re: Can't acquire lock in 0 ms

navaneethforu Nov 19, 2009 1:08 AM (in response to rs1050)

We are using Tree cache 1.4.1SP11 and getting simmilar excption

2009-11-16 09:33:31,435] [WARN ] [org.jboss.cache.TreeCache] replication failure with method_call _evict; id:8; Args: ( arg[0] = /XXXX/YYYY/masterdata/active
BarcodeTypeList) exception
org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/XXXX/YYYY/masterdata/activeBarcodeTypeList, caller=Thread[IncomingMessageHandler (channel=
YYYY-APP-CACHE-TEST),5,JGroups threads], lock=<unlocked> (org.jboss.cache.lock.LockStrategyReadCommitted@7c72d14f)
 at org.jboss.cache.Node.acquire(Node.java:533)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.acquireNodeLock(PessimisticLockInterceptor.java:410)

 at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:322)
 at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:196)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:32)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.InvalidationInterceptor.invoke(InvalidationInterceptor.java:60)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:379)
 at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:174)
 at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
 at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:179)
 at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5934)
 at org.jboss.cache.TreeCache._replicate(TreeCache.java:5211)
 at sun.reflect.GeneratedMethodAccessor228.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.jgroups.blocks.RpcDispatcher.handle(RpcDispatcher.java:281)
 at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:654)
 at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:544)
 at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:367)
 at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:779)
 at org.jgroups.JChannel.up(JChannel.java:1090)
 at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:382)
 at org.jgroups.stack.ProtocolStack.receiveUpEvent(ProtocolStack.java:398)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:158)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.pbcast.GMS.up(GMS.java:763)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.protocols.pbcast.GMS.receiveUpEvent(GMS.java:783)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:262)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:685)
 at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:517)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:170)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.FD.up(FD.java:300)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:301)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)
 at org.jgroups.protocols.MERGE2.up(MERGE2.java:162)
 at org.jgroups.stack.Protocol.receiveUpEvent(Protocol.java:470)
 at org.jgroups.stack.Protocol.passUp(Protocol.java:520)

 at org.jgroups.protocols.TP.access$900(TP.java:47)
 at org.jgroups.protocols.TP$IncomingMessageHandler.run(TP.java:1343)
 at java.lang.Thread.run(Thread.java:595)
Caused by: org.jboss.cache.lock.TimeoutException: read lock for /XXXX/YYYY/masterdata/activeBarcodeTypeList could not be acquired by Thread[IncomingMessageHan
dler (channel=YYYY-APP-CACHE-TEST),5,JGroups threads] after 0 ms. Locks: Read lock owners: []
Write lock owner: null
, lock info: <unlocked> (org.jboss.cache.lock.LockStrategyReadCommitted@7c72d14f)
 at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:262)
 at org.jboss.cache.Node.acquireReadLock(Node.java:545)
 at org.jboss.cache.Node.acquire(Node.java:507)
 ... 60 more

5. Re: Can't acquire lock in 0 ms

rs1050 Nov 20, 2009 4:54 PM (in response to rs1050)

In my case i see that two jvms are each trying to update the same set of nodes, however i have lockAcquisitionTimeout="200000" so I expected that they would have at least waited that long before freaking out.
Actions
6. Re: Can't acquire lock in 0 ms

rs1050 Nov 21, 2009 7:24 PM (in response to rs1050)

In debugger i see that inside MVCCHelper.acquireLock:159 invocation context's option overrides the value of lockAcquisitionTimeout to zero, even though for testing sake i explicitly set it to non-zero. What is more interesting, is that in the main thread a second later i can still see my correct non-zero lockAcquisitionTimeout override inside the context...
Actions
7. Re: Can't acquire lock in 0 ms

brian.stansberry Nov 25, 2009 12:51 PM (in response to rs1050)
The 0 ms is coming from MVCCLockInterceptor:

@Override public Object handleInvalidateCommand(InvocationContext ctx, InvalidateCommand command) throws Throwable { // this should be handled the same as a recursive evict command. ctx.getOptionOverrides().setLockAcquisitionTimeout(0); if (!command.getFqn().isRoot()) helper.wrapNodesRecursivelyForRemoval(ctx, command.getFqn()); return invokeNextInterceptor(ctx, command); }

I personally don't understand the reasoning behind that; the semantics of an invalidation are not the same as an evict, since an invalidation is concerned with data correctness while an evict is concerned with the lesser issue of managing memory.

Perhaps some of the folks who wrote this piece can comment?

This exception is thrown when a lock is attempted on a remote node. One thing I can think of is that with INVALIDATION_SYNC there is no point waiting more than 0 ms to acquire the lock since whatever is holding the lock on this node is before releasing it also going to send an invalidation message. Which won't succeed because whatever sent this message will be holding a lock. So might as well fail promptly.

The above logic doesn't hold true with INVALIDATION_ASYNC though.
Actions
8. Re: Can't acquire lock in 0 ms

rs1050 Nov 25, 2009 5:15 PM (in response to rs1050)

Thank you, good point. But I in case of invalidation and the situation you described I would expect that the timeoutexception would not be thrown to the caller.
Actions
9. Re: Can't acquire lock in 0 ms

brian.stansberry Dec 3, 2009 1:14 PM (in response to rs1050)

I've opened a JIRA for this, mostly about the semantic with INVALIDATION_ASYNC:

https://jira.jboss.org/jira/browse/JBCACHE-1559

With INVALIDATION_SYNC, I wasn't too clear. Neither transaction is going to succeed in putting the cache in a consistent state. That fact needs to propagate to the caller so it can decide what to do; hence the TimeoutException being thrown. This will happen whether the timeout is 0 ms or 100000000000 ms; setting the timeout to 0 ms is just to cause the inevitable to happen quickly.
Actions

Go to original post