1 Reply Latest reply on Dec 27, 2011 4:48 AM by Dirk Dollar

    Slow JBoss AS 6 startup - what causes the network timeouts / how to fix it?

    Dirk Dollar Newbie

      I already spent some time on it and tried to figure out what ports to open or what to do with wireshark... with little success.

       

      I run on windows and would be glad if someone knows how to get more details.

       

       

      Log

       

      20:08:18,974 INFO  [AbstractJBossASServerBase] Server Configuration:

       

          JBOSS_HOME URL: file:/D:/lifeDevSuite/jboss/jboss-6.0.0.Final/

          Bootstrap: $JBOSS_HOME\server/default/conf/bootstrap.xml

          Common Base: $JBOSS_HOME\common/

          Common Library: $JBOSS_HOME\common/lib/

          Server Name: default

          Server Base: $JBOSS_HOME\server/

          Server Library: $JBOSS_HOME\server/default/lib/

          Server Config: $JBOSS_HOME\server/default/conf/

          Server Home: $JBOSS_HOME\server/default/

          Server Data: $JBOSS_HOME\server/default/data/

          Server Log: $JBOSS_HOME\server/default/log/

          Server Temp: $JBOSS_HOME\server/default/tmp/

       

      20:08:18,974 INFO  [AbstractServer] Starting: JBossAS [6.0.0.Final "Neo"]

      20:08:20,584 INFO  [ServerInfo] Java version: 1.6.0_17,Sun Microsystems Inc.

      20:08:20,584 INFO  [ServerInfo] Java Runtime: Java(TM) SE Runtime Environment (build 1.6.0_17-b04)

      20:08:20,584 INFO  [ServerInfo] Java VM: Java HotSpot(TM) Client VM 14.3-b01,Sun Microsystems Inc.

      20:08:20,584 INFO  [ServerInfo] OS-System: Windows 7 6.1,x86

      20:08:20,584 INFO  [ServerInfo] VM arguments: -Dprogram.name=JBossTools: Real JBoss 6.0 Runtime -Xms256m -Xmx768m -XX:MaxPermSize=256m -Dsun.rmi.dgc.client.gcInterval=360000 -Dsun.rmi.dgc.server.gcInterval=360000 -Djava.endorsed.dirs=D:\lifeDevSuite\jboss\jboss-6.0.0.Final\lib\endorsed -Djava.library.path=D:\lifeDevSuite\jboss\jboss-6.0.0.Final\bin\native -Dfile.encoding=UTF-8

      20:08:20,632 INFO  [JMXKernel] Legacy JMX core initialized

      20:08:26,866 INFO  [AbstractServerConfig] JBoss Web Services - Stack CXF Server 3.4.1.GA

      20:08:27,836 INFO  [JSFImplManagementDeployer] Initialized 3 JSF configurations: [Mojarra-1.2, MyFaces-2.0, Mojarra-2.0]

      20:08:32,617 WARNUNG [FileConfigurationParser] AIO wasn't located on this platform, it will fall back to using pure Java NIO. If your platform is Linux, install LibAIO to enable the AIO journal

      20:09:02,978 WARNUNG [FileConfigurationParser] AIO wasn't located on this platform, it will fall back to using pure Java NIO. If your platform is Linux, install LibAIO to enable the AIO journal

      20:09:04,151 INFO  [JMXConnector] starting JMXConnector on host 0.0.0.0:1090

      20:09:04,355 INFO  [MailService] Mail Service bound to java:/Mail

      20:09:05,386 INFO  [HornetQServerImpl] live server is starting..

      20:09:05,496 INFO  [JournalStorageManager] Using NIO Journal

      20:09:05,527 WARNUNG [HornetQServerImpl] Security risk! It has been detected that the cluster admin user and password have not been changed from the installation default. Please see the HornetQ user guide, cluster chapter, for instructions on how to do this.

      20:09:07,262 INFO  [NettyAcceptor] Started Netty Acceptor version 3.2.1.Final-r2319 0.0.0.0:5455 for CORE protocol

      20:09:07,262 INFO  [NettyAcceptor] Started Netty Acceptor version 3.2.1.Final-r2319 0.0.0.0:5445 for CORE protocol

      20:09:07,262 INFO  [HornetQServerImpl] HornetQ Server version 2.1.2.Final (Colmeia, 120) started

      20:09:07,325 INFO  [WebService] Using RMI server codebase: http://CHDW020:8083/

      20:09:07,591 INFO  [jbossatx] ARJUNA-32010 JBossTS Recovery Service (tag: JBOSSTS_4_14_0_Final) - JBoss Inc.

      20:09:07,591 INFO  [arjuna] ARJUNA-12324 Start RecoveryActivators

      20:09:07,622 INFO  [arjuna] ARJUNA-12296 ExpiredEntryMonitor running at Mi, 21 Dez 2011 20:09:07

      20:09:07,716 INFO  [arjuna] ARJUNA-12310 Recovery manager listening on endpoint 0.0.0.0:4712

      20:09:07,716 INFO  [arjuna] ARJUNA-12344 RecoveryManagerImple is ready on port 4712

      20:09:07,716 INFO  [jbossatx] ARJUNA-32013 Starting transaction recovery manager

      20:09:07,732 INFO  [arjuna] ARJUNA-12163 Starting service com.arjuna.ats.arjuna.recovery.ActionStatusService on port 4713

      20:09:07,732 INFO  [arjuna] ARJUNA-12337 TransactionStatusManagerItem host: 0.0.0.0 port: 4713

      20:09:07,747 INFO  [arjuna] ARJUNA-12170 TransactionStatusManager started on port 4713 and host 0.0.0.0 with service com.arjuna.ats.arjuna.recovery.ActionStatusService

      20:09:07,810 INFO  [jbossatx] ARJUNA-32017 JBossTS Transaction Service (JTA version - tag: JBOSSTS_4_14_0_Final) - JBoss Inc.

      20:09:07,872 INFO  [arjuna] ARJUNA-12202 registering bean jboss.jta:type=ObjectStore.

      20:09:08,153 INFO  [AprLifecycleListener] The Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: D:\lifeDevSuite\jboss\jboss-6.0.0.Final\bin\native

      20:09:08,294 INFO  [ModClusterService] Initializing mod_cluster 1.1.0.Final

      20:09:08,311 INFO  [TomcatDeployment] deploy, ctxPath=/invoker

      20:09:08,795 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/lifeDevSuite/jboss/jboss-6.0.0.Final/server/default/deploy/jboss-local-jdbc.rar/META-INF/ra.xml

      20:09:08,811 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/lifeDevSuite/jboss/jboss-6.0.0.Final/server/default/deploy/jboss-xa-jdbc.rar/META-INF/ra.xml

      20:09:08,826 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/lifeDevSuite/jboss/jboss-6.0.0.Final/server/default/deploy/jms-ra.rar/META-INF/ra.xml

      20:09:08,842 INFO  [HornetQResourceAdapter] HornetQ resource adaptor started

      20:09:08,842 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/lifeDevSuite/jboss/jboss-6.0.0.Final/server/default/deploy/mail-ra.rar/META-INF/ra.xml

      20:09:08,858 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/lifeDevSuite/jboss/jboss-6.0.0.Final/server/default/deploy/quartz-ra.rar/META-INF/ra.xml

      20:09:10,029 INFO  [SimpleThreadPool] Job execution threads will use class loader of thread: Thread-2

      20:09:10,077 INFO  [SchedulerSignalerImpl] Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl

      20:09:10,077 INFO  [QuartzScheduler] Quartz Scheduler v.1.8.3 created.

      20:09:10,077 INFO  [RAMJobStore] RAMJobStore initialized.

      20:09:10,093 INFO  [QuartzScheduler] Scheduler meta-data: Quartz Scheduler (v1.8.3) 'JBossQuartzScheduler' with instanceId 'NON_CLUSTERED'

        Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.

        NOT STARTED.

        Currently in standby mode.

        Number of jobs executed: 0

        Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads.

        Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

       

      20:09:10,093 INFO  [StdSchedulerFactory] Quartz scheduler 'JBossQuartzScheduler' initialized from an externally opened InputStream.

      20:09:10,093 INFO  [StdSchedulerFactory] Quartz scheduler version: 1.8.3

      20:09:10,093 INFO  [QuartzScheduler] Scheduler JBossQuartzScheduler_$_NON_CLUSTERED started.

      20:09:10,624 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=DefaultDS' to JNDI name 'java:DefaultDS'

      20:09:10,937 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=JmsXA' to JNDI name 'java:JmsXA'

      20:09:11,155 INFO  [xnio] XNIO Version 2.1.0.CR2

      20:09:11,172 INFO  [nio] XNIO NIO Implementation Version 2.1.0.CR2

      20:09:12,656 INFO  [remoting] JBoss Remoting version 3.1.0.Beta2

      20:10:20,298 INFO  [TomcatDeployment] deploy, ctxPath=/MyApp

      20:10:20,424 INFO  [[/Lisa]] Initializing Spring root WebApplicationContext

      20:10:20,424 INFO  [ContextLoader] Root WebApplicationContext: initialization started

      20:10:20,424 INFO  [XmlWebApplicationContext] Refreshing org.springframework.web.context.support.XmlWebApplicationContext@1fca9f9: display name [Root WebApplicationContext]; startup date [Wed Dec 21 20:10:20 CET 2011]; root of context hierarchy

      20:10:20,440 INFO  [XmlBeanDefinitionReader] Loading XML bean definitions from ServletContext resource [/WEB-INF/applicationContextDefault.xml]

      20:10:20,471 INFO  [XmlWebApplicationContext] Bean factory for application context [org.springframework.web.context.support.XmlWebApplicationContext@1fca9f9]: org.springframework.beans.factory.support.DefaultListableBeanFactory@1cc5b64

      .

      .

      .

      .

      20:10:26,631 INFO  [ContextLoader] Root WebApplicationContext: initialization completed in 6207 ms

      20:10:26,631 INFO  [config] Initializing Mojarra (1.2_15-20100816-SNAPSHOT) for context '/Lisa'

      20:10:26,631 WARNUNG [config] JSF1059: WARNING!  The com.sun.faces.verifyObjects feature is to aid developers not using tools.  It shouldn''t be enabled if using an IDE, or if this application is being deployed for production as it will impact application start times.

      20:10:27,943 INFO  [CacheManager] Selected [org.ajax4jsf.cache.LRUMapCacheFactory] cache factory

      20:10:27,943 INFO  [LRUMapCacheFactory] Creating LRUMap cache instance using parameters: {org.jboss.jbossfaces.JSF_CONFIG_NAME=Mojarra-1.2, facelets.DEVELOPMENT=true, javax.faces.CONFIG_FILES=/WEB-INF/faces-config.xml, /WEB-INF/faces-navigation-abfrage.xml, /WEB-INF/faces-navigation-bearbeitung.xml, /WEB-INF/faces-navigation-elo.xml,/WEB-INF/faces-navigation-generell.xml , /WEB-INF/faces-beans-dev.xml, version=${version}, com.sun.faces.duplicateJARPattern=^tmp\d+(\S*\.jar), facelets.FACELET_LIBRARIES=/WEB-INF/tags/lisa.taglib.xml;/WEB-INF/tags-internal/lisa-internal.taglib.xml, com.sun.faces.injectionProvider=org.jboss.web.jsf.integration.injection.JBossDelegatingInjectionProvider, debugMode=true, com.sun.faces.validateXml=true, org.richfaces.LoadScriptStrategy=NONE, org.richfaces.LoadStyleStrategy=NONE, facelets.REFRESH_PERIOD=2, facelets.SKIP_COMMENTS=true, com.sun.faces.verifyObjects=true, javax.faces.DISABLE_FACELET_JSF_VIEWHANDLER=true, org.apache.myfaces.CHECK_EXTENSIONS_FILTER=false, contextConfigLocation=/WEB-INF/applicationContext*.xml, javax.faces.STATE_SAVING_METHOD=client, javax.faces.DEFAULT_SUFFIX=.xhtml, resteasy.unwrapped.exceptions=javax.ejb.EJBException}

      20:10:27,944 INFO  [LRUMapCacheFactory] Creating LRUMap cache instance of default capacity

      20:10:27,960 INFO  [CacheManager] Selected [org.ajax4jsf.cache.LRUMapCacheFactory] cache factory

      20:10:27,960 INFO  [LRUMapCacheFactory] Creating LRUMap cache instance using parameters: {org.jboss.jbossfaces.JSF_CONFIG_NAME=Mojarra-1.2, facelets.DEVELOPMENT=true, javax.faces.CONFIG_FILES=/WEB-INF/faces-config.xml, /WEB-INF/faces-navigation-abfrage.xml, /WEB-INF/faces-navigation-bearbeitung.xml, /WEB-INF/faces-navigation-elo.xml,/WEB-INF/faces-navigation-generell.xml , /WEB-INF/faces-beans-dev.xml, version=${version}, com.sun.faces.duplicateJARPattern=^tmp\d+(\S*\.jar), facelets.FACELET_LIBRARIES=/WEB-INF/tags/lisa.taglib.xml;/WEB-INF/tags-internal/lisa-internal.taglib.xml, com.sun.faces.injectionProvider=org.jboss.web.jsf.integration.injection.JBossDelegatingInjectionProvider, debugMode=true, com.sun.faces.validateXml=true, org.richfaces.LoadScriptStrategy=NONE, org.richfaces.LoadStyleStrategy=NONE, facelets.REFRESH_PERIOD=2, facelets.SKIP_COMMENTS=true, com.sun.faces.verifyObjects=true, javax.faces.DISABLE_FACELET_JSF_VIEWHANDLER=true, org.apache.myfaces.CHECK_EXTENSIONS_FILTER=false, contextConfigLocation=/WEB-INF/applicationContext*.xml, javax.faces.STATE_SAVING_METHOD=client, javax.faces.DEFAULT_SUFFIX=.xhtml, resteasy.unwrapped.exceptions=javax.ejb.EJBException}

      20:10:27,960 INFO  [LRUMapCacheFactory] Creating LRUMap cache instance of default capacity

      20:10:28,007 INFO  [TomcatDeployment] deploy, ctxPath=/

      20:10:28,053 INFO  [service] Removing bootstrap log handlers

      20:10:28,163 INFO  [org.apache.coyote.http11.Http11Protocol] Starting Coyote HTTP/1.1 on http-0.0.0.0-8080

      20:10:28,163 INFO  [org.apache.coyote.ajp.AjpProtocol] Starting Coyote AJP/1.3 on ajp-0.0.0.0-8009

      20:10:28,163 INFO  [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.Final "Neo"] Started in 2m:9s:189ms

       

       

       

       

      My vm settings
      "-Dprogram.name=JBossTools: Real JBoss 6.0 Runtime " -Xms256m -Xmx768m -XX:MaxPermSize=256m -Dsun.rmi.dgc.client.gcInterval=360000 -Dsun.rmi.dgc.server.gcInterval=360000 -Djava.endorsed.dirs="D:\lifeDevSuite\jboss\jboss-6.0.0.Final\lib\endorsed"

       

       

      My Program Arguments
      --configuration=default  -b 0.0.0.0
        • 1. Re: Slow JBoss AS 6 startup - what causes the network timeouts / how to fix it?
          Dirk Dollar Newbie

          I figured out that the slow deployment is caused by a known jboss issue : http://community.jboss.org/thread/160718?start=0&tstart=0 basically jboss unpacks all jar files in the web-inf/lib folder. The suggested workaround was to move all libs to /default/lib but I get a classnotfoundexception.     I use JSF 1.2 and that's why i gotta deal with the facelets jar jsf-facelets-1.1.15.B1.jar  Moving all jars to default/lib results in a   Caused by: java.lang.ClassNotFoundException: javax.faces.render.RenderKitFactory    it doesn't matter where I have my facelets jar (web-inf/lib or default/lib). It always ends in this error.  someone has an idea / different workaround? everything else of the application works as expected.   EDIT a working solution would be to deploy to an ear and have all libraries in mywebapp.ear/lib but things do not get deployed that way out of the box.