5 Replies Latest reply on Sep 29, 2010 5:25 AM by nimo stephan

    jboss 6 m5 slow start

    nimo stephan Master

      I updatet from m4 to m5.

       

      Besides this problem http://community.jboss.org/thread/157055 (which is not solved yet), I have another problem: the server start is sooo slow!

       

      09:30:39,762 INFO  [TomcatDeployment] deploy, ctxPath=/
      09:30:40,419 INFO  [service] Removing bootstrap log handlers
      09:30:41,450 WARNUNG [ServiceLoader] Could not load service class org.jboss.weld.extensions.resourceLoader.servlet.ServletResourceExtension
      09:30:41,466 WARNUNG [ServiceLoader] Could not load service class org.jboss.weld.extensions.bean.lookup.IdentifiableBeanExtension
      09:30:43,762 INFO  [org.jboss.web.tomcat.service.deployers.TomcatDeployment] deploy, ctxPath=/myWAR
      09:30:43,872 WARN  [org.jboss.web.tomcat.service.injection.WebResourceHandler] Ignoring invalid TimerService resource-env-ref
      09:30:43,903 WARN  [org.jboss.web.tomcat.service.injection.WebResourceHandler] Ignoring invalid TimerService resource-env-ref
      09:30:44,450 INFO  [javax.enterprise.resource.webcontainer.jsf.config] Mojarra 2.0.2 (FCS b10) für Kontext '/myWAR' wird initialisiert.
      09:31:07,449 INFO  [javax.enterprise.resource.webcontainer.jsf.config] Monitoring jndi:/localhost/myWAR/WEB-INF/faces-config.xml for modifications
      09:31:07,590 INFO  [org.jboss.resteasy.cdi.CdiInjectorFactory] Found BeanManager in ServletContext
      09:31:07,621 INFO  [org.jboss.ejb3.session.SessionSpecContainer] Starting jboss.j2ee:jar=MyWAR.war,name=MyEJB,service=EJB3
      09:31:07,621 INFO  [org.jboss.ejb3.EJBContainer] STARTED EJB: com.
      MyEJB ejbName: MyEJB
      09:31:07,949 INFO  [org.apache.coyote.http11.Http11Protocol] Starting Coyote HTTP/1.1 on http-localhost%2F127.0.0.1-8080
      09:31:08,012 INFO  [org.apache.coyote.ajp.AjpProtocol] Starting Coyote AJP/1.3 on ajp-localhost%2F127.0.0.1-8009
      09:31:08,012 INFO  [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.20100911-M5 "Neo"] Started in 5m:27s:151ms

       

      I have put only one war-file into my deploy-directory. The war-file is nothing special..only a minimal weld-jsf-war-application. And I have to wait soooo long. Why is that so?

       

      I have thought the server startup is now faster as said here http://community.jboss.org/wiki/LazyEJB31timerservicedeploymentstartingJBossAS600M5:

       

      {quote}By default, JBoss AS doesn't ship any EJB3.x deployments and hence  the lazy deployment of timerservice jar saves a few seconds of the  server boot time.{quote}

       

      But this is not true. With jboss 6 m4 server startup was about 1-2 minute.(Jboss 4 server startup was only approx. 30 seconds). With jboss 6 m5, I have to wait more than 5 minutes.

       

      I tried it with glassfish and it only needs approx. 30-40 seconds.

       

      I understand that new (hidden) services are included which makes the server (startup) slower. But 5 minutes to wait is too long. Will it be better in final versions?

        • 1. Re: jboss 6 m5 slow start
          jaikiran pai Master

          nimo stephan wrote:

           

          I have thought the server startup is now faster as said here http://community.jboss.org/wiki/LazyEJB31timerservicedeploymentstartingJBossAS600M5:

           

          By default, JBoss AS doesn't ship any EJB3.x deployments and hence  the lazy deployment of timerservice jar saves a few seconds of the  server boot time.

           

          But this is not true. With jboss 6 m4 server startup was about 1-2 minute.(Jboss 4 server startup was only approx. 30 seconds). With jboss 6 m5, I have to wait more than 5 minutes.

          That wiki is about the boot time of a clean JBoss AS without any applications deployed. It is certainly faster compared to a clean JBoss AS 6.0.0.M4 without any applications.

           

           

          nimo stephan wrote:

           

          I understand that new (hidden) services are included which makes the server (startup) slower.

           

          Actually, it shouldn't.

           

          nimo stephan wrote:


           

          09:30:39,762 INFO  [TomcatDeployment] deploy, ctxPath=/
          09:30:40,419 INFO  [service] Removing bootstrap log handlers
          09:30:41,450 WARNUNG [ServiceLoader] Could not load service class org.jboss.weld.extensions.resourceLoader.servlet.ServletResourceExtension
          09:30:41,466 WARNUNG [ServiceLoader] Could not load service class org.jboss.weld.extensions.bean.lookup.IdentifiableBeanExtension
          09:30:43,762 INFO  [org.jboss.web.tomcat.service.deployers.TomcatDeployment] deploy, ctxPath=/myWAR
          09:30:43,872 WARN  [org.jboss.web.tomcat.service.injection.WebResourceHandler] Ignoring invalid TimerService resource-env-ref
          09:30:43,903 WARN  [org.jboss.web.tomcat.service.injection.WebResourceHandler] Ignoring invalid TimerService resource-env-ref
          09:30:44,450 INFO  [javax.enterprise.resource.webcontainer.jsf.config] Mojarra 2.0.2 (FCS b10) für Kontext '/myWAR' wird initialisiert.
          09:31:07,449 INFO  [javax.enterprise.resource.webcontainer.jsf.config] Monitoring jndi:/localhost/myWAR/WEB-INF/faces-config.xml for modifications
          09:31:07,590 INFO  [org.jboss.resteasy.cdi.CdiInjectorFactory] Found BeanManager in ServletContext
          09:31:07,621 INFO  [org.jboss.ejb3.session.SessionSpecContainer] Starting jboss.j2ee:jar=MyWAR.war,name=MyEJB,service=EJB3
          09:31:07,621 INFO  [org.jboss.ejb3.EJBContainer] STARTED EJB: com.
          MyEJB ejbName: MyEJB
          09:31:07,949 INFO  [org.apache.coyote.http11.Http11Protocol] Starting Coyote HTTP/1.1 on http-localhost%2F127.0.0.1-8080
          09:31:08,012 INFO  [org.apache.coyote.ajp.AjpProtocol] Starting Coyote AJP/1.3 on ajp-localhost%2F127.0.0.1-8009
          09:31:08,012 INFO  [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.20100911-M5 "Neo"] Started in 5m:27s:151ms

           

          I have put only one war-file into my deploy-directory. The war-file is nothing special..only a minimal weld-jsf-war-application. And I have to wait soooo long. Why is that so?

           

          Without the .war file, how long does it take to boot the server? Can you post the output of:

           

          jar -tf myWar.war

          • 2. Re: jboss 6 m5 slow start
            jaikiran pai Master

            By the way, how long did it take to deploy this application in JBoss AS 6.0.0.M4?

            • 3. Re: jboss 6 m5 slow start
              nimo stephan Master

              yes, indeed. The server startup without my weld-application needs only about one minute:

               

              ..

              10:34:31,507 INFO  [StdSchedulerFactory] Quartz scheduler 'JBossQuartzScheduler' initialized from an externally opened InputStream.

              10:34:31,507 INFO  [StdSchedulerFactory] Quartz scheduler version: 1.8.0
              10:34:31,507 INFO  [QuartzScheduler] Scheduler JBossQuartzScheduler_$_NON_CLUSTERED started.
              10:34:32,101 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=MES_DS' to JNDI name 'java:MES_DS'
              10:34:32,991 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=DefaultDS' to JNDI name 'java:DefaultDS'
              10:34:33,523 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=JmsXA' to JNDI name 'java:JmsXA'
              10:34:33,616 INFO  [xnio] XNIO Version 2.1.0.CR2
              10:34:33,632 INFO  [nio] XNIO NIO Implementation Version 2.1.0.CR2
              10:34:34,460 INFO  [remoting] JBoss Remoting version 3.1.0.Beta2
              10:34:34,679 INFO  [TomcatDeployment] deploy, ctxPath=/
              10:34:34,866 INFO  [service] Removing bootstrap log handlers
              10:34:34,976 INFO  [org.apache.coyote.http11.Http11Protocol] Starting Coyote HTTP/1.1 on http-localhost%2F127.0.0.1-8080
              10:34:35,007 INFO  [org.apache.coyote.ajp.AjpProtocol] Starting Coyote AJP/1.3 on ajp-localhost%2F127.0.0.1-8009
              10:34:35,007 INFO  [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.20100911-M5 "Neo"] Started in 1m:19s:795ms

               

              I guess, the new version of weld is responsible for that. I tried the same with jboss as 5 m4 (Included WELD version before 1.1.0.Beta1!). First, I get not this error described in http://community.jboss.org/thread/157055. And second, the boot time is only about a minute.

               

              MyWAR is nothing special. I created the sceleton via Mavens weld-archetype:

               

              META-INF/
              META-INF/MANIFEST.MF
              META-INF/resources/
              META-INF/resources/comp/
              resources/
              resources/comp/
              resources/css/
              resources/gfx/
              throughput/
              WEB-INF/
              WEB-INF/classes/
              WEB-INF/classes/com/
              WEB-INF/classes/META-INF/
              WEB-INF/lib/
              WEB-INF/templates/
              index.jsp
              testUser.xhtml
              WEB-INF/classes/com/MyEJB.class
              WEB-INF/classes/com/User.class
              WEB-INF/classes/import.sql
              WEB-INF/classes/MyWAR-ds.xml
              WEB-INF/classes/META-INF/beans.xml
              WEB-INF/classes/META-INF/persistence.xml
              WEB-INF/ejb-jar.xml
              WEB-INF/env-entries.properties
              WEB-INF/faces-config.xml
              WEB-INF/lib/colt-1.2.0.jar
              WEB-INF/lib/commons-math-2.1.jar
              WEB-INF/lib/concurrent-1.3.4.jar
              WEB-INF/lib/el-impl-2.1.2-b04.jar
              WEB-INF/lib/jackson-core-asl-1.6.0.jar
              WEB-INF/lib/jackson-mapper-asl-1.6.0.jar
              WEB-INF/lib/joda-time-1.6.1.jar
              WEB-INF/lib/weld-extensions-1.0.0.Alpha2.jar
              WEB-INF/templates/default.xhtml
              WEB-INF/web.xml
              META-INF/maven/
              META-INF/maven/com/MyWAR/
              META-INF/maven/com/MyWAR/MES/
              META-INF/maven/com/MyWAR/MES/pom.xml
              META-INF/maven/com/MyWAR/pom.properties

               

               

              Maybe weld-extensions-1.0.0.Alpha2.jar is not combatible with 1.1.0.Beta1? I have no clue.

              • 4. Re: jboss 6 m5 slow start
                jaikiran pai Master

                Looking at your previous logs, I don't see where those 5 minutes are being spent. As for the application contents, I see that you have import.sql in the application. Are you sure the data import into the tables isn't causing the slowness? Do any of the logs or thread dumps suggest where the time is being spent?

                • 5. Re: jboss 6 m5 slow start
                  nimo stephan Master

                  I have 3 import-statements in import.sql..User-Records for the table  USERS. However, the exactly same war does not not need 5 minutes in  jboss 6m4. I guess, java.exe hanged a little bit and I had a  memory-problem. I closed all related things (eclipse, jboss) and make a  cold start.

                   

                  Now, I "only" have to wait about 2 minutes. The most time is lost here:

                   

                  11:12:52,252 INFO  [SingletonContainerDeployer] with supplies:
                  11:13:38,361 INFO  [Version] WELD-000900 1.1.0 (Beta1)
                  11:13:22,361 INFO  [PersistenceUnitDeployment] Starting persistence unit persistence.unit:unitName=myWAR.war#myWAR_PU
                  11:13:22,392 INFO  [Ejb3Configuration] Processing PersistenceUnitInfo [
                       name: myWAR_PU
                       ...]

                  ...

                  11:13:44,298 INFO  [SchemaExport] Executing import script: /import.sql
                  11:13:48,658 INFO  [SchemaExport] schema export complete

                  ...

                  11:13:52,768 INFO  [org.jboss.web.tomcat.service.deployers.TomcatDeployment] deploy, ctxPath=/myWAR

                  11:13:52,862 WARN  [org.jboss.web.tomcat.service.injection.WebResourceHandler] Ignoring invalid TimerService resource-env-ref
                  11:13:52,862 WARN  [org.jboss.web.tomcat.service.injection.WebResourceHandler] Ignoring invalid TimerService resource-env-ref
                  11:13:53,096 INFO  [javax.enterprise.resource.webcontainer.jsf.config] Mojarra 2.0.2 (FCS b10) für Kontext '/myWAR' wird initialisiert.
                  11:14:08,739 INFO  [javax.enterprise.resource.webcontainer.jsf.config] Monitoring  jndi:/localhost/myWAR/WEB-INF/faces-config.xml for modifications
                  11:14:06,801 INFO  [org.jboss.resteasy.cdi.CdiInjectorFactory] Found BeanManager in ServletContext
                  11:14:06,832 INFO  [org.jboss.ejb3.session.SessionSpecContainer] Starting jboss.j2ee:jar=myWAR.war,name=MyEJB,service=EJB3
                  11:14:06,832 INFO  [org.jboss.ejb3.EJBContainer] STARTED EJB: com.MyEJB ejbName: MyEJB
                  11:14:06,895 INFO  [org.apache.coyote.http11.Http11Protocol] Starting Coyote HTTP/1.1 on http-localhost%2F127.0.0.1-8080
                  11:14:06,910 INFO  [org.apache.coyote.ajp.AjpProtocol] Starting Coyote AJP/1.3 on ajp-localhost%2F127.0.0.1-8009
                  11:14:06,910 INFO  [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.20100911-M5 "Neo"] Started in 2m:17s:845ms

                   

                  So you see, 11:13:38,361 INFO  [Version] WELD-000900 1.1.0 (Beta1) needs approx 45 seconds.

                   

                   

                  {quote}And second, the boot time is only about a minute.{quote}

                   

                  approx. 2 minutes - approx. 45 seconds = approx. 1 minute.