11 Replies Latest reply on Jun 27, 2008 12:09 PM by rachna_agg

Passivation false problem

rachna_agg Jun 26, 2008 12:26 AM

Hi,

We are using JBoss Cache in a stand alone web application with tomcat 5.5.23 as our Web Server. We are using JDBC Cache Loader and passivation is taken as false.

We are facing an issue that we are not able to find the Cache Interceptor "ActivationInterceptor" MBean as registered although we have called the setRegisterInterceptors() API in CacheJmxWrapperMBean as true. As a result, we are not able to see the attributes "Activations", "CacheLoaderLoads" and "CacheLoaderMisses".

Can anyone please let us know is this Activation Interceptor linked with passivation property being true? I think they should not be linked as nodes are activated from the database when they are not found in the memory so we should get the attributes for Cache Loader Loads/Misses.

Also, when passivation is false, the attribute "Hits" is always zero and never increases and "Misses" attribute always increases whenever we call a retrieve API.

Regards,
Rachna

1. Re: Passivation false problem

manik Jun 26, 2008 6:27 AM (in response to rachna_agg)

The ActivationInterceptor *is* associated with passivation being set to true.

The ActivationInterceptor is a subclass of the CacheLoaderInterceptor, which should be present and should be recording loading of objects from the DB.

The only difference between the ActivationInterceptor and the CacheLoaderInterceptor is that the AI will *remove* objects from the DB if it is loaded from memory, while the CLI *just* loads stuff into memory if needed.
Actions
2. Re: Passivation false problem

rachna_agg Jun 26, 2008 7:12 AM (in response to rachna_agg)

Thanks for the reply.

But I think Activation is reading data from the database if it is not found in the memory which is the case even when passivation is set to false. So why Activation is associated with passivation being set to true only and not false?

Also, why the no of "Hits" is always zero even when "CacheLoaderLoads" in "CacheLoaderInterceptor" is increased. Moreover, everytime I retrieve the same record, my no of "Misses" increases" and not "Hits".

Regards,
Rachna
Actions
3. Re: Passivation false problem

manik Jun 26, 2008 7:59 AM (in response to rachna_agg)

"rachna_agg" wrote:
But I think Activation is reading data from the database if it is not found in the memory which is the case even when passivation is set to false.

No, that's what the CLI does. The AI just removes it from the DB if it's superclass (the CLI) has loaded it. Have a look at the src code if you don't believe me. ;)

"rachna_agg" wrote:

So why Activation is associated with passivation being set to true only and not false?

Because if passivation is false you don't want to remove state from the store when loaded in memory. You only want to do that when passivation is true.

"rachna_agg" wrote:
Also, why the no of "Hits" is always zero even when "CacheLoaderLoads" in "CacheLoaderInterceptor" is increased. Moreover, everytime I retrieve the same record, my no of "Misses" increases" and not "Hits".

Because for some reason the CLI needs to load state from the store again. Could be because an aggressive eviction policy is removing state from memory before it can be reloaded again. I'd have a look at TRACE level eviction logs.
Actions

4. Re: Passivation false problem

rachna_agg Jun 27, 2008 4:39 AM (in response to rachna_agg)

Thanks again for the reply.

My understanding about activation was wrong but now I am able to understand why the attribute "Activations" was not visible if passivation is false.

But I am still not clear about the "Hits" and "Misses" attributes. Let me explain my situation with the following steps and their corresponding attribute values:

1) Insert /A
2) Retrieve /A
3) Retrieve /A

Output

1) CL Loads = 0, Hits = 0, Misses = 0, CL Misses = 0, Evictions = 0
2) CL Loads = 1, Hits = 0, Misses = 1, CL Misses = 0, Evictions = 0
3) CL Loads = 1, Hits = 0, Misses = 2, CL Misses = 0, Evictions = 0

