9 Replies Latest reply on Dec 3, 2009 1:14 PM by Brian Stansberry

    Can't acquire lock in 0 ms

    R S Newbie

      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
          R S Newbie

          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
            R S Newbie

            Hi,

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

            Thank you.

            • 3. Re: Can't acquire lock in 0 ms
              R S Newbie

              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.

              • 4. Re: Can't acquire lock in 0 ms
                navaneeth kv Newbie

                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
                  R S Newbie

                  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.

                  • 6. Re: Can't acquire lock in 0 ms
                    R S Newbie

                    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...

                    • 7. Re: Can't acquire lock in 0 ms
                      Brian Stansberry Master

                      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.

                      • 8. Re: Can't acquire lock in 0 ms
                        R S Newbie

                        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.

                        • 9. Re: Can't acquire lock in 0 ms
                          Brian Stansberry Master

                          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.