Unexpected Locking on read

[fatbatman]

Hi.

Firstly I've been using JBossCache for a while now and it's a fantastic piece of technology.

That said, I've recently upgraded to JBossAS 5.0.1 and hence to cache 3, and I'm getting some unexpected locking problems.

I've tried to isolate the problem without much luck but have managed to replicate something similar that seems strange.

I deploy the cache in the old JMX style - pojocache-service.xml

<?xml version="1.0" encoding="UTF-8" ?>
<server>
 <mbean code="org.jboss.cache.pojo.jmx.PojoCacheJmxWrapper"
 name="jboss.cache:service=PojoCache">
 <depends>jboss:service=TransactionManager</depends> <depends>jboss.j2ee:jar=jade.jar,name=UserManagerBean,service=EJB3</depends> <depends>jboss.j2ee:jar=jade.jar,name=GameManagerBean,service=EJB3</depends-->
 <attribute name="TransactionManagerLookupClass">org.jboss.cache.transaction.JBossTransactionManagerLookup</attribute>
 <attribute name="IsolationLevel">REPEATABLE_READ</attribute>
 <attribute name="CacheMode">REPL_SYNC</attribute>
 <attribute name="ClusterName">PojoCacheCluster</attribute>
 <attribute name="ClusterConfig">
 <config>
 <UDP mcast_addr="228.1.2.3" mcast_port="48866"
 ip_ttl="64" ip_mcast="true"
 mcast_send_buf_size="150000" mcast_recv_buf_size="80000"
 ucast_send_buf_size="150000" ucast_recv_buf_size="80000"
 loopback="false"/>
 <PING timeout="2000" num_initial_members="3"/>
 <MERGE2 min_interval="10000" max_interval="20000"/>
 <FD shun="true"/>
 <FD_SOCK/>
 <VERIFY_SUSPECT timeout="1500"/>
 <pbcast.NAKACK gc_lag="50" retransmit_timeout="600,1200,2400,4800"
 max_xmit_size="8192"/>
 <UNICAST timeout="600,1200,2400,4800"/>
 <pbcast.STABLE desired_avg_gossip="400000"/>
 <FC max_credits="2000000" min_threshold="0.10"/>
 <FRAG2 frag_size="8192"/>
 <pbcast.GMS join_timeout="5000" join_retry_timeout="2000"
 shun="true" print_local_addr="true"/>
 <pbcast.STATE_TRANSFER/>
 </config>
 </attribute>

 <attribute name="FetchInMemoryState">true</attribute>
 <attribute name="InitialStateRetrievalTimeout">15000</attribute>
 <attribute name="SyncReplTimeout">15000</attribute>

 <!-- Set very low to help recreating the problem -->
 <attribute name="LockAcquisitionTimeout">100</attribute>

 </mbean>
</server>

I access the cache via JMX as follows;

public static org.jboss.cache.pojo.PojoCache getPojoCache() throws Exception {
MBeanServer mbs = MBeanServerLocator.locateJBoss();
PojoCacheJmxWrapperMBean cache = (PojoCacheJmxWrapperMBean) MBeanServerInvocationHandler.newProxyInstance(mbs, new ObjectName("jboss.cache:service=PojoCache"),
PojoCacheJmxWrapperMBean.class, false);
return cache.getPojoCache();
}

Add a Map to it for testing;

getPojoCache().attach("XXX", new Hashtable<String,String>());

I then run two threads one that writes data to the map, the other read from the map.
There are no other threads accessing this note of the cache.

Note - I don't define my own transactions.

Every so often I get a TimeoutException: Unable to acquire lock on Fqn ...
even though only one thread is ever writing to this node.

I thought there wasn't any locking when a element is reading from the cache? What am I doing wrong here? could it be related to me going through JMX?

Note - When I try the same thing in a stand alone test using PojoCacheFactory.createCache(configFile, toStart); all is fine.

regards

James

[fatbatman]

To clarify, should read;

...
"There are no other threads accessing this OBJECT(Hashtable) within the cache."
...

[fatbatman]

....but there was other threads writing to other objects within the cache.

Specifically the problem seems to be this;

public void aSessionBeanMethod(){
Map<String,String> map = (Map<String,String>)getPojoCache().find("XXX");
for(int i=0; i < 100; i++){
map.put(i+"",i+"");
}
}

In this scenario the writes to the Map get steadily slower. I assume because they are batched up into the session beans method transaction, to the point where the last few puts into the Map take nearly a second each.

So my questions are;

1. Why is the above so code so slow and how should I make it faster without moving the code outside of session bean method?
2. Why is the above code locking all writes to all objects stored in the pojocache? how do I set the locking to be per instance, I used to have the following in my pojocache-aop.xml, but the version in the latest download doesn't have this, and adding this back in didn't seem to help;

<!-- Perform parent level node locking -->



Thanks in advance

regards

James

[fatbatman]

Forgot to add CODE tags :)
... the default pojocache-aop.xml used to have the following for locking;

<!-- Perform parent level node locking -->
<interceptor name="TxLock" class="org.jboss.cache.pojo.interceptors.PojoTxLockInterceptor"
 scope="PER_INSTANCE"/>

but as far as I know the default pojocache-aop.xml is now;

<?xml version="1.0" encoding="UTF-8"?>
<!--
 This is a variant of jboss-aop.xml.
-->
<aop>
 <!-- If a POJO has a Replicable annotation, it will be asepectized. -->

 <!--
 Supports inheritance and polymorphism. It can either be a concrete class
 or an interface. All sub-classes or interface implementors will be instrumeneted.
 -->
 <prepare expr="field(* $instanceof{@org.jboss.cache.pojo.annotation.Replicable}->*)" />

 <!-- Work around that ensures annotated classes which do not access fields are instrumented -->
 <introduction expr="class($instanceof{@org.jboss.cache.pojo.annotation.Replicable})"/>

 <!-- Array support -->
 <!-- Comment entire section to disable -->
 <arrayreplacement expr="class($instanceof{@org.jboss.cache.pojo.annotation.Replicable})"/>
 <interceptor name="pojocache-array" class="org.jboss.cache.pojo.interceptors.dynamic.ArrayInterceptor"/>
 <introduction expr="class($instanceof{@org.jboss.cache.pojo.annotation.Replicable})">
 <interfaces>org.jboss.cache.pojo.impl.ArrayInterceptable</interfaces>
 </introduction>
 <arraybind name="pojocache-array" type="READ_WRITE">
 <interceptor-ref name="pojocache-array"/>
 </arraybind>
</aop>

[fatbatman]

By the way this used to work fine on Cache 1.4 on Jboss4.2.

To clarify in the code above each call of; map.put(i+"",i+""); get slower and slower with the last few taking over 1 second each.

As the map get bigger things get progressively slower, so the next time the loop is called it's even slower.
Note this isn't due to excessive logging, the same happens when level is INFO.

In production I do something similar but I write about 500 different entries to a few different lists. By the end this takes over 10 seconds per write causing timeout from other thread that try to write to (different) objects in the cache during that time.

Note - I notice that the session bean in question is being instrumented during (compile time) weaving, I assume because it contains references and accesses some other Replicable objects, but the session bean method I've used for testing I use a Map.