ClusteredCacheLoader

[lovelyliatroim]

Hi Guys,
Im seeing what i can only explain as strange behaviour using the ClusteredcacheLoader. Ok I´ll try and explain what im seeing. I have tried my code both with and without the ClusteredCacheLoader, everything works as expected when i dont have the cacheloader configured which leads me to believe it is something to do with my cache loader.

I have 2 nodes both running on tomcat (One actually runs on tomcat 5 and other tomcat 6 (dont ask))

As i said, without ClusteredcacheLoader, everything works fine.

Ok, I´ll try and explain, Node 1 and Node 2 are empty. Node 1 receives a request for data item X. Request for data Item X triggers 2 calls and 2 entries to be put into the cache. The path for data item 1 looks like so

/a/b(2)

Entry into the cache for data item 2 looks like so
/b/c/d/e(2)

*(2) This is the no of elements in the hashmap of the node. 1 is the custom object that i want to store and the other the expiration element needed for the expiration policy.

Im using the expiration eviction policy, the timeout for the first daa item is 15 mins and the 2nd is a week.

Now heres what happens.

I make the first request for data item X, its not there so i put 2 entries into the cache. What i expect to see is this
/a/b(2)
/b/c/d/e(2)

I look at my custom made mbean to view the cache tree and i see entries like so
/a(0)
/b(0)

I make a 2nd request, still within time frame and i see the following
/a/b(2)
/b/c(0)

I now have an entry in the cache for the first data element but still not the 2nd.

I make a third request and i see
/a/b(2)
/b/c/d(0)

I get a hit for the first data element but still not the 2nd.

And finally i make the 4th request and afterwards i see
/a/b(2)
/b/c/d/e(2)

So finally after 4 requests the same data item gets put into the cache. It looks like with every time i make a request it stores the extra path element. i.e
1st request /b
2nd /b/C
3rd /b/c/d
4th /b/c/d/e

Any ideas as to whats going on, the nodes have the same config, i havent changed "ClusterConfig" for the 2 nodes, should i?? Maybe port changes??(I need to read up on the jgroups side of things).

On another note, is there anything like jmx-console that runs in tomcat?? So i can use the jmx-beans that come out of the box with jboss-core, i mean more in relation to the tree structure, JConsole doesnt give me the nice tree structure that i would get when using jmx-console.

Like i said earlier, it works as i expect without the CacheLoader configured. I´m running the cache in REPL_ASYNC with a bit of hack like so

treeCache.getInvocationContext().getOptionOverrides().setCacheModeLocal(true);

for every item added to the cache to stop them from been replicated to other nodes. Also its the 2.1 version im using.

Thanks,
LL

[manik]

Wow, that is weird behaviour. Do you see this with other cache loaders as well (e.g., FileCacheLoader)?

I can't say we've seen this one before.

I don't think it has anything to do with your JGroups setup though.

Could you pls post your config?

[lovelyliatroim]

Config is like so

<server>


<!-- ==================================================================== -->
 <!-- NON PERSISTENT CACHE CONFIG -->
 <!-- ==================================================================== -->

 <mbean code="org.jboss.cache.jmx.CacheJmxWrapper"
 name="jboss.cache:service=CMDSNonPersistentCache">

 <depends>jboss:service=Naming</depends>
 <depends>jboss:service=TransactionManager</depends>

 <!--
 Configure the TransactionManager

 <attribute name="TransactionManagerLookupClass">org.jboss.cache.transaction.GenericTransactionManagerLookup
 </attribute>
