High class loading synchronization time in CR2

[rododendro.ivan]

Hello,
we were benching our application in CR2 and we've found the throughput scaled down of a factor of 3. After a quite deep analysys it turns out that there's a serious problem of thread syncronization in jboss' BaseClassloader.

Essentially 5 out of 10 threads serving the client threads are blocked waiting for a lock:

"WorkerThread#9[10.10.164.139:3007]" prio=1 tid=0x4f9f5628 nid=0x1434 waiting for monitor entry [0x2df22000..0x2df24030]
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoader.java:352)
 - waiting to lock <0x7478c838> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
 at org.jboss.ejb3.common.lang.SerializableMethod.getClassFromName(SerializableMethod.java:344)
 at org.jboss.ejb3.common.lang.SerializableMethod.getClassType(SerializableMethod.java:281)
 at org.jboss.ejb3.common.lang.SerializableMethod.toMethod(SerializableMethod.java:232)
 at org.jboss.ejb3.common.lang.SerializableMethod.toMethod(SerializableMethod.java:219)
 at org.jboss.ejb3.proxy.handler.ProxyInvocationHandlerBase.handleInvocationDirectly(ProxyInvocationHandlerBase.java:149)
 at org.jboss.ejb3.proxy.handler.session.SessionSpecProxyInvocationHandlerBase.invoke(SessionSpecProxyInvocationHandlerBase.java:94)
 at $Proxy359.findByKeyAndValue(Unknown Source)
 at com.gemalto.srm.impl.capability.CapabilityKeySessionBean.getOrCreateCapabilityKeyAndValue(CapabilityKeySessionBean.java:244)

Bench tests are attacking the API EJBs on the remote interface and the EJB's implementation calls an entity facade (EJB) on local interface.

CapabilityKeySessionBean

is the API EJB and

$Proxy359.findByKeyAndValue(Unknown Source)

is the call on entity facade local interface.

Activating the log on BaseClassloader we colud see that each class (even JDK's classes) is searched by BaseClassloader in a syncrhonized method even if the class is already loaded:

2008-10-09 16:40:38,868 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] BaseClassLoader@1c69f7b{vfsfile:/product/1_linqus/jboss-5.0.0.CR2_Patch01/server/default/deploy/srm.ear/} loadClass java.lang.Object resolve=false
2008-10-09 16:40:38,868 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] BaseClassLoader@1c69f7b{vfsfile:/product/1_linqus/jboss-5.0.0.CR2_Patch01/server/default/deploy/srm.ear/} already loaded class class java.lang.Object{cl=null codeSource=null}
2008-10-09 16:40:38,868 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] BaseClassLoader@1c69f7b{vfsfile:/product/1_linqus/jboss-5.0.0.CR2_Patch01/server/default/deploy/srm.ear/} loadClass java.lang.Object resolve=false
2008-10-09 16:40:38,868 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] BaseClassLoader@1c69f7b{vfsfile:/product/1_linqus/jboss-5.0.0.CR2_Patch01/server/default/deploy/srm.ear/} already loaded class class java.lang.Object{cl=null codeSource=null}
2008-10-09 16:40:38,868 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] BaseClassLoader@1c69f7b{vfsfile:/product/1_linqus/jboss-5.0.0.CR2_Patch01/server/default/deploy/srm.ear/} loadClass java.lang.Object resolve=false
2008-10-09 16:40:38,868 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] BaseClassLoader@1c69f7b{vfsfile:/product/1_linqus/jboss-5.0.0.CR2_Patch01/server/default/deploy/srm.ear/} already loaded class class java.lang.Object{cl=null codeSource=null}
2008-10-09 16:40:38,868 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] BaseClassLoader@1c69f7b{vfsfile:/product/1_linqus/jboss-5.0.0.CR2_Patch01/server/default/deploy/srm.ear/} loadClass java.lang.Object resolve=false

As you can see the class object is searched many times in even if it has already been loaded (The synchonized method is loadClass)

I am not at all an expert of java classloading but I found it almost surprising.

We re-deployed the same application in CR1 running on the same hardware and no synchronization problem was found.

I did not found any related bug on JIRA, am I missing something ?

Thank you
Ivan

[adrian.brock]

Good catch. ;-)

https://jira.jboss.org/jira/browse/JBCL-49