Here, I think that when I retrieve the same record in Step 3, then instead of the attribute "Misses" being increased, I think the attribute "Hits" should have been increased which is not happening in my case. I also enabled the DEBUG logging for jboss cache and I got the following output after Step 2:

Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=true, cache=, modificationType=null, data=null, fqn=/4528@rachna, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=false, cache=/4528@rachna 0 , modificationType=null, data=null, fqn=/4528@rachna, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=true, cache=/4528@rachna 0 , modificationType=null, data=null, fqn=/4528@rachna/42, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=false, cache=/4528@rachna 0 /42 0 , modificationType=null, data=null, fqn=/4528@rachna/42, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=true, cache=/4528@rachna 0 /42 0 , modificationType=null, data=null, fqn=/4528@rachna/42/1214554449967, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=false, cache=/4528@rachna 0 /42 0 /1214554449967 0 , modificationType=null, data=null, fqn=/4528@rachna/42/1214554449967, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=true, cache=/4528@rachna 0 /42 0 /1214554449967 0 , modificationType=null, data=null, fqn=/4528@rachna/42/1214554449967/10156252448681560289, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.500 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=false, cache=/4528@rachna 0 /42 0 /1214554449967 0 /10156252448681560289 0 , modificationType=null, data=null, fqn=/4528@rachna/42/1214554449967/10156252448681560289, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_CREATED}
Jun 27, 2008 01:59:27.532 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=true, cache=/4528@rachna 0 /42 0 /1214554449967 0 /10156252448681560289 0 , modificationType=null, data={}, fqn=/4528@rachna/42/1214554449967/10156252448681560289, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_LOADED}
Jun 27, 2008 01:59:27.532 PM DEBUG JBOSSCACHEEVENT_LOGGER - EventImpl{pre=false, cache=/4528@rachna 0 /42 0 /1214554449967 0 /10156252448681560289 4 , modificationType=null, data={somedata}, fqn=/4528@rachna/42/1214554449967/10156252448681560289, transaction=null, originLocal=true, targetFqn=null, successful=false, newView=null, type=NODE_LOADED}

and after executing Step 3, no logging appeared in jboss cache logs.

5. Re: Passivation false problem

manik Jun 27, 2008 6:47 AM (in response to rachna_agg)

I'm guessing something must have removed the node between steps 2 and 3.

The log you posted is not a JBoss Cache log, but some custom logging from a cache listener which is of limited use. Specifically, I'd want to see the CacheLoaderInterceptor logs and any eviction component logs at TRACE level.
Actions

6. Re: Passivation false problem

rachna_agg Jun 27, 2008 7:43 AM (in response to rachna_agg)

Sorry, here are the logs after Step 2:

Jun 27, 2008 05:09:02.046 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:02.046 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:02.046 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:02.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 50090ms
Jun 27, 2008 05:09:02.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:02.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 50090ms
Jun 27, 2008 05:09:02.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:03.108 PM DEBUG org.apache.catalina.session.ManagerBase - Start expire sessions StandardManager at 1214566743108 sessioncount 0
Jun 27, 2008 05:09:03.108 PM DEBUG org.apache.catalina.session.ManagerBase - End expire sessions StandardManager processingTime 0 expired sessions: 0
Jun 27, 2008 05:09:07.046 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:07.046 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:07.046 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:07.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 55090ms
Jun 27, 2008 05:09:07.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:07.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 55090ms
Jun 27, 2008 05:09:07.046 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3256@rachna/42/1214566690893/1883577710211620771185 for owner Thread[http-8080-Processor24,5,main]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - don't load, key requested is null
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3256@rachna/42/1214566690893/1883577710211620771185 mustLoad=false
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185) so it gets invoked on cache.
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3256@rachna/42/1214566690893/1883577710211620771185 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor24,5,main]=[read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]]]}
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893/1883577710211620771185: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3256@rachna/42/1214566690893/1883577710211620771185 for owner Thread[http-8080-Processor24,5,main]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - must Load, uninitialized
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3256@rachna/42/1214566690893/1883577710211620771185 mustLoad=true
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _lock; MethodIdInteger: 33; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, WRITE, false)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _lock; MethodIdInteger: 33; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, WRITE, false)]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, WRITE, false)
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3256@rachna/42/1214566690893/1883577710211620771185 for owner Thread[http-8080-Processor24,5,main]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3256@rachna
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3256@rachna/42
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3256@rachna/42/1214566690893
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3256@rachna/42/1214566690893/1883577710211620771185
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - loadNode /3256@rachna/42/1214566690893/1883577710211620771185
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.loader.JDBCCacheLoader - executing sql: select node from jbosscache where fqn=? (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.loader.ManagedConnectionFactory - Connection checked out: org.apache.tomcat.dbcp.dbcp.PoolableConnection@423606
Jun 27, 2008 05:09:07.186 PM DEBUG org.jboss.cache.marshall.VersionAwareMarshaller - Read version 20
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.marshall.CacheMarshaller200 - Unmarshalled object {somedata}
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - nodeExists true
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - Node data is not null, loading
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - Setting dataLoaded to true
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true) so it gets invoked on cache.
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.CacheImpl.JBossCache-Cluster - _get("/3256@rachna/42/1214566690893/1883577710211620771185", "", "true")
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - No event added. Element does not exist
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor24,5,main]=[read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]]]}
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893/1883577710211620771185: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)]
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - bypassed locking as method _getData() doesn't require locking
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185) so it gets invoked on cache.
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3256@rachna/42/1214566690893/1883577710211620771185 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {}
Jun 27, 2008 05:09:07.202 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 05:09:12.061 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:12.061 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 2 node events in region: /
Jun 27, 2008 05:09:12.061 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:12.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 0ms
Jun 27, 2008 05:09:12.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:12.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 0ms
Jun 27, 2008 05:09:12.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:17.061 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:17.061 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:17.061 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:17.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 5000ms
Jun 27, 2008 05:09:17.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:17.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 5000ms
Jun 27, 2008 05:09:17.061 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted

and after Step 3:

Jun 27, 2008 05:09:32.091 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:32.091 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:32.091 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:32.091 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 20030ms
Jun 27, 2008 05:09:32.091 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:32.091 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 20030ms
Jun 27, 2008 05:09:32.091 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:37.106 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:37.106 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:37.106 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:37.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 25045ms
Jun 27, 2008 05:09:37.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:37.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 25045ms
Jun 27, 2008 05:09:37.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:42.106 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:42.106 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:42.106 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:42.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 30045ms
Jun 27, 2008 05:09:42.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:42.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 30045ms
Jun 27, 2008 05:09:42.106 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:47.121 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:47.121 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:47.121 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:47.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 35060ms
Jun 27, 2008 05:09:47.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:47.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 35060ms
Jun 27, 2008 05:09:47.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:52.121 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:52.121 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:52.121 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:52.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 40060ms
Jun 27, 2008 05:09:52.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:52.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 40060ms
Jun 27, 2008 05:09:52.121 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:57.136 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:09:57.136 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:09:57.136 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:09:57.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 45075ms
Jun 27, 2008 05:09:57.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:09:57.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 45075ms
Jun 27, 2008 05:09:57.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:02.136 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:02.136 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:10:02.136 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:02.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 50075ms
Jun 27, 2008 05:10:02.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:02.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 50075ms
Jun 27, 2008 05:10:02.136 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:03.151 PM DEBUG org.apache.catalina.session.ManagerBase - Start expire sessions StandardManager at 1214566803151 sessioncount 0
Jun 27, 2008 05:10:03.151 PM DEBUG org.apache.catalina.session.ManagerBase - End expire sessions StandardManager processingTime 0 expired sessions: 0
Jun 27, 2008 05:10:07.151 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:07.151 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:10:07.151 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:07.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 55090ms
Jun 27, 2008 05:10:07.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:07.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 55090ms
Jun 27, 2008 05:10:07.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:12.151 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:12.151 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:10:12.151 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:12.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 60090ms
Jun 27, 2008 05:10:12.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:12.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 60090ms
Jun 27, 2008 05:10:12.151 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:17.166 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:17.166 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:10:17.166 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:17.166 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 65105ms
Jun 27, 2008 05:10:17.166 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:17.166 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 65105ms
Jun 27, 2008 05:10:17.166 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:22.181 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:22.181 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:10:22.181 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:22.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 70120ms
Jun 27, 2008 05:10:22.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:22.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 70120ms
Jun 27, 2008 05:10:22.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:27.181 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:27.181 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:10:27.181 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:27.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 75120ms
Jun 27, 2008 05:10:27.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:27.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 75120ms
Jun 27, 2008 05:10:27.181 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3256@rachna/42/1214566690893/1883577710211620771185 for owner Thread[http-8080-Processor25,5,main]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - don't load, key requested is null
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3256@rachna/42/1214566690893/1883577710211620771185 mustLoad=false
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185) so it gets invoked on cache.
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3256@rachna/42/1214566690893/1883577710211620771185 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor25,5,main]=[read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]]]}
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893/1883577710211620771185: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3256@rachna/42/1214566690893/1883577710211620771185 for owner Thread[http-8080-Processor25,5,main]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3256@rachna/42/1214566690893/1883577710211620771185, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3256@rachna/42/1214566690893/1883577710211620771185 mustLoad=false
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/3256@rachna/42/1214566690893/1883577710211620771185, , true) so it gets invoked on cache.
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.CacheImpl.JBossCache-Cluster - _get("/3256@rachna/42/1214566690893/1883577710211620771185", "", "true")
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - No event added. Element does not exist
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor25,5,main]=[read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]]]}
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893/1883577710211620771185: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42/1214566690893: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna/42: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3256@rachna: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)]
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - bypassed locking as method _getData() doesn't require locking
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _getData; MethodIdInteger: 24; Args: (/3256@rachna/42/1214566690893/1883577710211620771185) so it gets invoked on cache.
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3256@rachna/42/1214566690893/1883577710211620771185 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {}
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 05:10:32.196 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:32.196 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 2 node events in region: /
Jun 27, 2008 05:10:32.196 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:32.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 0ms
Jun 27, 2008 05:10:32.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:32.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 0ms
Jun 27, 2008 05:10:32.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:37.196 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 05:10:37.196 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 05:10:37.196 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 05:10:37.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 5000ms
Jun 27, 2008 05:10:37.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted
Jun 27, 2008 05:10:37.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 has been idle for 5000ms
Jun 27, 2008 05:10:37.196 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3256@rachna/42/1214566690893/1883577710211620771185 should not be evicted

7. Re: Passivation false problem

rachna_agg Jun 27, 2008 7:45 AM (in response to rachna_agg)

Here are the Evictoin Policy Details:

<attribute name="EvictionPolicyConfig">
 <config>
 <attribute name="wakeUpIntervalSeconds">5</attribute>
 <attribute name="eventQueueSize">200000</attribute>
 <attribute name="policyClass">
 org.jboss.cache.eviction.LRUPolicy
 </attribute>
 <region name="/">
 <attribute name="maxNodes">500</attribute>
 <attribute name="timeToLiveSeconds">1000</attribute>
 </region>
 <region name="/_default_">
 <attribute name="maxNodes">500</attribute>
 <attribute name="timeToLiveSeconds">1000</attribute>
 </region>
 </config>
 </attribute>

8. Re: Passivation false problem

manik Jun 27, 2008 7:59 AM (in response to rachna_agg)

Umm, I don't think the cache loader is loading the node from the DB for step 3.

...
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke Meth
odName: _get; MethodIdInteger: 31; Args: (/3256@rachna/42/1214566690893/1883577710211620771185)
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - don't load,
 key requested is null
Jun 27, 2008 05:10:31.290 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load elemen
t /3256@rachna/42/1214566690893/1883577710211620771185 mustLoad=false
...

