JBoss AS 5 deploys EARs much slower than JBoss 4.2
Hi,
We are migrating our application from JBoss 4.2 to JBoss 5, and we have found that JBoss 5 is much slower at deploying EARs than JBoss 4.2. I see in this forum that others have encountered the same problem. JBoss 5 is slow in two areas:
1. When an EAR is deployed, JBoss 5 takes much longer to process it (x3 slower than JBoss 4).
2. The first time a method is called on an EJB, JBoss 5 examines all of the bean's methods in search of interceptors. This takes a long time.
However, after the application has been deployed and all the EJB's have been accessed, the speed is the same as it was in JBoss 4. The slowdown is only in deployment and first use.
This is a huge problem during development because we redeploy the EARs very often on our development machines. In JBoss 4, a redeployment of our main EAR took 10-20 seconds. Now it takes 50-60 seconds. We have another EAR, which uses Seam, and it takes even longer. I'd almost prefer to switch to PHP just for the quick edit-test cycle...
The problem isn't as severe in Production, because we don't redeploy the application on Production that often. However, the slowdown when an EJB is first accessed is still a problem, because it means that the first user to exercise each EJB will see a very slow response time.
In order to demonstrate this problem I wrote a small application, called Cinco in honor of JBoss 5. It contains 10 stateless session beans, each of which contains 50 methods that do nothing. I timed how long it takes to deploy this application in JBoss 4 and 5. In addition, Cinco contains a servlet whose only purpose is to call a method on one of the EJB's. This demonstrates how long it takes to "initialize" the bean. The test machine uses Windows XP, with 2GB RAM. JBoss is in the "all" configuration. JBoss was run in Debug mode from within Eclipse.
The results are:
== Deploy Cinco ==
JBoss 4 - 0:01 sec
JBoss 5 - 0:13 sec
== Initialize one EJB (tested using the LoadBeans servlet) ==
JBoss 4 - 0:00 sec
JBoss 5 - 0:12 sec
Each test was run three times. The timings were very consistent.
== Where does the time go? ==
It takes 13-14 seconds to deploy Cinco.ear (vs. 1 second in JBoss 4). What takes all this time? I turned up the log level in jboss-log4j.xml and tried to understand what is happening. The full log is too long to include here, so I'll show only snippets.
The largest chunk of time is related to interceptors. JBoss begins to deploy the EJB's:
2009-03-31 14:31:05,441 DEBUG [org.jboss.ejb3.deployers.Ejb3Deployer] (HDScanner) ********* Ejb3Deployer Begin Unit: CincoBeans.jar jar: CincoBeans.jar
Then, for each of the 10 EJB's:
First, it does something with interceptors. This takes 0.5 seconds:
2009-03-31 14:31:05,457 DEBUG [org.jboss.ejb3.interceptors.metadata.InterceptorMetaDataBridge] (HDScanner) ======> Creating interceptor metadata bridge
Then, for each of the EJB's 50 methods, it does the following. This takes 0.4 seconds:
2009-03-31 14:31:06,098 DEBUG [org.jboss.aop.microcontainer.beans.GenericBeanAspectFactory] (HDScanner) Creating advice org.jboss.ejb3.tx.CMTTxInterceptorFactory 2009-03-31 14:31:06,098 DEBUG [org.jboss.aop.microcontainer.beans.GenericBeanAspectFactory] (HDScanner) Creating advice org.jboss.ejb3.tx.BMTTxInterceptorFactory
There are 10 EJB's, so the total time is 10 seconds:
2009-03-31 14:31:15,504 DEBUG [org.jboss.ejb3.Ejb3Deployment] (HDScanner) EJB3 deployment time took: 10063
Then, JBoss spends 2 seconds on this:
2009-03-31 14:31:15,504 DEBUG [org.jboss.ejb3.interceptors.registry.InterceptorRegistry] (HDScanner) Found default interceptors [] .... 2009-03-31 14:31:17,613 DEBUG [org.jboss.ejb3.interceptors.registry.InterceptorRegistry] (HDScanner) Found class interceptors []
Then, another 2 seconds are spent binding the beans to JNDI.
And then we come to the end:
2009-03-31 14:31:19,660 DEBUG [org.jboss.deployers.plugins.deployers.DeployersImpl] (HDScanner) Fully Deployed vfszip:/C:/dev/jboss/server/all/deploy/Cinco.ear/
Total time: 14 seconds.
Now for the second scenario: what happens the first time a method is called on an EJB. JBoss initializes the EJB, as follows:
2009-03-31 14:43:52,091 DEBUG [org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory] (http-127.0.0.1-8080-1) org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory servicing request for Cinco/Service01Bean/local 2009-03-31 14:43:52,091 DEBUG [org.jboss.ejb3.common.registrar.plugin.mc.Ejb3McRegistrar] (http-127.0.0.1-8080-1) Returning from name "ProxyFactory/Service01Bean/C inco/Service01Bean/local": org.jboss.ejb3.proxy.factory.session.stateless.StatelessSessionLocalProxyFactory@19f1862 2009-03-31 14:43:52,091 DEBUG [org.jboss.ejb3.proxy.objectfactory.session.SessionProxyObjectFactory] (http-127.0.0.1-8080-1) Created Proxy of type $Proxy455 for EJ B3 Business Interface: com.example.cinco.Service01 2009-03-31 14:43:52,091 DEBUG [org.jboss.ejb3.proxy.handler.ProxyInvocationHandlerBase] (http-127.0.0.1-8080-1) Couldn't handle invocation directly within org.jbos s.ejb3.proxy.handler.session.stateless.StatelessLocalProxyInvocationHandler@569c2a: Current invocation "public abstract void com.example.cinco.Service01.method01()" is not eligible for direct handling by org.jboss.ejb3.proxy.handler.session.stateless.StatelessLocalProxyInvocationHandler@569c2a 2009-03-31 14:43:52,091 DEBUG [org.jboss.ejb3.common.registrar.plugin.mc.Ejb3McRegistrar] (http-127.0.0.1-8080-1) Returning from name "jboss.j2ee:ear=Cinco.ear,jar= CincoBeans.jar,name=Service01Bean,service=EJB3": jboss.j2ee:ear=Cinco.ear,jar=CincoBeans.jar,name=Service01Bean,service=EJB3
Then, for each of the 50 methods, it does this:
2009-03-31 14:43:52,107 DEBUG [org.jboss.aop.microcontainer.beans.GenericBeanAspectFactory] (http-127.0.0.1-8080-1) Creating advice InjectInterceptorsFactory 2009-03-31 14:43:52,107 DEBUG [org.jboss.ejb3.interceptors.aop.InjectInterceptorsFactory] (http-127.0.0.1-8080-1) new InjectInterceptorsFactory 2009-03-31 14:43:52,107 DEBUG [org.jboss.ejb3.interceptors.aop.InjectInterceptorsFactory] (http-127.0.0.1-8080-1) Create interceptor chain for org.jboss.ejb3.aop.ExtendedManagedObjectAdvisor@32070423 on public void com.example.cinco.Service01Bean.method25() 2009-03-31 14:43:52,107 WARN [org.jboss.ejb3.interceptors.registry.InterceptorRegistry] (http-127.0.0.1-8080-1) applicable interceptors is non-existent for public void com.example.cinco.Service01Bean.method25()
Total: 12 seconds to initialize one EJB with 50 methods. If I had called all 10 EJB's, it would have taken 120 seconds.
If you want to reproduce these findings then download Cinco from: http://www.box.net/shared/f1cp9aayyt. I have included both the source code and the EAR (compiled with JBoss 5). Because Cinco needs to run in both JBoss 4 and JBoss 5, I included two versions each of build.xml and .classpath (used with Eclipse):
build.xml-4 build.xml-5 .classpath-4 .classpath-5
For example, to build and run Cinco in JBoss 5, do the following:
1. Start JBoss in the "all" configuration
2. Set environment variable JBOSS_HOME=path to JBoss
3. Rename build.xml-5 to build.xml
4. ant deploy (copies Cinco.ear to $JBOSS_HOME/server/all/deploy)
5. Check the log to see how long it took JBoss to start the EAR
6. Go to http://localhost:8080/cinco/LoadBeans . This servlet calls one method on one of the EJB's, and prints how long that took.
I hope this helps.
Thanks,
Oren
