1 2 Previous Next 26 Replies Latest reply on Nov 9, 2007 10:23 AM by Sebastien Pennec

    Strange ClassCastException in OptimisticCreateIfNotExistsInt

    Sebastien Pennec Newbie

      Hi all,

      I'm experiencing a very strange problem, and would like some insight on what's really happening.

      I am using TreeCache 2.0.0, under Weblogic 9.2.2. The app is deployed in a cluster with two members. The cache is configured with REPLY_ASYNC mode, and Optimistic Node Locking Scheme.

      At some point, I would like to refresh completely the data that is present in a given node. Inside a transaction, I remove two data nodes and put new values with updated data. The data is pretty big. It is a SortedSet that holds around 140'000 value objects, each containing a few Strings.

      When the transaction commit, an error is logged by CacheImpl, with the following stacktrace:

      java.lang.ClassCastException: com.myCompany.MyCachedValueObject
       at org.jboss.cache.interceptors.OptimisticCreateIfNotExistsInterceptor.invoke(OptimisticCreateIfNotExistsInterceptor.java:57)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:67)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:99)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.OptimisticReplicationInterceptor.invoke(OptimisticReplicationInterceptor.java:137)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:32)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.TxInterceptor.replayModifications(TxInterceptor.java:511)
       at org.jboss.cache.interceptors.TxInterceptor.handleOptimisticPrepare(TxInterceptor.java:373)
       at org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:250)
       at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:100)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:123)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:62)
       at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3939)
       at org.jboss.cache.CacheImpl._replicate(CacheImpl.java:2853)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:585)
       at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
       at org.jboss.cache.interceptors.CallInterceptor.invoke(CallInterceptor.java:49)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
       at org.jboss.cache.interceptors.OptimisticNodeInterceptor.invoke(OptimisticNodeInterceptor.java:161)
       at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
      


      In the invoke method of OptimisticCreateIfNotExistsInterceptor, the code tries to cast an object into a FQN class.

      The message accompagnying the log statement is as follows:

      Message = replication failure with method_call MethodName: optimisticPrepare; MethodIdInteger: 18; Args:
      (GlobalTransaction:<10.23.65.28:4691>:4, [MethodName: _remove; MethodIdInteger: 40; Args:
      (GlobalTransaction:<10.23.65.28:4691>:4, /Node1/SubNode/SubSubNode1, true, Ver=2), MethodName: _remove;
      MethodIdInteger: 40; Args: (GlobalTransaction:<10.23.65.28:4691>:4, /Node1/SubNode/SubSubNode2, true, Ver=2),
      MethodName: _put; MethodIdInteger: 39; Args: (GlobalTransaction:<10.23.65.28:4691>:4,
      /Node1/SubNode/SubSubNode1, Node_Key, {Whole_ToString()_Value_Of_SortedSet}

      Could anybody help me out with this issue?

      Thanks!

        • 1. Re: Strange ClassCastException in OptimisticCreateIfNotExist
          Manik Surtani Master

          I can't make out too much from the logs you posted. Are you using log4j for logging? Could you enable DEBUG or TRACE level logging?

          Also, is this exception on the instance where you're performing the transaction, or on one of the remote instances where this is replicated to?

          • 2. Re: Strange ClassCastException in OptimisticCreateIfNotExist
            Manik Surtani Master

            Ok, I answered my own question from your stack trace that this is on the remote instance, but still, some more logging would help a bit more.

            Thanks
            Manik

            • 3. Re: Strange ClassCastException in OptimisticCreateIfNotExist
              Sebastien Pennec Newbie

              Hello Manik,

              Here is what I hope will help you. Since I'm not too knowledgable about TreeCache's internals, I selected a few logs that I thought were representing of the situation just before the exception.

              <DEBUG> <14:26:40,328> <Started new local TX as result of remote PREPARE: local TX=Xid=BEA1-018D3B5CD670(42403790),
              Status=Active,numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=0,seconds left=30,activeThread=Thread
              [Incoming Thread,MyApp-TreeCache-Cluster,10.23.65.28:1716,5,Incoming],SCInfo[domain_MyApp+main-env_MyCompany_MyApp_intMgd02]
              =(state=active),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=main-env_MyCompany_MyApp_intMgd02
              +10.23.65.28:6621+domain_MyApp+t3+, XAResources={weblogic.jdbc.wrapper.JTSXAResourceImpl},NonXAResources={})]) (Status=0),
              global TX=GlobalTransaction:<10.23.65.38:1214>:72> <App.TxInterceptor > <org.jboss.cache.interceptors.TxInterceptor.
              handleRemotePrepare(TxInterceptor.java:205)>
              
              <DEBUG> <14:26:40,328> <creating new tx entry> <App.TxInterceptor>
              <org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:239)>
              
              <DEBUG> <14:26:40,328> <Handling optimistic remote prepare GlobalTransaction:<10.23.65.38:1214>:72> <App.TxInterceptor>
              <org.jboss.cache.interceptors.TxInterceptor.handleOptimisticPrepare(TxInterceptor.java:372)>
              
              <DEBUG> <14:26:40,328> <Adding Method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.38:1214>:72,
              /MyApp/DataType1/testDataType1ForCache400-2, true) to modification list> <App.OptimisticNodeInterceptor> <org.jboss.cache.interceptors.
              OptimisticNodeInterceptor.addToModificationList(OptimisticNodeInterceptor.java:202)>
              
              Here are around 30 others messages about _remove calls
              
              <DEBUG> <14:26:47,422> <Adding Method MethodName: _put; MethodIdInteger: 3; Args: (GlobalTransaction:<10.23.65.38:1214>:72,
              /MyApp/Portfolios/Portfolio_cache, item, {BIG_TOSTRING}
              <ERROR> <14:26:59,971> <method invocation failed> <App.TxInterceptor>
              <org.jboss.cache.interceptors.TxInterceptor.replayModifications(TxInterceptor.java:520)>
              java.lang.ClassCastException: com.MyCompany.MyApp.cache.CachedValueObject
               at org.jboss.cache.interceptors.OptimisticCreateIfNotExistsInterceptor.invoke(OptimisticCreateIfNotExistsInterceptor.java:57)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:67)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:99)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.OptimisticReplicationInterceptor.invoke(OptimisticReplicationInterceptor.java:137)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:32)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.TxInterceptor.replayModifications(TxInterceptor.java:511)
               at org.jboss.cache.interceptors.TxInterceptor.handleOptimisticPrepare(TxInterceptor.java:373)
               at org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:250)
               at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:100)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:123)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:62)
               at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3939)
               at org.jboss.cache.CacheImpl._replicate(CacheImpl.java:2853)
               at sun.reflect.GeneratedMethoMyAppcessor92.invoke(Unknown Source)
               at sun.reflect.DelegatingMethoMyAppcessorImpl.invoke(DelegatingMethoMyAppcessorImpl.java:25)
               at java.lang.reflect.Method.invoke(Method.java:585)
               at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
               at org.jboss.cache.interceptors.CallInterceptor.invoke(CallInterceptor.java:49)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.OptimisticNodeInterceptor.invoke(OptimisticNodeInterceptor.java:161)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.EvictionInterceptor.invoke(EvictionInterceptor.java:90)
               at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
               at org.jboss.cache.interceptors.OptimisticCreateIfNotExistsInterceptor.invoke(OptimisticCreateIfNotExistsInterceptor.java:70)
              <DEBUG> <14:26:59,971> <Finished remote prepare GlobalTransaction:<10.23.65.38:1214>:72> <App.TxInterceptor>
              <org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:262)>
              
              


              • 4. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                Manik Surtani Master

                it helps a bit (the CCE happens when replaying transaction modifications on remote instances during a commit) but the logs aren't very detailed.

                Between the

                <DEBUG> <14:26:47,422> <Adding Method MethodName: _put; MethodIdInteger: 3; Args: (GlobalTransaction:<10.23.65.38:1214>:72,
                /MyApp/Portfolios/Portfolio_cache, item, {BIG_TOSTRING}
                


                and

                <ERROR> <14:26:59,971> <method invocation failed> <App.TxInterceptor>
                (stack trace)
                


                lines I would have expected many more lines of logging - especially if you use TRACE level logging.

                I see that you are using WebLogic logging and it could be that this isn't logging everything. Could I ask you to add log4j.jar to your application, as well as a log4j.xml file in your classpath so that this is also logged using log4j? See the JBoss Cache distribution for a sample log4j.xml file.


                • 5. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                  Sebastien Pennec Newbie

                  Hi Manik,

                  I've sent a bunch of logging statements to a file, using log4j and a TRACE level appender.

                  This situation is a real problem for my project, thanks a lot for your help! :)

                  Here they are:

                  
                  
                  2007-11-02 16:02:43,986 413229 TRACE [org.jboss.cache.ReplicationQueue] (Timer-7:) flush(): flushing repl queue (num elements=0)
                  2007-11-02 16:02:44,017 413260 TRACE [org.jgroups.protocols.pbcast.STABLE] (Timer,MyProject-TreeCache-Cluster,10.23.65.38:2818:) setting latest_local_digest from NAKACK: [10.23.65.28:3963#2505, 10.23.65.38:2818#9]
                  2007-11-02 16:02:44,783 414026 TRACE [org.jgroups.protocols.pbcast.STABLE] (Timer,MyProject-TreeCache-Cluster,10.23.65.38:2818:) sending stable msg [10.23.65.28:3963#2505, 10.23.65.38:2818#9]
                  2007-11-02 16:02:44,298 413541 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /
                  2007-11-02 16:02:44,783 414026 TRACE [org.jgroups.protocols.pbcast.NAKACK] (Timer,MyProject-TreeCache-Cluster,10.23.65.38:2818:) sending 10.23.65.38:2818#10
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /
                  2007-11-02 16:02:44,783 414026 TRACE [org.jgroups.protocols.UDP] (Timer,MyProject-TreeCache-Cluster,10.23.65.38:2818:) sending msg to null, src=10.23.65.38:2818, headers are {STABLE=[STABLE_GOSSIP]: digest is 10.23.65.38:2818: [0 : 9 (9)], 10.23.65.28:3963: [0 : 2505 (2508)], NAKACK=[MSG, seqno=10], UDP=[channel_name=MyProject-TreeCache-Cluster]}
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:44,783 414026 TRACE [org.jgroups.protocols.UDP] (Timer,MyProject-TreeCache-Cluster,10.23.65.38:2818:) looping back message [dst: <null>, src: 10.23.65.38:2818 (3 headers), size=0 bytes, flags=OOB]
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType2s
                  2007-11-02 16:02:44,783 414026 TRACE [org.jgroups.protocols.UDP] (UDP mcast receiver,MyProject-TreeCache-Cluster,10.23.65.38:2818:) received (mcast) 157 bytes from 10.23.65.38:6601
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /MyProject/MyDataType2s
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest has been idle for 273700ms
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest should not be evicted
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest has been idle for 273700ms
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest should not be evicted
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType1s
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /MyProject/MyDataType1s
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/NoCliDos_cache has been idle for 366855ms
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/NoCliDos_cache should not be evicted
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache has been idle for 273700ms
                  2007-11-02 16:02:44,783 414026 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache should not be evicted
                  2007-11-02 16:02:44,861 414104 TRACE [org.jgroups.protocols.UDP] (UDP mcast receiver,MyProject-TreeCache-Cluster,10.23.65.38:2818:) received (mcast) 59 bytes from 10.23.65.28:6601
                  2007-11-02 16:02:47,095 416338 TRACE [org.jgroups.protocols.UDP] (UDP mcast receiver,MyProject-TreeCache-Cluster,10.23.65.38:2818:) received (mcast) 59 bytes from 10.23.65.28:6601
                  2007-11-02 16:02:47,111 416354 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Invoked on cache instance [10.23.65.38:2818] and InvocationContext [InvocationContext{methodCall=MethodName: optimisticPrepare; MethodIdInteger: 18; Args: (GlobalTransaction:<10.23.65.28:3963>:5, [MethodName: _remove; MethodIdInteger: 40; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType2s/MyDataType2 de TotoTest, true, Ver=2), MethodName: _remove; MethodIdInteger: 40; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, true, Ver=2), MethodName: _remove; MethodIdInteger: 40; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/NoCliDos_cache, true, Ver=2), MethodName: _put; MethodIdInteger: 39; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, item, {BIG_TOSTRING}
                  
                  
                  
                  
                  2007-11-02 16:02:47,298 416541 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Setting up transactional context.
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Setting tx as Xid=BEA1-006D91DC3593C0F2F661(25018081),Status=Active,numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=14,seconds left=16,activeThread=Thread[Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818,5,Incoming],SCInfo[domain_MyProject+main-env_MyCompany_MyProject_intMgd01]=(state=active),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=main-env_MyCompany_MyProject_intMgd01+10.23.65.38:6611+domain_MyProject+t3+, XAResources={weblogic.jdbc.wrapper.JTSXAResourceImpl},NonXAResources={})],CoordinatorURL=main-env_MyCompany_MyProject_intMgd01+10.23.65.38:6611+domain_MyProject+t3+) and gtx as GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType2s
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /MyProject/MyDataType2s
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest has been idle for 276872ms
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest should not be evicted
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest has been idle for 276872ms
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest should not be evicted
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType1s
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /MyProject/MyDataType1s
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/NoCliDos_cache has been idle for 370027ms
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/NoCliDos_cache should not be evicted
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache has been idle for 276872ms
                  2007-11-02 16:02:47,955 417198 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache should not be evicted
                  2007-11-02 16:02:48,439 417682 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) (10.23.65.38:2818) call on method [MethodName: optimisticPrepare; MethodIdInteger: 18; Args: (GlobalTransaction:<10.23.65.28:3963>:5, [MethodName: _remove; MethodIdInteger: 40; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType2s/MyDataType2 de TotoTest, true, Ver=2), MethodName: _remove; MethodIdInteger: 40; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, true, Ver=2), MethodName: _remove; MethodIdInteger: 40; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/NoCliDos_cache, true, Ver=2), MethodName: _put; MethodIdInteger: 39; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, item, {BIG_TOSTRING}
                  
                  
                  2007-11-02 16:02:49,955 419198 TRACE [org.jboss.cache.ReplicationQueue] (Timer-7:) flush(): flushing repl queue (num elements=0)
                  2007-11-02 16:02:50,298 419541 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /
                  2007-11-02 16:02:50,923 420166 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Got gtx from invocation context GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Creating transaction for thread Thread[Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818,5,Incoming]
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Created new tx for gtx GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType2s
                  2007-11-02 16:02:50,923 420166 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Started new local TX as result of remote PREPARE: local TX=Xid=BEA1-006E91DC3593(40564248),Status=Active,numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=0,seconds left=30,activeThread=Thread[Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818,5,Incoming],SCInfo[domain_MyProject+main-env_MyCompany_MyProject_intMgd01]=(state=active),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=main-env_MyCompany_MyProject_intMgd01+10.23.65.38:6611+domain_MyProject+t3+, XAResources={weblogic.jdbc.wrapper.JTSXAResourceImpl},NonXAResources={})]) (Status=0), global TX=GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /MyProject/MyDataType2s
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Resuming existing transaction Xid=BEA1-006E91DC3593(40564248),Status=Active,numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=0,seconds left=30,activeThread=Thread[Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818,5,Incoming],SCInfo[domain_MyProject+main-env_MyCompany_MyProject_intMgd01]=(state=active),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=main-env_MyCompany_MyProject_intMgd01+10.23.65.38:6611+domain_MyProject+t3+, XAResources={weblogic.jdbc.wrapper.JTSXAResourceImpl},NonXAResources={})]), global TX=GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest has been idle for 279840ms
                  2007-11-02 16:02:50,923 420166 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) creating new tx entry
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest should not be evicted
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) TxTable contents: 2 mappings, 2 transactions
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Setting up transactional context.
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest has been idle for 279840ms
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Setting tx as Xid=BEA1-006E91DC3593(40564248),Status=Active,numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=0,seconds left=30,activeThread=Thread[Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818,5,Incoming],SCInfo[domain_MyProject+main-env_MyCompany_MyProject_intMgd01]=(state=active),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=main-env_MyCompany_MyProject_intMgd01+10.23.65.38:6611+domain_MyProject+t3+, XAResources={weblogic.jdbc.wrapper.JTSXAResourceImpl},NonXAResources={})]) and gtx as GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType2s/MyDataType2 de TotoTest should not be evicted
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) registering for TX completion: SynchronizationHandler(TxInterceptor.RemoteSynchronizationHandler(gtx=GlobalTransaction:<10.23.65.28:3963>:5, tx=weblogic.transaction.internal.ServerTransactionImpl@40564248))
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType1s
                  2007-11-02 16:02:50,923 420166 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Handling optimistic remote prepare GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /MyProject/MyDataType1s
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/NoCliDos_cache has been idle for 372995ms
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/NoCliDos_cache should not be evicted
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Processing method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType2s/MyDataType2 de TotoTest, true)
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache has been idle for 279840ms
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Received method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType2s/MyDataType2 de TotoTest, true) not handling
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache should not be evicted
                  2007-11-02 16:02:50,923 420166 TRACE [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Setting versioning for node /MyProject/MyDataType2s/MyDataType2 de TotoTest to explicit
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) marking node /MyProject/MyDataType2s/MyDataType2 de TotoTest as deleted
                  2007-11-02 16:02:50,939 420182 DEBUG [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Adding Method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType2s/MyDataType2 de TotoTest, true) to modification list
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Invoking EvictionInterceptor
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Updating node/element events with no tx
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Adding event EvictedEN[fqn=/MyProject/MyDataType2s/MyDataType2 de TotoTest event=REMOVE_NODE_EVENT diff=0] to region at /MyProject/MyDataType2s
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished updating node
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished invoking EvictionInterceptor
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Processing method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, true)
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Received method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, true) not handling
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Setting versioning for node /MyProject/MyDataType1s/MyDataType1_cache to explicit
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) marking node /MyProject/MyDataType1s/MyDataType1_cache as deleted
                  2007-11-02 16:02:50,939 420182 DEBUG [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Adding Method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, true) to modification list
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Invoking EvictionInterceptor
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Updating node/element events with no tx
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Adding event EvictedEN[fqn=/MyProject/MyDataType1s/MyDataType1_cache event=REMOVE_NODE_EVENT diff=0] to region at /MyProject/MyDataType1s
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished updating node
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished invoking EvictionInterceptor
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Processing method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/NoCliDos_cache, true)
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Received method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/NoCliDos_cache, true) not handling
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Setting versioning for node /MyProject/MyDataType1s/NoCliDos_cache to explicit
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) marking node /MyProject/MyDataType1s/NoCliDos_cache as deleted
                  2007-11-02 16:02:50,939 420182 DEBUG [org.jboss.cache.interceptors.OptimisticNodeInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Adding Method MethodName: _remove; MethodIdInteger: 5; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/NoCliDos_cache, true) to modification list
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Invoking EvictionInterceptor
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Updating node/element events with no tx
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Adding event EvictedEN[fqn=/MyProject/MyDataType1s/NoCliDos_cache event=REMOVE_NODE_EVENT diff=0] to region at /MyProject/MyDataType1s
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished updating node
                  2007-11-02 16:02:50,939 420182 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished invoking EvictionInterceptor
                  2007-11-02 16:02:51,111 420354 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Processing method MethodName: _put; MethodIdInteger: 3; Args: (GlobalTransaction:<10.23.65.28:3963>:5, /MyProject/MyDataType1s/MyDataType1_cache, item, {BIGF_TOSTRING}
                  
                  
                  2007-11-02 16:02:54,970 424213 TRACE [org.jboss.cache.ReplicationQueue] (Timer-7:) flush(): flushing repl queue (num elements=0)
                  2007-11-02 16:02:54,986 424229 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Invoking EvictionInterceptor
                  2007-11-02 16:02:54,986 424229 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Updating node/element events with no tx
                  2007-11-02 16:02:54,986 424229 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Adding event EvictedEN[fqn=/MyProject/MyDataType1s/MyDataType1_cache event=ADD_ELEMENT_EVENT diff=1] to region at /MyProject/MyDataType1s
                  2007-11-02 16:02:54,986 424229 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished updating node
                  2007-11-02 16:02:54,986 424229 TRACE [org.jboss.cache.interceptors.EvictionInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished invoking EvictionInterceptor
                  2007-11-02 16:02:55,158 424401 TRACE [org.jboss.cache.interceptors.OptimisticReplicationInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Processing method MethodName: _put; MethodIdInteger: 3; Args: (BIG_TOSTRING}
                  
                  
                  2007-11-02 16:02:56,923 426166 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType2s
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 0 node events in region: /MyProject/MyDataType2s
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) process(): region: /MyProject/MyDataType1s
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Adding element /MyProject/MyDataType1s/MyDataType1_cache for a node that doesn't exist yet. Process as an add.
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Adding node /MyProject/MyDataType1s/MyDataType1_cache with 1 elements to eviction queue
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) /MyProject/MyDataType1s/MyDataType1_cache added successfully to eviction queue
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) processed 1 node events in region: /MyProject/MyDataType1s
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.BaseEvictionAlgorithm] (EvictionTimer-0:) Recycle queue is empty
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache has been idle for 0ms
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache should not be evicted
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache has been idle for 0ms
                  2007-11-02 16:02:57,283 426526 TRACE [org.jboss.cache.eviction.LRUAlgorithm] (EvictionTimer-0:) Node /MyProject/MyDataType1s/MyDataType1_cache should not be evicted
                  2007-11-02 16:02:57,298 426541 ERROR [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) method invocation failed
                  java.lang.ClassCastException: com.MyCompany.MyProject.cache.CachedMyDataType1
                   at org.jboss.cache.interceptors.OptimisticCreateIfNotExistsInterceptor.invoke(OptimisticCreateIfNotExistsInterceptor.java:57)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:67)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:99)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.OptimisticReplicationInterceptor.invoke(OptimisticReplicationInterceptor.java:137)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.NotificationInterceptor.invoke(NotificationInterceptor.java:32)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.TxInterceptor.replayModifications(TxInterceptor.java:511)
                   at org.jboss.cache.interceptors.TxInterceptor.handleOptimisticPrepare(TxInterceptor.java:373)
                   at org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:250)
                   at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:100)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:123)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.InvocationContextInterceptor.invoke(InvocationContextInterceptor.java:62)
                   at org.jboss.cache.CacheImpl.invokeMethod(CacheImpl.java:3939)
                   at org.jboss.cache.CacheImpl._replicate(CacheImpl.java:2853)
                   at sun.reflect.NativeMethoMyProjectcessorImpl.invoke0(Native Method)
                   at sun.reflect.NativeMethoMyProjectcessorImpl.invoke(NativeMethoMyProjectcessorImpl.java:39)
                   at sun.reflect.DelegatingMethoMyProjectcessorImpl.invoke(DelegatingMethoMyProjectcessorImpl.java:25)
                   at java.lang.reflect.Method.invoke(Method.java:585)
                   at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:330)
                   at org.jboss.cache.interceptors.CallInterceptor.invoke(CallInterceptor.java:49)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                   at org.jboss.cache.interceptors.OptimisticNodeInterceptor.invoke(OptimisticNodeInterceptor.java:161)
                   at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                  2007-11-02 16:02:57,314 426557 DEBUG [org.jboss.cache.interceptors.TxInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Finished remote prepare GlobalTransaction:<10.23.65.28:3963>:5
                  2007-11-02 16:02:57,314 426557 TRACE [org.jboss.cache.interceptors.InvocationContextInterceptor] (Incoming Thread,MyProject-TreeCache-Cluster,10.23.65.38:2818:) Resetting invocation-scope options
                  


                  • 6. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                    Manik Surtani Master

                    Hmm, I still don't get this. The OptimisticCreateIfNotExistsInterceptor throws a CCE attempting to cast the 2nd argument to an Fqn, but the eviction interceptor before that does manage the cast with no problems.

                    I just tried to recreate this as well, in a unit test, with no luck. Do you have a unit test that can recreate this?

                    • 7. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                      Sebastien Pennec Newbie

                      Well I must admin that it's very strange to me, too.

                      I've seen the line of code that results in the exception, but don't see why my class is being returned at that point.

                      I don't have a test case that can recreate this. Actually, I don't have the slightest idea on how to write a test case that can recreate replication between two members of a cluster.

                      If you have such a test case, I could modify it and make it use my class.

                      • 8. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                        Sebastien Pennec Newbie

                        I changed a few things and might have moved a bit forward....

                        The ClassCast with my class happened with the put being done this way:

                        final InvocationContext invocationContext = treeCache.getInvocationContext();
                        final Option optionOverrides = invocationContext.getOptionOverrides();
                        optionOverrides.setCacheModeLocal(localMode);
                        treeCache.put(fqn, ITEM, map);
                        


                        ... with ITEM being a static final String named "item" just to bind a key to the map.

                        Now I have a class cast, but not on my class. The ClassCast is as follows:

                        java.lang.ClassCastException: java.lang.String
                         at org.jboss.cache.interceptors.OptimisticCreateIfNotExistsInterceptor.invoke(OptimisticCreateIfNotExistsInterceptor.java:57)
                         at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                         at org.jboss.cache.interceptors.OptimisticValidatorInterceptor.invoke(OptimisticValidatorInterceptor.java:67)
                         at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:76)
                         at org.jboss.cache.interceptors.OptimisticLockingInterceptor.invoke(OptimisticLockingInterceptor.java:99)
                        
                        


                        The only thing I changed is the way I put the data in treeCache. It is now done this way:

                        
                        
                        Node<String, Object> node = treeCache.getRoot().getChild(PF_CACHE_FQN);
                         if (node == null) {
                         node = treeCache.getRoot().addChild(fqn);
                         if (logger.isDebugEnabled()) {
                         logger.debug("Added cache child: " + fqn);
                         }
                         }
                        
                        final InvocationContext invocationContext = treeCache.getInvocationContext();
                        final Option optionOverrides = invocationContext.getOptionOverrides();
                        optionOverrides.setCacheModeLocal(localMode);
                        node.put(PF_CACHE_NAME, portfolioCache);
                        


                        ... with PF_CACHE_FQN being a Fqn object to describe the node, and PF_CACHE_NAME being a String that is used as a key to bind the map.

                        Does it help you understand what's going wrong??

                        Thanks a lot for your help!

                        • 10. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                          Manik Surtani Master

                          The other thing that has changed here is that you are now using an Option to suppress replication (cache mode local). Do you have an updated stack trace with this? The previous trace showed the CCE on the remote node when the change is replicated. That won't be the case any more.

                          • 11. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                            Sebastien Pennec Newbie

                            Manik,

                            The localMode variable is not always set to 'true'.

                            When I load the cache at startup-time, both members of the cluster fill their cache based on the data that is in the database. The both fill their cache in local mode, so that one does not invalidate the other's data.

                            Once the app is loaded, when some data is invalidated, then the localMode variable is set to false, meaning that any invalidation or 'put' operation results in a replication.

                            Is that behaviour correct? It seems logical to me, but I might be wrong.

                            To answer your question: the CCE only occurs when replication is happening.

                            Also, I've tested something new, that is replicating a lower amount of data.

                            The data that is being cached are two big maps, typed like this:


                            SortedMap<String, List<CachedData>>
                            and
                            SortedMap<String, CachedData>
                            


                            The are put in two nodes, each under one key. That is:

                            - Node1 - Key1 - Map1.
                            - Node2 - Key2 - Map2.

                            If I make the maps smaller in size (say, 10'000 CachedData objects), everything goes fine.

                            If I fill them with the whole amount of data that I need to cache (around 140'000 objects), then the CCE occurs.

                            I tried to make the map size intermediate, around 50'000 and the CCE occured, too.

                            Could it be that the size of the object (i.e. the SortedMap) that is being cached provokes the CCE?? Or am I doing things badly, and unconsciously provoking the CCE?

                            • 12. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                              Manik Surtani Master

                              Re Options, as a general rule, I recommend not creating and caching the options. Options are meant for single use only, and should not be reused as I cannot guarantee that the option is not modified/reset during the course of a call. If you want to reuse an Option object, make sure you reset() it and then set parameters as needed before each call.

                              But that is probably not what is causing your problem.

                              Your last few statements/observations are very interesting, regarding the size of the map and the fact that the CCE happens on the remote node only (am I correct?). Let me try a few things here, it could have to do with the marshalling algorithm used to marshall payloads (I don't simply serialize them, for performance reasons).

                              • 13. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                                Sebastien Pennec Newbie

                                Thanks for the advice regarding Options.
                                What I always do is these calls:

                                final InvocationContext invocationContext = treeCache.getInvocationContext();
                                final Option optionOverrides = invocationContext.getOptionOverrides();


                                I guess that I recieve a new option object each time, or at least one that is recent enough to apply to the current transaction. Based on what I've been able to observe until now, it seems to work fine.

                                You are correct: the CCE only happens on the remote node.

                                We are heavily using TreeCache on my project, so if I can be of any help to have this problem solved, I'd be more than happy! :-)

                                One more small question (slightly off topic, though): if I setup a TreeCacheListener on the two members of my cluster, and I remove a node in one member: is the other member's listener supposed to be called?

                                Thanks for your support!

                                • 14. Re: Strange ClassCastException in OptimisticCreateIfNotExist
                                  Manik Surtani Master

                                  Ok this is definitely a bug/limitation in the CacheMarshaller.

                                  See JBCACHE-1211.

                                  Thanks for bringing this up.

                                  1 2 Previous Next