5 Replies Latest reply on Mar 5, 2007 6:02 AM by manik

    long wait when cache is started

      when i load Jboss and start the cache, i see that the cache initialization takes few minutes.

      The cache is not very big. i use JDBCCacheLoader.

      Is there any way to workaround the long wait?

      10:24:12,645 INFO [InterceptorChainFactory] interceptor chain is:
      class org.jboss.cache.interceptors.CallInterceptor
      class org.jboss.cache.interceptors.PessimisticLockInterceptor
      class org.jboss.cache.interceptors.CacheLoaderInterceptor
      class org.jboss.cache.interceptors.UnlockInterceptor
      class org.jboss.cache.interceptors.CacheStoreInterceptor
      class org.jboss.cache.interceptors.NotificationInterceptor
      class org.jboss.cache.interceptors.TxInterceptor
      class org.jboss.cache.interceptors.CacheMgmtInterceptor
      class org.jboss.cache.interceptors.InvocationContextInterceptor
      10:27:35,124 INFO [CacheImpl] JBoss Cache version: JBossCache 'Habanero' 2.0.0.ALPHA2[ $Id: Version.java,v 1.26 2006/12/30 17:49:54 msurtani Exp $]

        • 1. Re: long wait when cache is started
          manik

          Could you enable trace level logging? Just to test where the time is being spent? Could be in obtaining database connections - are you pooling the connections?

          • 2. Re: long wait when cache is started

            I use standard Jboss data source for pooling connections.

            I noticed it's not always take that long. i still didn't feagure out the reason. We have several developers sharing a DB, so i'm not always aware about all changes in DB - it may happen when one AS start while another is during the process of initializing the cache. This senario won't happen in production. I'll investigate it.

            I'll give the current trace, hoping it would help. If i'll have a better senario, i'll add the relevant log as well.

            The log was very big, so i'll skip some in the middle:

            2007-03-01 23:08:49,489 INFO [org.jboss.cache.factories.InterceptorChainFactory] interceptor chain is:
            class org.jboss.cache.interceptors.CallInterceptor
            class org.jboss.cache.interceptors.PessimisticLockInterceptor
            class org.jboss.cache.interceptors.CacheLoaderInterceptor
            class org.jboss.cache.interceptors.UnlockInterceptor
            class org.jboss.cache.interceptors.CacheStoreInterceptor
            class org.jboss.cache.interceptors.NotificationInterceptor
            class org.jboss.cache.interceptors.TxInterceptor
            class org.jboss.cache.interceptors.CacheMgmtInterceptor
            class org.jboss.cache.interceptors.InvocationContextInterceptor
            2007-03-01 23:08:51,067 DEBUG [org.jboss.cache.loader.CacheLoaderManager] preloading transient state from cache loader org.jboss.cache.loader.JDBCCacheLoader@14ea4a2
            2007-03-01 23:08:51,067 DEBUG [org.jboss.cache.loader.CacheLoaderManager] preloading /
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as null
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/, bla, true)]
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is null
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.CacheImpl] created new GTX: GlobalTransaction:<null>:1, local TX=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16]
            2007-03-01 23:08:51,129 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Registering sync handler for tx TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], gtx GlobalTransaction:<null>:1
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.TxInterceptor] registering for TX completion: SynchronizationHandler(TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<null>:1, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16]))
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/, bla, true)
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/, bla, true)
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] must Load, uninitialized
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element / mustLoad=true
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/)
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists false
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Setting dataLoaded to true
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/, WRITE, false)
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node / for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/, bla, true)
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node / for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/, bla, true) so it gets invoked on cache.
            2007-03-01 23:08:51,145 DEBUG [org.jboss.cache.CacheImpl] _get("/", "bla", "true")
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/)
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__, bla, true)]
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__, bla, true)
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__, bla, true)
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /__JBossInternal__ mustLoad=true
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /__JBossInternal__
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/__JBossInternal__)
            2007-03-01 23:08:51,161 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:08:51,176 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:08:51,176 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/__JBossInternal__
            2007-03-01 23:08:51,176 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/__JBossInternal__, WRITE, false)
            2007-03-01 23:08:51,176 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__ for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__, bla, true)
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__ for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__, bla, true) so it gets invoked on cache.
            2007-03-01 23:08:51,270 DEBUG [org.jboss.cache.CacheImpl] _get("/__JBossInternal__", "bla", "true")
            2007-03-01 23:08:51,286 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:08:51,286 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:08:51,286 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/__JBossInternal__)
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, bla, true)]
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, bla, true)
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, bla, true)
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a mustLoad=true
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a
            2007-03-01 23:08:51,317 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a)
            2007-03-01 23:08:51,379 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, WRITE, false)
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, bla, true)
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a, bla, true) so it gets invoked on cache.
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.CacheImpl] _get("/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a", "bla", "true")
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:08:51,489 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrojzhn-a)
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, bla, true)]
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, bla, true)
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, bla, true)
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61 mustLoad=true
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61
            2007-03-01 23:08:51,520 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61)
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, WRITE, false)
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61 for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,348 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, bla, true)
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61 for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61, bla, true) so it gets invoked on cache.
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.CacheImpl] _get("/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61", "bla", "true")
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftuca-61)
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, bla, true)]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, bla, true)
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, bla, true)
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e mustLoad=true
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e
            2007-03-01 23:08:52,364 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e)
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, WRITE, false)
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, bla, true)
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e, bla, true) so it gets invoked on cache.
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.CacheImpl] _get("/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e", "bla", "true")
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyrorc4h-5e)
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, bla, true)]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:08:52,395 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, bla, true)
            2007-03-01 23:08:52,411 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:08:52,411 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, bla, true)
            2007-03-01 23:08:52,411 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:08:52,411 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60 mustLoad=true
            2007-03-01 23:08:52,411 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60
            2007-03-01 23:08:52,411 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60)
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, WRITE, false)
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60 for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, bla, true)
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60 for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60, bla, true) so it gets invoked on cache.
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.CacheImpl] _get("/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60", "bla", "true")
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:08:52,426 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrftubf-60)
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, bla, true)]
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, bla, true)
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, bla, true)
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w mustLoad=true
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w)
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, WRITE, false)
            2007-03-01 23:08:52,442 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, bla, true)
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w for owner GlobalTransaction:<null>:1
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w, bla, true) so it gets invoked on cache.
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.CacheImpl] _get("/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w", "bla", "true")
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/__JBossInternal__/5c4oa2y-64ssue-eyro7iw5-1-eyroreif-5w)
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/__JBossInternal__/5c4oa2y-4fydgh-eyrfhgzk-1-eyrg9460-fw, bla, true)]
            2007-03-01 23:08:52,458 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            
            ...
            ...
            ... skip a lot of lines
            ...
            ...
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1, bla, true) so it gets invoked on cache.
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.CacheImpl] _get("/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1", "bla", "true")
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:09:15,662 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, bla, true)]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, bla, true)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, bla, true)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11 mustLoad=true
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, WRITE, false)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11 for owner GlobalTransaction:<null>:1
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, caller=GlobalTransaction:<null>:1, lock=<unlocked>
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, bla, true)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11 for owner GlobalTransaction:<null>:1
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CallInterceptor] Passing up method MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11, bla, true) so it gets invoked on cache.
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.CacheImpl] _get("/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11", "bla", "true")
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.NotificationInterceptor] Adding [] to transaction entry's notification list
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting invocation-scope options
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select fqn from jbosscache_application where parent=? (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-6-SIBLINGS_IN_LEVEL-11-11)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on cache instance [null] and InvocationContext [InvocationContext{transaction=TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16], globalTransaction=GlobalTransaction:<null>:1, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, forceDataGravitation=false, bypassInterceptorChain=false}, originLocal=true, txHasMods=false}]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up transactional context.
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx as TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] and gtx as GlobalTransaction:<null>:1
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (null) call on method [MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7, bla, true)]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[main,5,jboss]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Associated gtx in txTable is GlobalTransaction:<null>:1
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=gil-pc/16, BranchQual=, localId=16] is already registered.
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] CacheStoreInterceptor called with meth MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7, bla, true)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheStoreInterceptor] transactional so don't put stuff in the cloader yet.
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] invoke MethodName: _get; MethodIdInteger: 26; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7, bla, true)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] mustLoad, node null
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] load element /aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7 mustLoad=true
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] loadNode /aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.loader.JDBCCacheLoader] executing sql: select node from jbosscache_application where fqn=? (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] nodeExists true
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.CacheLoaderInterceptor] Node data is not null, loading
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.UnversionedNode] created child: fqn=/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] PessimisticLockInterceptor invoked for method MethodName: _lock; MethodIdInteger: 33; Args: (/aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7, WRITE, false)
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.interceptors.PessimisticLockInterceptor] Attempting to lock node /aag/queries/d1-2-d2-0-d3-41-d4-1527-d5-0-d6-0-d7-0-d8-84-24-1/queryDefinition3-7-SIBLINGS_IN_LEVEL-7-7 for owner GlobalTransaction:<null>:1
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquired RL: fqn=/aag, caller=GlobalTransaction:<null>:1, lock=read owners=[GlobalTransaction:<null>:1]
            2007-03-01 23:09:15,677 DEBUG [org.jboss.cache.lock.IdentityLock] acquiring RL: fqn=/aag/queries, caller=GlobalTransaction:<null>:1, lock=read owners=[Global


            • 3. Re: long wait when cache is started
              manik

              It just looks like the time taken to load a lot of stuff from the cache loader. This can be slow if:

              1) Connections to your DB are slow (I'm assuming minimal overhead in connection establishment since they're pooled)
              2) State in your DB is large

              In JBoss Cache 2.0.0.BETA1 (which should be released shortly) we have a much faster JDBCCacheLoader implementation.

              • 4. Re: long wait when cache is started

                What do you mean in

                2) State in your DB is large
                ? the state of the cache?

                • 5. Re: long wait when cache is started
                  manik

                  Specifically, the state that is passivated/stored in the DB and is preloaded. E.g., if you preload "/" on startup this will take time. If you only preload certain regions that you foresee may be needed as soon as the system starts up (and leave the rest to load lazily), this may be quicker.