5.0.0.Beta4 startup performance problem

[gcoleman]

I've got an ear with about 30 EJB modules. The modules are either all entity beans or all SLSBs/MDBs (this is to let us migrate session beans to EJB3 without having to do the entities at the same time).

I've got two versions of the same ear: one pre-migration with all EJB2 modules, and one where all the session bean modules have been migrated to EJB3.

On JBoss 5 the mixed EJB2/EJB3 takes a VERY long time to start up - anywhere between 10 and 30 minutes and is pegged at about 25% CPU for most of that time. The EJB2 only ear takes about 2 minutes.

I've done some thread dumps and the main deployer thread is more often than not here:

"main" prio=6 tid=0x044b7430 nid=0x10b4 runnable [0x049cd000..0x049cf9f8]
 at java.lang.Throwable.fillInStackTrace(Native Method)
 at java.lang.Throwable.<init>(Throwable.java:196)
 at java.lang.Exception.<init>(Exception.java:41)
 at javax.management.JMException.<init>(JMException.java:35)
 at javax.management.OperationsException.<init>(OperationsException.java:36)
 at javax.management.MalformedObjectNameException.<init>(MalformedObjectNameException.java:35)
 at javax.management.ObjectName.construct(ObjectName.java:393)
 at javax.management.ObjectName.<init>(ObjectName.java:1304)
 at org.jboss.ejb3.dependency.EjbLinkDemandMetaData$EjbLinkDemandDependencyItem.resolve(EjbLinkDemandMetaData.java:134)
 at org.jboss.dependency.plugins.AbstractDependencyInfo.resolveDependencies(AbstractDependencyInfo.java:140)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:901)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:839)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:784)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:622)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:411)
 at org.jboss.system.ServiceController.doChange(ServiceController.java:659)
 at org.jboss.system.ServiceController.create(ServiceController.java:393)
 at org.jboss.system.ServiceController.create(ServiceController.java:358)
 at sun.reflect.GeneratedMethodAccessor212.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
 at org.jboss.system.ServiceMBeanSupport.create(ServiceMBeanSupport.java:186)
 at org.jboss.ejb.EntityContainer.createService(EntityContainer.java:286)
 at org.jboss.system.ServiceMBeanSupport.jbossInternalCreate(ServiceMBeanSupport.java:267)
 at org.jboss.system.ServiceMBeanSupport.jbossInternalLifecycle(ServiceMBeanSupport.java:243)
 at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
 at org.jboss.system.microcontainer.ServiceProxy.invoke(ServiceProxy.java:167)
 at $Proxy5.create(Unknown Source)
 at org.jboss.system.microcontainer.CreateDestroyLifecycleAction.installAction(CreateDestroyLifecycleAction.java:42)
 at org.jboss.system.microcontainer.CreateDestroyLifecycleAction.installAction(CreateDestroyLifecycleAction.java:37)
 at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62)
 at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71)
 at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51)
 at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:327)
 at org.jboss.system.microcontainer.ServiceControllerContext.install(ServiceControllerContext.java:255)
 at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1309)
 at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:734)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:862)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:784)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:622)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:411)
 at org.jboss.system.ServiceController.doChange(ServiceController.java:659)
 at org.jboss.system.ServiceController.create(ServiceController.java:393)
 at sun.reflect.GeneratedMethodAccessor211.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
 at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210)
 at $Proxy306.create(Unknown Source)
 at org.jboss.ejb.EjbModule.createService(EjbModule.java:408)
 at org.jboss.system.ServiceMBeanSupport.jbossInternalCreate(ServiceMBeanSupport.java:267)
 at org.jboss.system.ServiceMBeanSupport.jbossInternalLifecycle(ServiceMBeanSupport.java:243)
 at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
 at org.jboss.system.microcontainer.ServiceProxy.invoke(ServiceProxy.java:167)
 at $Proxy5.create(Unknown Source)
 at org.jboss.system.microcontainer.CreateDestroyLifecycleAction.installAction(CreateDestroyLifecycleAction.java:42)
 at org.jboss.system.microcontainer.CreateDestroyLifecycleAction.installAction(CreateDestroyLifecycleAction.java:37)
 at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62)
 at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71)
 at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51)
 at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:327)
 at org.jboss.system.microcontainer.ServiceControllerContext.install(ServiceControllerContext.java:255)
 at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1309)
 at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:734)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:862)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:784)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:622)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:411)
 at org.jboss.system.ServiceController.doChange(ServiceController.java:659)
 at org.jboss.system.ServiceController.create(ServiceController.java:393)
 at org.jboss.system.ServiceController.create(ServiceController.java:358)
 at org.jboss.system.deployers.ServiceDeployer.create(ServiceDeployer.java:145)
 at org.jboss.system.deployers.ServiceDeployer.deploy(ServiceDeployer.java:105)
 at org.jboss.system.deployers.ServiceDeployer.deploy(ServiceDeployer.java:46)
 at org.jboss.deployers.spi.deployer.helpers.AbstractSimpleRealDeployer.internalDeploy(AbstractSimpleRealDeployer.java:65)
 at org.jboss.deployers.spi.deployer.helpers.AbstractRealDeployer.deploy(AbstractRealDeployer.java:50)
 at org.jboss.deployers.plugins.deployers.DeployerWrapper.deploy(DeployerWrapper.java:169)
 at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:853)
 at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:874)
 at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:906)
 at org.jboss.deployers.plugins.deployers.DeployersImpl.install(DeployersImpl.java:794)
 at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:327)
 at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1309)
 at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:734)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:862)
 at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:784)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:622)
 at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:411)
 at org.jboss.deployers.plugins.deployers.DeployersImpl.process(DeployersImpl.java:498)
 at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:506)
 at org.jboss.system.server.profileservice.ProfileServiceBootstrap.loadProfile(ProfileServiceBootstrap.java:246)
 at org.jboss.system.server.profileservice.ProfileServiceBootstrap.start(ProfileServiceBootstrap.java:131)
 at org.jboss.bootstrap.AbstractServerImpl.start(AbstractServerImpl.java:408)
 at org.jboss.Main.boot(Main.java:208)
 at org.jboss.Main$1.run(Main.java:534)
 at java.lang.Thread.run(Thread.java:595)

