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

    Passivation false problem

    Rachna Aggarwal Newbie

      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 Surtani Master

          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.

          • 2. Re: Passivation false problem
            Rachna Aggarwal Newbie

            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

            • 3. Re: Passivation false problem
              Manik Surtani Master

               

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


              • 4. Re: Passivation false problem
                Rachna Aggarwal Newbie

                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 Surtani Master

                      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.

                      • 6. Re: Passivation false problem
                        Rachna Aggarwal Newbie

                        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 Aggarwal Newbie

                          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 Surtani Master

                            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 Aggarwal Newbie

                              Which statistics are you talking about? We are using JBossCache-core-2.0.0.GA.

                              • 10. Re: Passivation false problem
                                Manik Surtani Master

                                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?

                                • 11. Re: Passivation false problem
                                  Rachna Aggarwal Newbie

                                  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