5 Replies Latest reply on Feb 21, 2011 10:15 AM by robert.geisler

    run JBoss 6.0.0 M3 with -Xdebug

    robert.geisler Newbie

      hello...

       

      we use to run our application (let's call it) 'APP' (~900 Stateless Session Beans, ~600 Entities) with JBoss 4.2.2.GA.

      these days i'm validating JBoss 6.0.0 M3. i also tried JBoss 5.x some months ago, but performance (especially boot time including deployment) was very bad. with JBoss 6.0.0 M3 boot time of JBoss improved in comparison to JBoss 5.x, but still is "slow" when compared with JBoss 4.x.

       

      to prove my assumption i compared the time JBoss needs to start (with and without APP deployed). in addition i (de)activated remote socket debugging (in run.conf.bat). you may find the measurements in the following table. btw, i did not measure the duration, its the time that JBoss tells me through the server.log (INFO [...] JBossAS [version] Started in [mm:ss:SSS]:

       

      JBossAPP
      -Xdebugboot time (s)
      boot time (m)
      4.2.2.GA--90,15
      4.2.2.GAxx671,12
      5.1.0.GA--290,48
      5.1.0.GAx-2734,55
      5.1.0.GAxx5338,88
      6.0.0.M3--150,25
      6.0.0.M3x-1322,20
      6.0.0.M3xx4898,15

       

      i notice that JBoss 6.x improved over JBoss 5.x. well done.

       

      but i recognize, too, that running JBoss 6.0.0.M3 in debug mode is just impractical!!

      we use debug mode for development reasons, of course. so (re)deployment MUST NOT take ~10 minutes.

      the question is: why does debug mode slows down JBoss boot time this much??

       

      feel free to have a look at boot.log attached.

      it seems to me, that JBoss enjoys some nap in debug mode :- /

       

      11:59:54,038 INFO  [AbstractJBossASServerBase] Server Configuration:

       

          JBOSS_HOME URL: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/
          Bootstrap: $JBOSS_HOME\server/APP/conf/bootstrap.xml
          Common Base: $JBOSS_HOME\common/
          Common Library: $JBOSS_HOME\common/lib/
          Server Name: APP
          Server Base: $JBOSS_HOME\server/
          Server Library: $JBOSS_HOME\server/APP/lib/
          Server Config: $JBOSS_HOME\server/APP/conf/
          Server Home: $JBOSS_HOME\server/APP/
          Server Data: $JBOSS_HOME\server/APP/data/
          Server Log: $JBOSS_HOME\server/APP/log/
          Server Temp: $JBOSS_HOME\server/APP/tmp/

       

      11:59:54,044 INFO  [AbstractServer] Starting: JBossAS [6.0.0.20100429-M3 "Neo"]
      11:59:55,552 INFO  [ServerInfo] Java version: 1.6.0_20,Sun Microsystems Inc.
      11:59:55,553 INFO  [ServerInfo] Java Runtime: Java(TM) SE Runtime Environment (build 1.6.0_20-b02)
      11:59:55,554 INFO  [ServerInfo] Java VM: Java HotSpot(TM) 64-Bit Server VM 16.3-b01,Sun Microsystems Inc.
      11:59:55,554 INFO  [ServerInfo] OS-System: Windows Vista 6.0,amd64
      11:59:55,555 INFO  [ServerInfo] VM arguments: -Dprogram.name=run.bat -Xms512M -Xmx1536M -XX:MaxPermSize=512M -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Dorg.jboss.resolver.warning=true -Djava.net.preferIPv4Stack=true -Xdebug -Xrunjdwp:transport=dt_socket,address=7099,server=y,suspend=n -Djava.endorsed.dirs=D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\lib\endorsed
      11:59:55,557 DEBUG [ServerInfo] Full System Properties Dump
      11:59:55,558 DEBUG [ServerInfo]     awt.toolkit: sun.awt.windows.WToolkit
      11:59:55,558 DEBUG [ServerInfo]     bind.address: 192.168.1.123
      11:59:55,560 DEBUG [ServerInfo]     file.encoding: Cp1252
      11:59:55,561 DEBUG [ServerInfo]     file.encoding.pkg: sun.io
      11:59:55,561 DEBUG [ServerInfo]     file.separator: \
      11:59:55,561 DEBUG [ServerInfo]     java.awt.graphicsenv: sun.awt.Win32GraphicsEnvironment
      11:59:55,561 DEBUG [ServerInfo]     java.awt.printerjob: sun.awt.windows.WPrinterJob
      11:59:55,561 DEBUG [ServerInfo]     java.class.path: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\bin\run.jar
      11:59:55,561 DEBUG [ServerInfo]     java.class.version: 50.0
      11:59:55,561 DEBUG [ServerInfo]     java.endorsed.dirs: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\lib\endorsed
      11:59:55,562 DEBUG [ServerInfo]     java.ext.dirs: C:\Java\64bit\jre6\lib\ext;C:\Windows\Sun\Java\lib\ext
      11:59:55,562 DEBUG [ServerInfo]     java.home: C:\Java\64bit\jre6
      11:59:55,562 DEBUG [ServerInfo]     java.io.tmpdir: C:\Users\USERNAME\AppData\Local\Temp\
      11:59:55,562 DEBUG [ServerInfo]     java.library.path: C:\Java\64bit\jre6\bin;.;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Program Files (x86)\Microsoft SQL Server\80\Tools\Binn\;C:\Program Files\Microsoft SQL Server\90\Tools\binn\;C:\Program Files (x86)\Microsoft SQL Server\90\Tools\binn\;C:\Program Files (x86)\Microsoft SQL Server\90\DTS\Binn\;C:\Program Files (x86)\Microsoft SQL Server\90\Tools\Binn\VSShell\Common7\IDE\;C:\Program Files\Microsoft SQL Server\90\DTS\Binn\;C:\Program Files (x86)\Lotus\Notes\jvm\bin;C:\Program Files (x86)\Lotus\Notes;C:\Program Files (x86)\Microsoft SQL Server\100\Tools\Binn\;C:\Program Files\Microsoft SQL Server\100\Tools\Binn\;C:\Program Files\Microsoft SQL Server\100\DTS\Binn\;C:\Program Files (x86)\Microsoft SQL Server\100\Tools\Binn\VSShell\Common7\IDE\;C:\Program Files (x86)\Microsoft SQL Server\100\DTS\Binn\;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Java\64bit\jdk1.6.0_20\bin
      11:59:55,562 DEBUG [ServerInfo]     java.net.preferIPv4Stack: true
      11:59:55,563 DEBUG [ServerInfo]     java.protocol.handler.pkgs: org.jboss.net.protocol|org.jboss.vfs.protocol
      11:59:55,563 DEBUG [ServerInfo]     java.rmi.server.RMIClassLoaderSpi: org.jboss.system.JBossRMIClassLoader
      11:59:55,563 DEBUG [ServerInfo]     java.rmi.server.hostname: 192.168.1.123
      11:59:55,563 DEBUG [ServerInfo]     java.runtime.name: Java(TM) SE Runtime Environment
      11:59:55,563 DEBUG [ServerInfo]     java.runtime.version: 1.6.0_20-b02
      11:59:55,563 DEBUG [ServerInfo]     java.specification.name: Java Platform API Specification
      11:59:55,563 DEBUG [ServerInfo]     java.specification.vendor: Sun Microsystems Inc.
      11:59:55,564 DEBUG [ServerInfo]     java.specification.version: 1.6
      11:59:55,564 DEBUG [ServerInfo]     java.util.logging.manager: org.jboss.logmanager.LogManager
      11:59:55,564 DEBUG [ServerInfo]     java.vendor: Sun Microsystems Inc.
      11:59:55,564 DEBUG [ServerInfo]     java.vendor.url: http://java.sun.com/
      11:59:55,564 DEBUG [ServerInfo]     java.vendor.url.bug: http://java.sun.com/cgi-bin/bugreport.cgi
      11:59:55,564 DEBUG [ServerInfo]     java.version: 1.6.0_20
      11:59:55,564 DEBUG [ServerInfo]     java.vm.info: mixed mode
      11:59:55,565 DEBUG [ServerInfo]     java.vm.name: Java HotSpot(TM) 64-Bit Server VM
      11:59:55,565 DEBUG [ServerInfo]     java.vm.specification.name: Java Virtual Machine Specification
      11:59:55,565 DEBUG [ServerInfo]     java.vm.specification.vendor: Sun Microsystems Inc.
      11:59:55,565 DEBUG [ServerInfo]     java.vm.specification.version: 1.0
      11:59:55,565 DEBUG [ServerInfo]     java.vm.vendor: Sun Microsystems Inc.
      11:59:55,565 DEBUG [ServerInfo]     java.vm.version: 16.3-b01
      11:59:55,565 DEBUG [ServerInfo]     javax.management.builder.initial: org.jboss.mx.server.MBeanServerBuilderImpl
      11:59:55,566 DEBUG [ServerInfo]     jboss.bind.address: 192.168.1.123
      11:59:55,566 DEBUG [ServerInfo]     jboss.boot.server.log.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\server\APP\log
      11:59:55,566 DEBUG [ServerInfo]     jboss.bootstrap.home.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/conf/
      11:59:55,566 DEBUG [ServerInfo]     jboss.bootstrap.name: bootstrap.xml
      11:59:55,566 DEBUG [ServerInfo]     jboss.bootstrap.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/conf/bootstrap.xml
      11:59:55,566 DEBUG [ServerInfo]     jboss.common.base.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/common/
      11:59:55,566 DEBUG [ServerInfo]     jboss.common.lib.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/common/lib/
      11:59:55,567 DEBUG [ServerInfo]     jboss.home: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3
      11:59:55,567 DEBUG [ServerInfo]     jboss.home.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3
      11:59:55,567 DEBUG [ServerInfo]     jboss.home.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/
      11:59:55,567 DEBUG [ServerInfo]     jboss.host.name: USERNAME-pc-XYZ
      11:59:55,567 DEBUG [ServerInfo]     jboss.lib.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/lib/
      11:59:55,567 DEBUG [ServerInfo]     jboss.native.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\server\APP\tmp\native
      11:59:55,568 DEBUG [ServerInfo]     jboss.native.load: false
      11:59:55,568 DEBUG [ServerInfo]     jboss.node.name: USERNAME-pc-XYZ
      11:59:55,568 DEBUG [ServerInfo]     jboss.partition.name: DefaultPartition
      11:59:55,568 DEBUG [ServerInfo]     jboss.platform.mbeanserver: true
      11:59:55,568 DEBUG [ServerInfo]     jboss.qualified.host.name: USERNAME-pc-XYZ
      11:59:55,568 DEBUG [ServerInfo]     jboss.server.base.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\server
      11:59:55,568 DEBUG [ServerInfo]     jboss.server.base.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/
      11:59:55,569 DEBUG [ServerInfo]     jboss.server.config.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/conf/
      11:59:55,569 DEBUG [ServerInfo]     jboss.server.data.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\server\APP\data
      11:59:55,569 DEBUG [ServerInfo]     jboss.server.home.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\server\APP
      11:59:55,569 DEBUG [ServerInfo]     jboss.server.home.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/
      11:59:55,569 DEBUG [ServerInfo]     jboss.server.lib.url: file:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/lib/
      11:59:55,569 DEBUG [ServerInfo]     jboss.server.log.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\server\APP\log
      11:59:55,569 DEBUG [ServerInfo]     jboss.server.name: APP
      11:59:55,570 DEBUG [ServerInfo]     jboss.server.temp.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\server\APP\tmp
      11:59:55,570 DEBUG [ServerInfo]     jboss.vfs.forceCopy: true
      11:59:55,570 DEBUG [ServerInfo]     jbossmx.loader.repository.class: org.jboss.mx.loading.UnifiedLoaderRepository3
      11:59:55,570 DEBUG [ServerInfo]     jgroups.bind_addr: 192.168.1.123
      11:59:55,570 DEBUG [ServerInfo]     line.separator:

       

      11:59:55,570 DEBUG [ServerInfo]     log4j.defaultInitOverride: true
      11:59:55,570 DEBUG [ServerInfo]     org.jboss.logging.Logger.pluginClass: org.jboss.logging.logmanager.LoggerPluginImpl
      11:59:55,571 DEBUG [ServerInfo]     org.jboss.resolver.warning: true
      11:59:55,571 DEBUG [ServerInfo]     os.arch: amd64
      11:59:55,571 DEBUG [ServerInfo]     os.name: Windows Vista
      11:59:55,571 DEBUG [ServerInfo]     os.version: 6.0
      11:59:55,571 DEBUG [ServerInfo]     path.separator: ;
      11:59:55,571 DEBUG [ServerInfo]     program.name: run.bat
      11:59:55,571 DEBUG [ServerInfo]     sun.arch.data.model: 64
      11:59:55,571 DEBUG [ServerInfo]     sun.boot.class.path: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\lib\endorsed\activation.jar;D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\lib\endorsed\jaxb-api.jar;D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\lib\endorsed\jaxws-api.jar;D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\lib\endorsed\jbossws-native-factories.jar;D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3\lib\endorsed\stax-api.jar;C:\Java\64bit\jre6\lib\resources.jar;C:\Java\64bit\jre6\lib\rt.jar;C:\Java\64bit\jre6\lib\sunrsasign.jar;C:\Java\64bit\jre6\lib\jsse.jar;C:\Java\64bit\jre6\lib\jce.jar;C:\Java\64bit\jre6\lib\charsets.jar;C:\Java\64bit\jre6\classes
      11:59:55,572 DEBUG [ServerInfo]     sun.boot.library.path: C:\Java\64bit\jre6\bin
      11:59:55,572 DEBUG [ServerInfo]     sun.cpu.endian: little
      11:59:55,572 DEBUG [ServerInfo]     sun.cpu.isalist: amd64
      11:59:55,572 DEBUG [ServerInfo]     sun.desktop: windows
      11:59:55,572 DEBUG [ServerInfo]     sun.io.unicode.encoding: UnicodeLittle
      11:59:55,573 DEBUG [ServerInfo]     sun.java.launcher: SUN_STANDARD
      11:59:55,573 DEBUG [ServerInfo]     sun.jnu.encoding: Cp1252
      11:59:55,573 DEBUG [ServerInfo]     sun.management.compiler: HotSpot 64-Bit Server Compiler
      11:59:55,573 DEBUG [ServerInfo]     sun.os.patch.level: Service Pack 2
      11:59:55,573 DEBUG [ServerInfo]     sun.rmi.dgc.client.gcInterval: 3600000
      11:59:55,573 DEBUG [ServerInfo]     sun.rmi.dgc.server.gcInterval: 3600000
      11:59:55,573 DEBUG [ServerInfo]     user.country: DE
      11:59:55,574 DEBUG [ServerInfo]     user.dir: D:\USERNAME\JBoss\jboss-6.0.0.20100429-M3
      11:59:55,574 DEBUG [ServerInfo]     user.home: C:\Users\USERNAME
      11:59:55,574 DEBUG [ServerInfo]     user.language: de
      11:59:55,574 DEBUG [ServerInfo]     user.name: USERNAME
      11:59:55,574 DEBUG [ServerInfo]     user.timezone: Europe/Berlin
      11:59:55,574 DEBUG [ServerInfo]     user.variant:
      11:59:55,574 DEBUG [ServerInfo]     xb.builder.repeatableParticleHandlers: false
      11:59:55,575 DEBUG [ServerInfo]     xb.builder.useUnorderedSequence: true
      11:59:55,597 INFO  [JMXKernel] Legacy JMX core initialized
      12:00:00,359 INFO  [AbstractServerConfig] JBoss Web Services - Native Server 3.3.0.CR1.SP2
      12:00:07,657 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

       

      ***** [n-times 'Encountered deployment' like] *****
      12:00:21,155 INFO  [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@80183631{vfs:///D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/deploy/APP.ear/TheFirstEJB3Module.jar/}
      12:00:21,288 INFO  [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@1319106496{vfs:///D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/deploy/APP.ear/TheLastEJB3Module.jar/}
      ***** [/'Encountered deployment'] *****

       

      12:00:22,753 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
      12:00:22,938 INFO  [JMXConnector] starting JMXConnector on host 192.168.1.123:1090
      12:00:23,797 INFO  [MailService] Mail Service bound to java:/Mail
      12:00:24,610 INFO  [HornetQServerImpl] live server is starting..
      12:00:24,687 INFO  [JournalStorageManager] Using NIO Journal
      12:00:24,708 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.
      12:00:26,097 INFO  [NettyAcceptor] Started Netty Acceptor version 3.2.0.BETA1-r2215 192.168.1.123:5455
      12:00:26,098 INFO  [NettyAcceptor] Started Netty Acceptor version 3.2.0.BETA1-r2215 192.168.1.123:5445
      12:00:26,102 INFO  [HornetQServerImpl] HornetQ Server version 2.1.0.BETA3 (Hungry Hornet, 117) started
      12:00:26,180 INFO  [WebService] Using RMI server codebase: http://192.168.1.123:8083/
      12:00:26,934 INFO  [AprLifecycleListener] The Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: C:\Java\64bit\jre6\bin;.;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Program Files (x86)\Microsoft SQL Server\80\Tools\Binn\;C:\Program Files\Microsoft SQL Server\90\Tools\binn\;C:\Program Files (x86)\Microsoft SQL Server\90\Tools\binn\;C:\Program Files (x86)\Microsoft SQL Server\90\DTS\Binn\;C:\Program Files (x86)\Microsoft SQL Server\90\Tools\Binn\VSShell\Common7\IDE\;C:\Program Files\Microsoft SQL Server\90\DTS\Binn\;C:\Program Files (x86)\Lotus\Notes\jvm\bin;C:\Program Files (x86)\Lotus\Notes;C:\Program Files (x86)\Microsoft SQL Server\100\Tools\Binn\;C:\Program Files\Microsoft SQL Server\100\Tools\Binn\;C:\Program Files\Microsoft SQL Server\100\DTS\Binn\;C:\Program Files (x86)\Microsoft SQL Server\100\Tools\Binn\VSShell\Common7\IDE\;C:\Program Files (x86)\Microsoft SQL Server\100\DTS\Binn\;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Java\64bit\jdk1.6.0_20\bin
      12:00:27,080 INFO  [TomcatDeployment] deploy, ctxPath=/invoker
      12:00:27,766 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/deploy/jboss-local-jdbc.rar/META-INF/ra.xml
      12:00:27,777 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/deploy/jboss-xa-jdbc.rar/META-INF/ra.xml
      12:00:27,784 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/deploy/jms-ra.rar/META-INF/ra.xml
      12:00:27,800 INFO  [HornetQResourceAdapter] HornetQ resource adaptor started
      12:00:27,806 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/deploy/mail-ra.rar/META-INF/ra.xml
      12:00:27,816 INFO  [RARDeployment] Required license terms exist, view vfs:/D:/USERNAME/JBoss/jboss-6.0.0.20100429-M3/server/APP/deploy/quartz-ra.rar/META-INF/ra.xml
      12:00:27,889 INFO  [SimpleThreadPool] Job execution threads will use class loader of thread: Thread-2
      12:00:27,919 INFO  [SchedulerSignalerImpl] Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
      12:00:27,920 INFO  [QuartzScheduler] Quartz Scheduler v.1.7.3 created.
      12:00:27,921 DEBUG [UpdateChecker] Checking for update...
      12:00:27,923 INFO  [RAMJobStore] RAMJobStore initialized.
      12:00:27,923 INFO  [StdSchedulerFactory] Quartz scheduler 'DefaultQuartzScheduler' initialized from default resource file in Quartz package: 'quartz.properties'
      12:00:27,924 INFO  [StdSchedulerFactory] Quartz scheduler version: 1.7.3
      12:00:27,925 INFO  [QuartzScheduler] Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED started.
      12:00:28,052 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=APPDB' to JNDI name 'java:APPDB'
      12:00:28,085 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=APPDBNoTx' to JNDI name 'java:APPDBNoTx'
      12:00:28,406 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=DefaultDS' to JNDI name 'java:DefaultDS'
      12:00:28,644 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=JmsXA' to JNDI name 'java:JmsXA'
      12:00:28,684 INFO  [xnio] XNIO Version 2.1.0.CR2
      12:00:28,688 INFO  [nio] XNIO NIO Implementation Version 2.1.0.CR2
      12:00:28,745 INFO  [UpdateChecker] New update(s) found: 1.8.0 [http://www.terracotta.org/kit/reflector?kitID=default&pageID=QuartzChangeLog]
      12:00:28,843 INFO  [remoting] JBoss Remoting version 3.1.0.Beta2
      12:00:28,935 INFO  [TomcatDeployment] deploy, ctxPath=/APPHttpConnector
      12:00:28,994 INFO  [TomcatDeployment] deploy, ctxPath=/APPWebStart
      12:00:29,036 INFO  [TomcatDeployment] deploy, ctxPath=/

       

      ***** [n-times 'Created KernelDeployment' like] *****
      12:00:29,670 INFO  [JBossASKernel] Created KernelDeployment for: TheFirstEJB3Module.jar
      12:00:49,178 WARN  [InterceptorInfoRepository] EJBTHREE-1852: InterceptorInfoRepository is deprecated
      12:00:49,223 WARN  [EJBRemoteHandler] EJBTHREE-1828: EJBInjectionContainer jboss.j2ee:ear=APP.ear,jar=AnEJB3Module.jar,name=AStatelessSession,service=EJB3 is unconfigured, using legacy resolve
      12:00:49,231 INFO  [JBossASKernel] Created KernelDeployment for: TheLastEJB3Module.jar
      ***** [/'Created KernelDeployment'] *****

       

      ***** [n-times 'STARTED EJB' like] *****
      12:00:50,354 INFO  [SessionSpecContainer] Starting jboss.j2ee:ear=APP.ear,jar=TheFirstEJB3Module.jar,name=AStatelessSession,service=EJB3
      12:00:50,365 INFO  [EJBContainer] STARTED EJB: app.package.AStatelessSessionBean ejbName: AStatelessSession
      12:00:50,470 INFO  [JndiSessionRegistrarBase] Binding the following Entries in Global JNDI:

       

          app/package/AStatelessSession - EJB3.x Default Local Business Interface
          APP/AStatelessSession/local-app.package.AStatelessSession - EJB3.x Local Business Interface
      ***** [/'STARTED EJB'] *****

       

      12:01:01,203 INFO  [PersistenceUnitDeployment] Starting persistence unit persistence.unit:unitName=APP.ear/EJB3Persistence.jar#app.persistence.unit
      12:01:10,514 INFO  [Version] Hibernate Annotations 3.5.0-CR-1
      12:01:10,542 INFO  [Environment] Hibernate 3.5.0-CR-1
      12:01:10,545 INFO  [Environment] hibernate.properties not found
      12:01:10,550 INFO  [Environment] Bytecode provider name : javassist
      12:01:10,558 INFO  [Environment] using JDK 1.4 java.sql.Timestamp handling
      12:01:10,748 INFO  [Version] Hibernate Commons Annotations 3.2.0-SNAPSHOT
      12:01:10,763 INFO  [Version] Hibernate EntityManager 3.5.0-CR-1
      12:01:10,806 INFO  [Ejb3Configuration] Processing PersistenceUnitInfo [
          name: app.persistence.unit
          ...]
      12:01:15,134 WARN  [Ejb3Configuration] Persistence provider caller does not implement the EJB3 spec correctly. PersistenceUnitInfo.getNewTempClassLoader() is null.
      12:01:18,370 INFO  [Version] Hibernate Validator 3.1.0.GA
      12:01:19,115 INFO  [Version] Hibernate Validator 4.0.2.GA
      12:01:19,142 INFO  [DefaultTraversableResolver] Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResolver.
      12:01:20,317 INFO  [DefaultTraversableResolver] Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResolver.
      12:01:20,327 INFO  [HibernateSearchEventListenerRegister] Unable to find org.hibernate.search.event.FullTextIndexEventListener on the classpath. Hibernate Search is not enabled.
      12:01:20,956 INFO  [DefaultTraversableResolver] Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResolver.
      12:01:22,626 INFO  [ConnectionProviderFactory] Initializing connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
      12:01:22,634 INFO  [InjectedDataSourceConnectionProvider] Using provided datasource
      12:01:23,260 INFO  [SettingsFactory] RDBMS: Microsoft SQL Server, version: 9.00.4053
      12:01:23,261 INFO  [SettingsFactory] JDBC driver: Microsoft SQL Server JDBC Driver 2.0, version: 2.0.1803.100
      12:01:23,312 INFO  [Dialect] Using dialect: org.hibernate.dialect.SQLServerDialect
      12:01:23,340 INFO  [TransactionFactoryFactory] Transaction strategy: org.hibernate.ejb.transaction.JoinableCMTTransactionFactory
      12:01:23,345 INFO  [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup
      12:01:23,349 INFO  [TransactionManagerLookupFactory] instantiated TransactionManagerLookup
      12:01:23,349 INFO  [SettingsFactory] Automatic flush during beforeCompletion(): disabled
      12:01:23,350 INFO  [SettingsFactory] Automatic session close at end of transaction: disabled
      12:01:23,351 INFO  [SettingsFactory] Scrollable result sets: enabled
      12:01:23,352 INFO  [SettingsFactory] JDBC3 getGeneratedKeys(): enabled
      12:01:23,352 INFO  [SettingsFactory] Connection release mode: auto
      12:01:23,354 INFO  [SettingsFactory] Default batch fetch size: 1
      12:01:23,355 INFO  [SettingsFactory] Generate SQL with comments: disabled
      12:01:23,355 INFO  [SettingsFactory] Order SQL updates by primary key: disabled
      12:01:23,355 INFO  [SettingsFactory] Order SQL inserts for batching: disabled
      12:01:23,356 INFO  [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
      12:01:23,361 INFO  [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory
      12:01:23,361 INFO  [SettingsFactory] Query language substitutions: {}
      12:01:23,361 INFO  [SettingsFactory] JPA-QL strict compliance: enabled
      12:01:23,362 INFO  [SettingsFactory] Second-level cache: enabled
      12:01:23,362 INFO  [SettingsFactory] Query cache: disabled
      12:01:23,373 INFO  [SettingsFactory] Cache region factory : org.hibernate.cache.impl.bridge.RegionFactoryCacheProviderBridge
      12:01:23,374 INFO  [RegionFactoryCacheProviderBridge] Cache provider: org.hibernate.cache.HashtableCacheProvider
      12:01:23,376 INFO  [SettingsFactory] Optimize cache for minimal puts: disabled
      12:01:23,377 INFO  [SettingsFactory] Cache region prefix: persistence.unit:unitName=APP.ear/EJB3Persistence.jar#app.persistence.unit
      12:01:23,377 INFO  [SettingsFactory] Structured second-level cache entries: disabled
      12:01:23,390 INFO  [SettingsFactory] Statistics: disabled
      12:01:23,390 INFO  [SettingsFactory] Deleted entity synthetic identifier rollback: disabled
      12:01:23,391 INFO  [SettingsFactory] Default entity-mode: pojo
      12:01:23,391 INFO  [SettingsFactory] Named query checking : enabled
      12:01:23,391 INFO  [SettingsFactory] Check Nullability in Core (should be disabled when Bean Validation is on): disabled
      12:01:24,179 INFO  [SessionFactoryImpl] building session factory
      12:01:27,785 INFO  [SessionFactoryObjectFactory] Factory name: persistence.unit:unitName=APP.ear/EJB3Persistence.jar#app.persistence.unit
      12:01:27,788 INFO  [NamingHelper] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
      12:01:27,798 INFO  [NamingHelper] Creating subcontext: persistence.unit:unitName=APP.ear
      12:01:27,798 INFO  [SessionFactoryObjectFactory] Bound factory to JNDI name: persistence.unit:unitName=APP.ear/EJB3Persistence.jar#app.persistence.unit
      12:01:27,799 WARN  [SessionFactoryObjectFactory] InitialContext did not implement EventContext
      12:01:27,799 INFO  [NamingHelper] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}

       

      -----> ***** note that JBoss sleeps here for ~4 minutes, doing nothing; at least logging nothing :- / *****
      -----> ***** note that JndiSessionRegistrarBase needs ~3 minutes to register ~600 EJB3 Session Beans!! *****
      ***** [n-times 'STARTED EJB' like] *****
      12:05:07,966 INFO  [SessionSpecContainer] Starting jboss.j2ee:ear=APP.ear,jar=AnotherEJB3Module.jar,name=AnotherStatelessSession,service=EJB3
      12:05:07,967 INFO  [EJBContainer] STARTED EJB: app.package.AnotherStatelessSessionBean ejbName: AnotherStatelessSession
      12:05:08,253 INFO  [JndiSessionRegistrarBase] Binding the following Entries in Global JNDI:

       

          app/package/AnotherStatelessSession - EJB3.x Default Local Business Interface
          APP/AnotherStatelessSession/local-app.package.AnotherStatelessSession - EJB3.x Local Business Interface

       

      12:08:03,036 INFO  [SessionSpecContainer] Starting jboss.j2ee:ear=APP.ear,jar=TheLastEJB3Module.jar,name=TheLastStatelessSession,service=EJB3
      12:08:03,038 INFO  [EJBContainer] STARTED EJB: app.package.TheLastStatelessSessionBean ejbName: TheLastStatelessSession
      12:08:03,048 INFO  [JndiSessionRegistrarBase] Binding the following Entries in Global JNDI:

       

          app/package/TheLastStatelessSession - EJB3.x Default Remote Business Interface
          APP/TheLastStatelessSession/remote-app.packageTheLastStatelessSession - EJB3.x Remote Business Interface
      ***** [/'STARTED EJB'] *****

       

      12:08:03,221 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=eis/TheFirstResourceAdapter' to JNDI name 'java:eis/TheFirstResourceAdapter'
      12:08:03,247 INFO  [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=eis/TheLastResourceAdapter' to JNDI name 'java:eis/TheLastResourceAdapter'
      12:08:03,635 INFO  [service] Removing bootstrap log handlers

       


      ***** following lines from server.log ******

       

      12:08:03,789 INFO  [org.jboss.system.server.profileservice.ProfileServiceBootstrap] Loading profile: ProfileKey@4671b856[domain=default, server=default, name=APP]
      12:08:03,823 INFO  [org.apache.coyote.http11.Http11Protocol] Starting Coyote HTTP/1.1 on http-192.168.1.123-8080
      12:08:03,826 INFO  [org.apache.coyote.ajp.AjpProtocol] Starting Coyote AJP/1.3 on ajp-192.168.1.123-8009
      -----> ***** note that overall start time (boot+deploy) is ~8 minutes oO *****
      12:08:03,827 INFO  [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.20100429-M3 "Neo"] Started in 8m:9s:780ms

        • 2. Re: run JBoss 6.0.0 M3 with -Xdebug
          jaikiran pai Master

          I haven't compared the boot/deployment time difference when using -XDebug and when not using it. But I would still expect -XDebug to slow down things noticeably.

           

          Are you deploying the exact same application, with the same number of EJB3 beans even in 4.2.x? I know, there's a whole lot of additional processing that goes on in AS-5.x and AS-6.x as compared to 4.2.x. So that's going to affect the timings too.

          • 3. Re: run JBoss 6.0.0 M3 with -Xdebug
            robert.geisler Newbie

            thanks for response.

             

            the application deployed was not changed while testing with JBoss 4.2.2 GA and JBoss 6.0.0 M3. of course we do have some deployment deskriptors that differs because of the JBoss versions, but Java Code, EJBs,... did not changed at all.

             

            maybe you like to tell me a bit more about 'additional processing' so i could have a look for some optimisation?

             

            regards

            robert

            • 4. Re: run JBoss 6.0.0 M3 with -Xdebug
              jaikiran pai Master

              Robert Geisler wrote:

               

              maybe you like to tell me a bit more about 'additional processing' so i could have a look for some optimisation?

               

              1) Annotation scanning for (most of the) classes

              2) A completely different underlying kernel (JBoss Micro Container) in AS-5.x and AS-6.x, as compared to JBoss AS-4.x

               

              Those are some of the things that I can think of. If you really want to see what's going on with the slow performance with -Xdebug, I think you should use a profiler (ex: JProfiler) and compare the difference. But from what I remember, trying to profile JBoss AS running with -Xdebug, is really going to take long time and the profiling numbers themselves aren't really accurate.

              • 5. Re: run JBoss 6.0.0 M3 with -Xdebug
                robert.geisler Newbie

                update:

                 

                we did not investigate this any further.

                 

                anyway... with JBoss 6.0.0 final we do not see this behaviour, yet:

                start time with or without -Xdebug is about 2min 30secs (with our app deployed!).

                we dont know what changed since milestone3, but its fine for use now.

                 

                regards

                robert