-->



 <!--
 Node locking level : SERIALIZABLE
 REPEATABLE_READ (default)
 READ_COMMITTED
 READ_UNCOMMITTED
 NONE
 -->
 <attribute name="IsolationLevel">REPEATABLE_READ</attribute>

 <!--
 Valid modes are LOCAL
 REPL_ASYNC
 REPL_SYNC
 INVALIDATION_ASYNC
 INVALIDATION_SYNC
 -->
 <attribute name="CacheMode">REPL_ASYNC</attribute>

 <!-- Name of cluster. Needs to be the same for all clusters, in order
 to find each other
 -->
 <attribute name="ClusterName">CMDS-Cluster</attribute>

 <!-- JGroups protocol stack properties NOT NEEDED since CacheMode is LOCAL -->

 <!--
 The max amount of time (in milliseconds) we wait until the
 state (ie. the contents of the cache) are retrieved from
 existing members in a clustered environment
 -->
 <attribute name="StateRetrievalTimeout">20000</attribute>

 <!--
 Number of milliseconds to wait until all responses for a
 synchronous call have been received.
 -->
 <attribute name="SyncReplTimeout">20000</attribute>

 <attribute name="FetchInMemoryState">false</attribute>



 <!-- Max number of milliseconds to wait for a lock acquisition -->
 <attribute name="LockAcquisitionTimeout">15000</attribute>

 <attribute name="ClusterConfig">
 <config>
 <UDP mcast_addr="228.10.10.10"
 mcast_port="45588"
 tos="8"
 ucast_recv_buf_size="20000000"
 ucast_send_buf_size="640000"
 mcast_recv_buf_size="25000000"
 mcast_send_buf_size="640000"
 loopback="false"
 discard_incompatible_packets="true"
 max_bundle_size="64000"
 max_bundle_timeout="30"
 use_incoming_packet_handler="true"
 ip_ttl="2"
 enable_bundling="false"
 enable_diagnostics="true"

 use_concurrent_stack="true"

 thread_naming_pattern="pl"

 thread_pool.enabled="true"
 thread_pool.min_threads="1"
 thread_pool.max_threads="25"
 thread_pool.keep_alive_time="30000"
 thread_pool.queue_enabled="true"
 thread_pool.queue_max_size="10"
 thread_pool.rejection_policy="Run"

 oob_thread_pool.enabled="true"
 oob_thread_pool.min_threads="1"
 oob_thread_pool.max_threads="4"
 oob_thread_pool.keep_alive_time="10000"
 oob_thread_pool.queue_enabled="true"
 oob_thread_pool.queue_max_size="10"
 oob_thread_pool.rejection_policy="Run"/>

 <PING timeout="2000" num_initial_members="3"/>
 <MERGE2 max_interval="30000" min_interval="10000"/>
 <FD_SOCK/>
 <FD timeout="10000" max_tries="5" shun="true"/>
 <VERIFY_SUSPECT timeout="1500"/>
 <pbcast.NAKACK max_xmit_size="60000"
 use_mcast_xmit="false" gc_lag="0"
 retransmit_timeout="300,600,1200,2400,4800"
 discard_delivered_msgs="true"/>
 <UNICAST timeout="300,600,1200,2400,3600"/>
 <pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000"
 max_bytes="400000"/>
 <pbcast.GMS print_local_addr="true" join_timeout="5000"
 join_retry_timeout="2000" shun="false"
 view_bundling="true" view_ack_collection_timeout="5000"/>
 <FRAG2 frag_size="60000"/>
 <pbcast.STREAMING_STATE_TRANSFER use_reading_thread="true"/>
 <!-- <pbcast.STATE_TRANSFER/> -->
 <pbcast.FLUSH timeout="0"/>
 </config>
 </attribute>

 <!-- Specific eviction policy configurations. This is LRU -->
 <attribute name="EvictionPolicyConfig">
 <config>
 <attribute name="wakeUpIntervalSeconds">5</attribute>
 <attribute name="eventQueueSize">200000</attribute>
 <attribute name="policyClass">org.jboss.cache.eviction.LRUPolicy</attribute>

 <region name="/_default_">
 <attribute name="maxNodes">500000</attribute>
 <attribute name="timeToLiveSeconds">900</attribute>
 </region>

 <region name="/ricIds" policyClass="org.jboss.cache.eviction.ExpirationPolicy">
 <attribute name="maxNodes">50000</attribute>
 </region>
 <region name="/quotes" policyClass="org.jboss.cache.eviction.ExpirationPolicy">
 <attribute name="maxNodes">50000</attribute>
 </region>

 <!--There are other regions configured but have removed them for simplicity -->


 </config>
 </attribute>


 <attribute name="CacheLoaderConfig" replace="false">
 <config>
 <cacheloader>
 <class>org.jboss.cache.loader.ClusteredCacheLoader</class>
 <properties>
 timeout=15000
 </properties>
 </cacheloader>
 </config>
 </attribute>

 </mbean>

</server>

/ricIds = /b/c/d/e (Given in example)
/quotes = /a/b.

Do you see this with other cache loaders as well (e.g., FileCacheLoader)?

When i get the time i will try it out and let you know how it goes.


What i do see alot of entries on the log file is for this

11:07:26 [EvictionTimer-0] WARN eviction.ExpirationAlgorithm - Unable to remove nodes to reduce region size below 50000. Set expiration for nodes in this region

Now why would i get this warning when the cache is practically empty?? Might and mightnt be related!!

[lovelyliatroim]

Do you see this with other cache loaders as well (e.g., FileCacheLoader)?

Just tried it there with the berkley cache loader and i have no problems with it!! Works as expected!!