Could be that the statistics are inaccurate. Which version of JBC is this?

9. Re: Passivation false problem

rachna_agg Jun 27, 2008 9:21 AM (in response to rachna_agg)

Which statistics are you talking about? We are using JBossCache-core-2.0.0.GA.
Actions
10. Re: Passivation false problem

manik Jun 27, 2008 9:51 AM (in response to rachna_agg)

I'm guessing you are getting your statistics on hits and misses from JMX?

Have you tried a newer version, 2.1.1.GA or 2.2.0.CR4?
Actions

11. Re: Passivation false problem

rachna_agg Jun 27, 2008 12:09 PM (in response to rachna_agg)

Yes we have enabled JMX in tomcat and are retrieving the statistics from the MBeans "jboss.cache:service=TreeCache,cache-interceptor=CacheLoaderInterceptor" and "jboss.cache:service=TreeCache,cache-interceptor=CacheMgmtInterceptor".

I tried using the newer version 2.1.1.GA but got same results. Here are the logs after Step 2:

Jun 27, 2008 09:36:11.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 09:36:11.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 09:36:11.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 09:36:11.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 10000ms
Jun 27, 2008 09:36:11.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:36:11.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 10000ms
Jun 27, 2008 09:36:11.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:36:16.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 09:36:16.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 09:36:16.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 09:36:16.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 15000ms
Jun 27, 2008 09:36:16.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:36:16.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 15000ms
Jun 27, 2008 09:36:16.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3520@rachna/42/1214582760875/8501033611511983927136 for owner Thread[http-8080-Processor24,5,main]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - don't load, key requested is null
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3520@rachna/42/1214582760875/8501033611511983927136 mustLoad=false
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136) so it gets invoked on cache.
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3520@rachna/42/1214582760875/8501033611511983927136 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor24,5,main]=[read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]]]}
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875/8501033611511983927136: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3520@rachna/42/1214582760875/8501033611511983927136 for owner Thread[http-8080-Processor24,5,main]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor24,5,main], lock=<unlocked>
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - must Load, uninitialized
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3520@rachna/42/1214582760875/8501033611511983927136 mustLoad=true
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _lock; MethodIdInteger: 33; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, WRITE, false)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _lock; MethodIdInteger: 33; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, WRITE, false)]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, WRITE, false)
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3520@rachna/42/1214582760875/8501033611511983927136 for owner Thread[http-8080-Processor24,5,main]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3520@rachna
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3520@rachna/42
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3520@rachna/42/1214582760875
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquireReadLock(): caller Thread[http-8080-Processor24,5,main] already owns lock for /3520@rachna/42/1214582760875/8501033611511983927136
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor24,5,main], lock=read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - loadNode /3520@rachna/42/1214582760875/8501033611511983927136
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.loader.JDBCCacheLoader - executing sql: select node from jbosscache where fqn=? (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:36:20.765 PM DEBUG org.jboss.cache.loader.ManagedConnectionFactory - Connection checked out: org.apache.tomcat.dbcp.dbcp.PoolableConnection@1e2f6b0
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.marshall.VersionAwareMarshaller - Read version 20
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.marshall.CacheMarshaller200 - Unmarshalled object {somedata}
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - nodeExists true
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - Node data is not null, loading
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - Setting dataLoaded to true
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true) so it gets invoked on cache.
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.CacheImpl.JBossCache-Cluster - _get("/3520@rachna/42/1214582760875/8501033611511983927136", "", "true")
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - No event added. Element does not exist
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor24,5,main]=[read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]], read owners=[Thread[http-8080-Processor24,5,main]]]}
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875/8501033611511983927136: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor24,5,main]]
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)]
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - bypassed locking as method _getData() doesn't require locking
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136) so it gets invoked on cache.
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3520@rachna/42/1214582760875/8501033611511983927136 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {}
Jun 27, 2008 09:36:20.781 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 09:36:21.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 09:36:21.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 2 node events in region: /
Jun 27, 2008 09:36:21.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 09:36:21.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 0ms
Jun 27, 2008 09:36:21.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:36:21.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 0ms
Jun 27, 2008 09:36:21.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:36:26.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 09:36:26.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 0 node events in region: /
Jun 27, 2008 09:36:26.531 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 09:36:26.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 5000ms
Jun 27, 2008 09:36:26.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:36:26.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 5000ms
Jun 27, 2008 09:36:26.531 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted

and after Step 3:

Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3520@rachna/42/1214582760875/8501033611511983927136 for owner Thread[http-8080-Processor25,5,main]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - don't load, key requested is null
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3520@rachna/42/1214582760875/8501033611511983927136 mustLoad=false
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 31; Args: (/3520@rachna/42/1214582760875/8501033611511983927136) so it gets invoked on cache.
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3520@rachna/42/1214582760875/8501033611511983927136 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor25,5,main]=[read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]]]}
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875/8501033611511983927136: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - Attempting to lock node /3520@rachna/42/1214582760875/8501033611511983927136 for owner Thread[http-8080-Processor25,5,main]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquiring RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor25,5,main], lock=<unlocked>
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.lock.IdentityLock - acquired RL: fqn=/3520@rachna/42/1214582760875/8501033611511983927136, caller=Thread[http-8080-Processor25,5,main], lock=read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - load element /3520@rachna/42/1214582760875/8501033611511983927136 mustLoad=false
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/3520@rachna/42/1214582760875/8501033611511983927136, , true) so it gets invoked on cache.
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.CacheImpl.JBossCache-Cluster - _get("/3520@rachna/42/1214582760875/8501033611511983927136", "", "true")
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - No event added. Element does not exist
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {Thread[http-8080-Processor25,5,main]=[read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]], read owners=[Thread[http-8080-Processor25,5,main]]]}
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875/8501033611511983927136: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42/1214582760875: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna/42: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /3520@rachna: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - releasing lock for /: read owners=[Thread[http-8080-Processor25,5,main]]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Invoked on cache instance [null] and InvocationContext [InvocationContext{methodCall=MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, skipDataGravitation=false}, originLocal=true, txHasMods=false}]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting up transactional context.
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.TxInterceptor - (null) call on method [MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)]
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - PessimisticLockInterceptor invoked for method MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.PessimisticLockInterceptor - bypassed locking as method _getData() doesn't require locking
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheLoaderInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CacheStoreInterceptor - invoke MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136)
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.CallInterceptor - Passing up method MethodName: _getData; MethodIdInteger: 24; Args: (/3520@rachna/42/1214582760875/8501033611511983927136) so it gets invoked on cache.
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Invoking EvictionInterceptor
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Updating node/element events with no tx
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Adding event EvictedEN[fqn=/3520@rachna/42/1214582760875/8501033611511983927136 event=VISIT_NODE_EVENT diff=0] to region at /
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished updating node
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.EvictionInterceptor - Finished invoking EvictionInterceptor
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.UnlockInterceptor - Attempting to release locks on current thread. Lock table is {}
Jun 27, 2008 09:40:33.765 PM DEBUG org.jboss.cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options
Jun 27, 2008 09:40:36.593 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - process(): region: /
Jun 27, 2008 09:40:36.593 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - processed 2 node events in region: /
Jun 27, 2008 09:40:36.593 PM DEBUG org.jboss.cache.eviction.BaseEvictionAlgorithm - Recycle queue is empty
Jun 27, 2008 09:40:36.593 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 0ms
Jun 27, 2008 09:40:36.593 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted
Jun 27, 2008 09:40:36.593 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 has been idle for 0ms
Jun 27, 2008 09:40:36.593 PM DEBUG org.jboss.cache.eviction.LRUAlgorithm - Node /3520@rachna/42/1214582760875/8501033611511983927136 should not be evicted

Go to original post