The deployment itself does not succeed because of some dependency problems between beans - I don't know if this is a problem with our deployment descriptors and annotations or a JBoss problem.

10:50:12,829 ERROR [ProfileServiceBootstrap] [main] Failed to load profile: Summary of incomplete deployments (SEE PREVIOUS ERRORS FOR DETAILS):

*** CONTEXTS MISSING DEPENDENCIES: Name -> Dependency{Required State:Actual State}

jboss.j2ee:ear=app.ear,jar=framework-ejbs.jar,name=UpgradeManager,service=EJB3
 -> <UNKNOWN>{Described:** UNRESOLVED Demands 'jboss.j2ee:ear=app.ear,name=UserProfile,service=EJB3,* **}
 -> <UNKNOWN>{Described:** UNRESOLVED Demands 'jboss.ejb:service=EJBTimerService **}
 -> <UNKNOWN>{Described:** UNRESOLVED Demands 'jboss.j2ee:ear=app.ear,name=DownloadManager,service=EJB3,* **}
 -> <UNKNOWN>{Described:** UNRESOLVED Demands 'jboss.j2ee:ear=app.ear,name=ClientDeviceManager,service=EJB3,* **}
....
10:50:13,273 INFO [ServerImpl] [main] JBoss (Microcontainer) [5.0.0.Beta4 (build: SVNTag=
JBoss_5_0_0_Beta4 date=200802091115)] Started in 21m:42s:973ms

Regardless, it shouldn't take this long, should it?

[gcoleman]

I should add that there are dependency errors for about 40 different beans once the server finally starts up.

[gcoleman]

I can cut the startup time to about 5mins by changing org.jboss.ejb3.dependency.EjbLinkDemandMetaData with the following patch.

I stole some code from the ObjectName constructor. It's quick, dirty and not production quality but proves the point that relying on Exceptions for flow control is a bad idea.

Index: EjbLinkDemandMetaData.java

===================================================================

--- EjbLinkDemandMetaData.java (revision 71344)

+++ EjbLinkDemandMetaData.java (working copy)

@@ -45,7 +45,7 @@

 * specified.
 *
 * @author <a href="mailto:[e-mail]">Carlo de Wolf</a>
- * @version $Revision: $
+ * @version $Revision$
 */
 public class EjbLinkDemandMetaData extends JBossObject
 implements DemandMetaData, Serializable
@@ -129,9 +129,13 @@

 {
 for(ControllerContext context : controller.getContextsByState(ControllerState.INSTALLED))
 {
- try
- {
- ObjectName otherName = new ObjectName(context.getName().toString());
+
+ String otherNameStr = context.getName().toString();
+ if (isValidName(otherNameStr))
+ {
+ try
+ {
+ ObjectName otherName = new ObjectName(otherNameStr);

 if(demand.apply(otherName))
 {
@@ -144,12 +148,63 @@

 catch (MalformedObjectNameException e)
 {
 // ignore this context
+ System.out.println("MalformedObjectNameException constructing ObjectName for " + context.getName().toString());
 }
+ }
 }
 setResolved(false);
 return isResolved();
 }
-
+
+ private boolean isValidName(String name) {
+
+ // The name cannot be null
+ if (name == null)
+ return false;
+
+ if (name.startsWith("vfsfile:/"))
+ return false;
+
+ if (name.startsWith("java:comp/"))
+ return false;
+
+ // Test if the name is empty
+ if (name.length() == 0) {
+ return true;
+ }
+
+ // initialize parsing of the string
+ char[] name_chars = name.toCharArray();
+ int len = name_chars.length;
+ // length at most
+ int index = 0;
+
+ domain_parsing:
+ while (index < len) {
+ switch (name_chars[index]) {
+ case ':' :
+ break domain_parsing;
+ case '=' :
+ int i = ++index;
+ while ((i < len) && (name_chars[i++] != ':'))
+ if (i == len)
+ return false;
+ break;
+ case '\n' :
+ return false;
+ case '*' :
+ case '?' :
+
+ default :
+ index++;
+ }
+ }
+
+ // check for non-empty properties
+ return (index != len);
+ }
+
+
 @Override
 public void toString(JBossStringBuilder buffer)
 {