[manik]

ok; do you have this in a form of a unit test? Also, have you tried it with the recent 2.2.0.CR1 that I released yesterday?

[lovelyliatroim]

have you tried it with the recent 2.2.0.CR1 that I released yesterday?

Just tried it there, just swapped the jboss-core.jar file all other libs belong to the 2.1 version. Still getting the same problem.

do you have this in a form of a unit test?

Nope but i guess your next question will be can you write one, will try to before the day is out otherwise wont get to it till monday!!

[lovelyliatroim]

Actually you dont need 2 nodes up and running, occurs standalone as well.

[manik]

"lovelyliatroim" wrote:
Nope but i guess your next question will be can you write one, will try to before the day is out otherwise wont get to it till monday!!

:-) You read my mind!

Sorry, it just means I can deal with it quicker if it is in the form of a TestNG unit test that I can drop in to the test suite and work with.

[lovelyliatroim]

Ok found the problem area!!!

It is something to do with my custom MBean, why it causes this behaviour i dont know.


To replicate, just take the following. (Sorry i didnt get a chance to put in test case but it should be easy to copy and paste this into one).

{
 CacheFactory factory = DefaultCacheFactory.getInstance();
 Cache cache = factory.createCache(configPath);
 CacheJmxWrapperMBean wrapper = new CacheJmxWrapper(cache);
 wrapper.create();
 wrapper.start();
 System.out.println("Cache created");

 String quotePath = "/quotes/quoteA";
 String ricPath = "/ricIds/A/B/C";

 String key = "quote", value = "10;19";
 Long future = new Long(System.currentTimeMillis() + 604800000);

 cache.getInvocationContext().getOptionOverrides().setCacheModeLocal(true);
 cache.put(quotePath, key, value);
 cache.getInvocationContext().getOptionOverrides().setCacheModeLocal(true);
 cache.put(quotePath,CacheConstants.EXPIRATION_KEY, future);


 cache.getInvocationContext().getOptionOverrides().setCacheModeLocal(true);
 cache.put(ricPath, key, value);
 cache.getInvocationContext().getOptionOverrides().setCacheModeLocal(true);
 cache.put(ricPath,CacheConstants.EXPIRATION_KEY, future);

 cache.getRoot().getChild("quotes").setResident(true);


 //Remove this block and works as normal
 StringBuilder b = new StringBuilder();
 Node n = cache.getRoot();
 Node node = n.getChild(Fqn.fromString("/"));
 Iterator i = node.getChildren().iterator();
 while(i.hasNext()){
 Object child = i.next();
 if(child instanceof NodeInvocationDelegate){
 getLastNode((NodeInvocationDelegate)child,b);
 }
 }

 System.out.println(b.toString());


 Object quoteObj = cache.get(quotePath, key);
 Object ricObj = cache.get(ricPath, key);

 System.out.println("quoteObj= " +quoteObj);
 System.out.println("ricObj =" +ricObj);

 cache.stop();
 cache.destroy();
 }

private void getLastNode(NodeInvocationDelegate parent,StringBuilder nodeList){
 if(parent.getChildren().size() == 0){
 //reached the end node
 nodeList.append(parent.getFqn().toString()+"("+parent.dataSize() +")\n");
 return;
 }
 Iterator<Object> i = parent.getChildren().iterator();
 while(i.hasNext()){
 Object child = i.next();
 if(child instanceof NodeInvocationDelegate){
 NodeInvocationDelegate subNode = (NodeInvocationDelegate)child;
 getLastNode(subNode,nodeList);
 }
 }
 }

I have taken snippets of all code and mashed it all together to reproduce whats happening.Its not exactly happening in the above snippet as i explained earlier.

What i see as output for the above running is

Cache created

quoteObj= null
ricObj =null

I would have expected to see
quotes/quoteA(2)
/ricIds/A/B/C(2)


Maybe i shouldnt be doing what im doing to see whats in the tree, i wanted to create something similar to whats in the jmx-console so i can have a nice tree path view of whats paths and how many elements in the tree.

Wont be around till monday but if you dont call the mbean code, it works as normal!! Strange though!!

[lovelyliatroim]

Any update on why this occurs??

Thanks,
LL

[manik]

I've found your problem. It is a bug, detailed here: JBCACHE-1360.

Sadly the fix missed 2.2.0.CR2 which I released earlier today. If you want to try out the fix, I'd recommend grabbing trunk from SVN and building it yourself.

Cheers
Manik

[lovelyliatroim]

Thanks Manik, at least I know what the problem is now!!