14 Replies Latest reply on Feb 26, 2010 6:22 PM by mike.curwen

    JBoss 3.2.6 - pauses for a minute during startup

    mike.curwen

      Hello,

       

      I'm currently migrating a production application from older physical hardware, to a new vmware host.

       

      I've confirmed that all components (java version, jboss version, config files, application and  libraries) are the same between platforms.  I've also made the platforms  as close as possible, recognizing that vmware HD space, RAM and CPU are not the same as 'real' ones.  The remaining differences would be that our existing production server is (I think) some flavour of redhat running linux 2.6.8 on reiserfs, and the  new vmware host is ubuntu linux 2.6.24  using ext3.

      I recognize that there's quite a difference between plain hardware  and VMWare hosts.  But... 

      When I start this application on my localhost (also ubuntu) for development it  takes about 17 seconds for the whole thing to start.  On production it  takes about the same.  But on the new VM host, it takes a minute and 17  seconds, and nearly the whole minute extra is experienced right here  (3rd line from bottom):

       

      =========================================================================
      
        JBoss Bootstrap Environment
      
        JBOSS_HOME: /usr/foo/java/jboss-3.2.6
      
        JAVA: /usr/foo/java/j2sdk1.4.2_19/bin/java
      
        JAVA_OPTS: -server -Xms700m -Xmx700m -Djava.awt.headless=true -Dprogram.name=run.sh
      
        CLASSPATH: /usr/foo/java/jboss-3.2.6/bin/run.jar:/usr/foo/java/j2sdk1.4.2_19/lib/tools.jar
      
      =========================================================================
      
      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$ 10:06:41,010 INFO  [Server] Starting JBoss (MX MicroKernel)...
      10:06:41,011 INFO  [Server] Release ID: JBoss [WonderLand] 3.2.6 (build: CVSTag=JBoss_3_2_6 date=200410140106)
      10:06:41,012 INFO  [Server] Home Dir: /usr/foo/java/jboss-3.2.6
      10:06:41,012 INFO  [Server] Home URL: file:/usr/foo/java/jboss-3.2.6/
      10:06:41,012 INFO  [Server] Library URL: file:/usr/foo/java/jboss-3.2.6/lib/
      10:06:41,013 INFO  [Server] Patch URL: null
      10:06:41,013 INFO  [Server] Server Name: default
      10:06:41,013 INFO  [Server] Server Home Dir: /usr/foo/java/jboss-3.2.6/server/default
      10:06:41,013 INFO  [Server] Server Home URL: file:/usr/foo/java/jboss-3.2.6/server/default/
      10:06:41,013 INFO  [Server] Server Data Dir: /usr/foo/java/jboss-3.2.6/server/default/data
      10:06:41,014 INFO  [Server] Server Temp Dir: /usr/foo/java/jboss-3.2.6/server/default/tmp
      10:06:41,014 INFO  [Server] Server Config URL: file:/usr/foo/java/jboss-3.2.6/server/default/conf/
      10:06:41,014 INFO  [Server] Server Library URL: file:/usr/foo/java/jboss-3.2.6/server/default/lib/
      10:06:41,014 INFO  [Server] Root Deployment Filename: jboss-service.xml
      10:06:41,016 INFO  [Server] Starting General Purpose Architecture (GPA)...
      10:06:41,250 INFO  [ServerInfo] Java version: 1.4.2_19,Sun Microsystems Inc.
      10:06:41,250 INFO  [ServerInfo] Java VM: Java HotSpot(TM) Server VM 1.4.2_19-b04,Sun Microsystems Inc.
      10:06:41,250 INFO  [ServerInfo] OS-System: Linux 2.6.24-23-generic,i386
      10:06:41,422 INFO  [Server] Core system initialized
      10:07:34,053 INFO  [Log4jService$URLWatchTimerTask] Configuring from URL: resource:log4j.xml
      10:07:39,116 INFO  [WebService] Using RMI server codebase: http://oldhost:8083/
      

       

      See how it takes nearly a minute after "Core system initialized" to proceed with the rest of the startup?  Once it's past this hump, the rest of the load proceeds 'normally' and the app itself seems performant (haven't gotten to true load testing yet).

       

      Has anyone seen this before, or have ideas what it could be, or where I should start looking for my lost minute?

       

      Thanks.

        • 1. Re: JBoss 3.2.6 - pauses for a minute during startup
          peterj

          Unless someone on the AS team recalls what is being done during that time on startup (doubtful considering how ancient 3.2.6 is), your best bet would be to take a few JVM thread dumps during that time. Looking at the dumps should give you some idea as to what code is being processed.

           

          Offhand, I suspect that what you are seeing is the transition from the bootstrap code to the server code which means that there are a lot of JARs being loaded and that the code is doing a lot of disk IO. But this is just a guess.

          • 2. Re: JBoss 3.2.6 - pauses for a minute during startup
            mike.curwen

            Thanks Peter,

             

            It's odd, I've done three more time trials, and this time it was 20 seconds, 1 minute 30 seconds, and 25 seconds.

             

            During the 1 minute pause of the second run, vmstat showed no i/o or cpu wait.   weird.

            • 3. Re: JBoss 3.2.6 - pauses for a minute during startup
              peterj
              Was vmstat run in the client VM? Often such tools return questionable results when run within a VM which is one reason why I suggested grabbing thread dumps since they might give a better picture of what is going on.
              • 4. Re: JBoss 3.2.6 - pauses for a minute during startup
                jaikiran

                My guess is there is no "pause". It's just that, there is no INFO level logging happening during that time. Check the JBOSS_HOME/server/< servername>/log/server.log and you might see some DEBUG level logging at this time, which might show what is being processed.

                • 5. Re: JBoss 3.2.6 - pauses for a minute during startup
                  mike.curwen

                  ah, yes it was the client vm.  It will be useful to get under the host though.  will ask our infra guy to check out the VM server.

                  • 6. Re: JBoss 3.2.6 - pauses for a minute during startup
                    mike.curwen

                    The pause is not reliable anymore.  Earlier today it was fairly consistently pausing, but now it's fairly consistently not pausing.

                     

                    Anyways, I did manage to catch it's pause behaviour, and during that time, there is no DEBUG level activity in the $JBOSS_HOME/server/default/log/boot.log file.

                     

                    tail: boot.log: file truncated
                    14:22:25,317 DEBUG [SARDeployer] Created jboss.system:service=ServiceDeployer
                    14:22:25,317 DEBUG [ServiceController] Creating dependent components for: jboss.system:service=ServiceDeployer dependents are: []
                    14:22:25,317 DEBUG [ServiceController] starting service jboss.system:service=ServiceDeployer
                    14:22:25,317 DEBUG [SARDeployer] Starting jboss.system:service=ServiceDeployer
                    14:22:25,317 DEBUG [MainDeployer] Adding deployer: org.jboss.deployment.SARDeployer@cbf30e
                    14:22:25,324 DEBUG [SARDeployer] Started jboss.system:service=ServiceDeployer
                    14:22:25,324 DEBUG [ServiceController] Starting dependent components for: jboss.system:service=ServiceDeployer dependent components: []
                    14:22:25,324 INFO  [Server] Core system initialized
                    14:22:25,334 DEBUG [MainDeployer] Starting deployment of package: file:/usr/foo/java/jboss-3.2.6/server/default/conf/jboss-service.xml
                    14:22:25,334 DEBUG [MainDeployer] Starting deployment (init step) of package at: file:/usr/foo/java/jboss-3.2.6/server/default/conf/jboss-service.xml
                    
                    
                    (this gap here corresponds to the 1 minute pause)
                    
                    
                    14:23:30,054 DEBUG [MainDeployer] Copying file:/usr/foo/java/jboss-3.2.6/server/default/conf/jboss-service.xml -> /usr/foo/java/jboss-3.2.6/server/default/tmp/deploy/tmp7686472998202003391jboss-service.xml
                    14:23:30,058 DEBUG [MainDeployer] using deployer org.jboss.deployment.SARDeployer@cbf30e
                    14:23:30,287 DEBUG [SARDeployer] Found classpath element: [classpath: null]
                    14:23:30,289 DEBUG [SARDeployer] codebase URL is file:/usr/foo/java/jboss-3.2.6/server/default/lib/
                    14:23:30,289 DEBUG [SARDeployer] listing codebase for archives matching *
                    14:23:30,291 DEBUG [SARDeployer] URLLister class is org.jboss.net.protocol.file.FileURLLister
                    14:23:30,304 DEBUG [SARDeployer] deployed classes for file:/usr/foo/java/jboss-3.2.6/server/default/lib/jboss-hibernate.jar
                    14:23:30,304 DEBUG [SARDeployer] deployed classes for file:/usr/foo/java/jboss-3.2.6/server/default/lib/jboss-common-jdbc-wrapper.jar
                    14:23:30,305 DEBUG [SARDeployer] deployed classes for file:/usr/foo/java/jboss-3.2.6/server/default/lib/bcel.jar
                    14:23:30,305 DEBUG [SARDeployer] deployed classes for file:/usr/foo/java/jboss-3.2.6/server/default/lib/PDDIB.jar
                    etc.
                    .
                    .
                    
                    
                    • 7. Re: JBoss 3.2.6 - pauses for a minute during startup
                      mike.curwen

                      I've managed to catch a pause again.  I took 3 thread dumps, each about 10 seconds apart.

                       

                      14:54:02,029 INFO  [Server] Root Deployment Filename: jboss-service.xml
                      14:54:02,030 INFO  [Server] Starting General Purpose Architecture (GPA)...
                      14:54:02,263 INFO  [ServerInfo] Java version: 1.4.2_19,Sun Microsystems Inc.
                      14:54:02,263 INFO  [ServerInfo] Java VM: Java HotSpot(TM) Server VM 1.4.2_19-b04,Sun Microsystems Inc.
                      14:54:02,263 INFO  [ServerInfo] OS-System: Linux 2.6.24-23-generic,i386
                      14:54:02,437 INFO  [Server] Core system initialized
                      Full thread dump Java HotSpot(TM) Server VM (1.4.2_19-b04 mixed mode):
                      
                      "DestroyJavaVM" prio=1 tid=0x08057c38 nid=0x472e waiting on condition [0x00000000..0xbff722ec]
                      
                      "main" prio=1 tid=0x080ef038 nid=0x4738 runnable [0x81ad4000..0x81ad51b8]
                              at java.io.FileInputStream.readBytes(Native Method)
                              at java.io.FileInputStream.read(FileInputStream.java:194)
                              at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
                              at java.io.BufferedInputStream.read1(BufferedInputStream.java:222)
                              at java.io.BufferedInputStream.read(BufferedInputStream.java:277)
                              - locked <0x83238588> (a java.io.BufferedInputStream)
                              at sun.security.provider.SeedGenerator$URLSeedGenerator.getSeedByte(SeedGenerator.java:467)
                              at sun.security.provider.SeedGenerator.getSeedBytes(SeedGenerator.java:137)
                              at sun.security.provider.SeedGenerator.generateSeed(SeedGenerator.java:132)
                              at sun.security.provider.SecureRandom.engineGenerateSeed(SecureRandom.java:112)
                              at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:169)
                              - locked <0x83238048> (a sun.security.provider.SecureRandom)
                              at java.security.SecureRandom.nextBytes(SecureRandom.java:381)
                              - locked <0x831bffc0> (a java.security.SecureRandom)
                              at java.security.SecureRandom.next(SecureRandom.java:403)
                              at java.util.Random.nextLong(Random.java:282)
                              at java.io.File.generateFile(File.java:1291)
                              at java.io.File.createTempFile(File.java:1399)
                              at org.jboss.deployment.MainDeployer.makeLocalCopy(MainDeployer.java:990)
                              at org.jboss.deployment.MainDeployer.init(MainDeployer.java:673)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:631)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:604)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:588)
                              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                              at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
                              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                              at java.lang.reflect.Method.invoke(Method.java:324)
                              at org.jboss.mx.server.ReflectedDispatcher.dispatch(ReflectedDispatcher.java:60)
                              at org.jboss.mx.server.Invocation.dispatch(Invocation.java:62)
                              at org.jboss.mx.server.Invocation.dispatch(Invocation.java:54)
                              at org.jboss.mx.server.Invocation.invoke(Invocation.java:82)
                              at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:197)
                              at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:473)
                              at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:176)
                              at $Proxy5.deploy(Unknown Source)
                              at org.jboss.system.server.ServerImpl.doStart(ServerImpl.java:407)
                              at org.jboss.system.server.ServerImpl.start(ServerImpl.java:311)
                              at org.jboss.Main.boot(Main.java:145)
                              at org.jboss.Main$1.run(Main.java:399)
                              at java.lang.Thread.run(Thread.java:534)
                      
                      "Signal Dispatcher" daemon prio=1 tid=0x080c09f0 nid=0x4733 waiting on condition [0x00000000..0x00000000]
                      
                      "Finalizer" daemon prio=1 tid=0x080bb858 nid=0x4731 in Object.wait() [0x82535000..0x825351b8]
                              at java.lang.Object.wait(Native Method)
                              - waiting on <0x82910490> (a java.lang.ref.ReferenceQueue$Lock)
                              at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111)
                              - locked <0x82910490> (a java.lang.ref.ReferenceQueue$Lock)
                              at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127)
                              at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
                      
                      "Reference Handler" daemon prio=1 tid=0x080bb480 nid=0x4730 in Object.wait() [0x825b6000..0x825b61b8]
                              at java.lang.Object.wait(Native Method)
                              - waiting on <0x82910380> (a java.lang.ref.Reference$Lock)
                              at java.lang.Object.wait(Object.java:429)
                              at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115)
                              - locked <0x82910380> (a java.lang.ref.Reference$Lock)
                      
                      "VM Thread" prio=1 tid=0x080ba9e0 nid=0x472f runnable
                      
                      "VM Periodic Task Thread" prio=1 tid=0x080c4fe0 nid=0x4737 waiting on condition
                      "Suspend Checker Thread" prio=1 tid=0x080c0000 nid=0x4732 runnable
                      
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$  (this is me hitting enter a couple times...)
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$ Full thread dump Java HotSpot(TM) Server VM (1.4.2_19-b04 mixed mode):
                      
                      "DestroyJavaVM" prio=1 tid=0x08057c38 nid=0x472e waiting on condition [0x00000000..0xbff722ec]
                      
                      "main" prio=1 tid=0x080ef038 nid=0x4738 runnable [0x81ad4000..0x81ad51b8]
                              at java.io.FileInputStream.readBytes(Native Method)
                              at java.io.FileInputStream.read(FileInputStream.java:194)
                              at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
                              at java.io.BufferedInputStream.read1(BufferedInputStream.java:222)
                              at java.io.BufferedInputStream.read(BufferedInputStream.java:277)
                              - locked <0x83238588> (a java.io.BufferedInputStream)
                              at sun.security.provider.SeedGenerator$URLSeedGenerator.getSeedByte(SeedGenerator.java:467)
                              at sun.security.provider.SeedGenerator.getSeedBytes(SeedGenerator.java:137)
                              at sun.security.provider.SeedGenerator.generateSeed(SeedGenerator.java:132)
                              at sun.security.provider.SecureRandom.engineGenerateSeed(SecureRandom.java:112)
                              at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:169)
                              - locked <0x83238048> (a sun.security.provider.SecureRandom)
                              at java.security.SecureRandom.nextBytes(SecureRandom.java:381)
                              - locked <0x831bffc0> (a java.security.SecureRandom)
                              at java.security.SecureRandom.next(SecureRandom.java:403)
                              at java.util.Random.nextLong(Random.java:282)
                              at java.io.File.generateFile(File.java:1291)
                              at java.io.File.createTempFile(File.java:1399)
                              at org.jboss.deployment.MainDeployer.makeLocalCopy(MainDeployer.java:990)
                              at org.jboss.deployment.MainDeployer.init(MainDeployer.java:673)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:631)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:604)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:588)
                              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                              at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
                              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                              at java.lang.reflect.Method.invoke(Method.java:324)
                              at org.jboss.mx.server.ReflectedDispatcher.dispatch(ReflectedDispatcher.java:60)
                              at org.jboss.mx.server.Invocation.dispatch(Invocation.java:62)
                              at org.jboss.mx.server.Invocation.dispatch(Invocation.java:54)
                              at org.jboss.mx.server.Invocation.invoke(Invocation.java:82)
                              at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:197)
                              at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:473)
                              at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:176)
                              at $Proxy5.deploy(Unknown Source)
                              at org.jboss.system.server.ServerImpl.doStart(ServerImpl.java:407)
                              at org.jboss.system.server.ServerImpl.start(ServerImpl.java:311)
                              at org.jboss.Main.boot(Main.java:145)
                              at org.jboss.Main$1.run(Main.java:399)
                              at java.lang.Thread.run(Thread.java:534)
                      
                      "Signal Dispatcher" daemon prio=1 tid=0x080c09f0 nid=0x4733 waiting on condition [0x00000000..0x00000000]
                      
                      "Finalizer" daemon prio=1 tid=0x080bb858 nid=0x4731 in Object.wait() [0x82535000..0x825351b8]
                              at java.lang.Object.wait(Native Method)
                              - waiting on <0x82910490> (a java.lang.ref.ReferenceQueue$Lock)
                              at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111)
                              - locked <0x82910490> (a java.lang.ref.ReferenceQueue$Lock)
                              at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127)
                              at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
                      
                      "Reference Handler" daemon prio=1 tid=0x080bb480 nid=0x4730 in Object.wait() [0x825b6000..0x825b61b8]
                              at java.lang.Object.wait(Native Method)
                              - waiting on <0x82910380> (a java.lang.ref.Reference$Lock)
                              at java.lang.Object.wait(Object.java:429)
                              at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115)
                              - locked <0x82910380> (a java.lang.ref.Reference$Lock)
                      
                      "VM Thread" prio=1 tid=0x080ba9e0 nid=0x472f runnable
                      
                      "VM Periodic Task Thread" prio=1 tid=0x080c4fe0 nid=0x4737 waiting on condition
                      "Suspend Checker Thread" prio=1 tid=0x080c0000 nid=0x4732 runnable
                      
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$  (more of me hitting enter)
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$ Full thread dump Java HotSpot(TM) Server VM (1.4.2_19-b04 mixed mode):
                      
                      "DestroyJavaVM" prio=1 tid=0x08057c38 nid=0x472e waiting on condition [0x00000000..0xbff722ec]
                      
                      "main" prio=1 tid=0x080ef038 nid=0x4738 runnable [0x81ad4000..0x81ad51b8]
                              at java.io.FileInputStream.readBytes(Native Method)
                              at java.io.FileInputStream.read(FileInputStream.java:194)
                              at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
                              at java.io.BufferedInputStream.read1(BufferedInputStream.java:222)
                              at java.io.BufferedInputStream.read(BufferedInputStream.java:277)
                              - locked <0x83238588> (a java.io.BufferedInputStream)
                              at sun.security.provider.SeedGenerator$URLSeedGenerator.getSeedByte(SeedGenerator.java:467)
                              at sun.security.provider.SeedGenerator.getSeedBytes(SeedGenerator.java:137)
                              at sun.security.provider.SeedGenerator.generateSeed(SeedGenerator.java:132)
                              at sun.security.provider.SecureRandom.engineGenerateSeed(SecureRandom.java:112)
                              at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:169)
                              - locked <0x83238048> (a sun.security.provider.SecureRandom)
                              at java.security.SecureRandom.nextBytes(SecureRandom.java:381)
                              - locked <0x831bffc0> (a java.security.SecureRandom)
                              at java.security.SecureRandom.next(SecureRandom.java:403)
                              at java.util.Random.nextLong(Random.java:282)
                              at java.io.File.generateFile(File.java:1291)
                              at java.io.File.createTempFile(File.java:1399)
                              at org.jboss.deployment.MainDeployer.makeLocalCopy(MainDeployer.java:990)
                              at org.jboss.deployment.MainDeployer.init(MainDeployer.java:673)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:631)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:604)
                              at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:588)
                              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                              at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
                              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                              at java.lang.reflect.Method.invoke(Method.java:324)
                              at org.jboss.mx.server.ReflectedDispatcher.dispatch(ReflectedDispatcher.java:60)
                              at org.jboss.mx.server.Invocation.dispatch(Invocation.java:62)
                              at org.jboss.mx.server.Invocation.dispatch(Invocation.java:54)
                              at org.jboss.mx.server.Invocation.invoke(Invocation.java:82)
                              at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:197)
                              at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:473)
                              at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:176)
                              at $Proxy5.deploy(Unknown Source)
                              at org.jboss.system.server.ServerImpl.doStart(ServerImpl.java:407)
                              at org.jboss.system.server.ServerImpl.start(ServerImpl.java:311)
                              at org.jboss.Main.boot(Main.java:145)
                              at org.jboss.Main$1.run(Main.java:399)
                              at java.lang.Thread.run(Thread.java:534)
                      
                      "Signal Dispatcher" daemon prio=1 tid=0x080c09f0 nid=0x4733 waiting on condition [0x00000000..0x00000000]
                      
                      "Finalizer" daemon prio=1 tid=0x080bb858 nid=0x4731 in Object.wait() [0x82535000..0x825351b8]
                              at java.lang.Object.wait(Native Method)
                              - waiting on <0x82910490> (a java.lang.ref.ReferenceQueue$Lock)
                              at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111)
                              - locked <0x82910490> (a java.lang.ref.ReferenceQueue$Lock)
                              at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127)
                              at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
                      
                      "Reference Handler" daemon prio=1 tid=0x080bb480 nid=0x4730 in Object.wait() [0x825b6000..0x825b61b8]
                              at java.lang.Object.wait(Native Method)
                              - waiting on <0x82910380> (a java.lang.ref.Reference$Lock)
                              at java.lang.Object.wait(Object.java:429)
                              at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115)
                              - locked <0x82910380> (a java.lang.ref.Reference$Lock)
                      
                      "VM Thread" prio=1 tid=0x080ba9e0 nid=0x472f runnable
                      
                      "VM Periodic Task Thread" prio=1 tid=0x080c4fe0 nid=0x4737 waiting on condition
                      "Suspend Checker Thread" prio=1 tid=0x080c0000 nid=0x4732 runnable
                      
                      
                      me@oldhost:/usr/foo/java/jboss-3.2.6/bin$ 14:54:46,561 INFO  [Log4jService$URLWatchTimerTask] Configuring from URL: resource:log4j.xml
                      
                      pause is now over....
                      
                      

                       

                      so I read that as "it's waiting for i/o", except vmstat within the host didn't show this wait.    Would this be evidence of resource contention in the server that is hosting the VM?

                      • 8. Re: JBoss 3.2.6 - pauses for a minute during startup
                        peterj

                        Yes, it looks like it is waiting for IO to complete. And given this part of the stack:

                         

                        at org.jboss.deployment.MainDeployer.makeLocalCopy(MainDeployer.java:990)
                                at org.jboss.deployment.MainDeployer.init(MainDeployer.java:673)
                                at org.jboss.deployment.MainDeployer.deploy(MainDeployer.java:631)

                         

                        I would say that it is copying the packaged archive files from the deploy directory to the tmp directory.

                        1 of 1 people found this helpful
                        • 9. Re: JBoss 3.2.6 - pauses for a minute during startup
                          brian.stansberry

                          It's reading from a URL that's meant to be a source of randomness (e.g. /dev/random or /dev/urandom). Presumably so it can create a name for a temp file.

                           

                          In boot.log there is a dump at the beginning of all the system property values available at the time: is there anything for

                           

                          • java.security.egd
                          • securerandom.source

                           

                          If so, that tells you the URL it's reading from.

                          • 10. Re: JBoss 3.2.6 - pauses for a minute during startup
                            mike.curwen

                            Hi Brian, I don't find an entry for either of those properties in the boot.log.

                             

                            I've googled a bit, and are you thinking I should add

                            -Djava.security.egd=file:/dev/urandom

                            ?

                            Thanks.
                            • 11. Re: JBoss 3.2.6 - pauses for a minute during startup
                              peterj
                              Another thought - did you preallocate the disk? If not, VMWare at times expanding the size of the virtual disk could explain the wild differences in "pause" times.
                              • 12. Re: JBoss 3.2.6 - pauses for a minute during startup
                                mike.curwen

                                the disk is preallocated.

                                • 13. Re: JBoss 3.2.6 - pauses for a minute during startup
                                  brian.stansberry
                                  Oops; I misread. It's not checking System.getProperty("securerandom.source") -- it's Security.getProperty("securerandom.source"). And the value for that generally comes from

                                   

                                  $JAVA_HOME/jre/lib/security/java.security

                                   

                                  where $JAVA_HOME is the root of the JDK you're using.

                                   

                                  On my system, that's

                                   

                                  securerandom.source=file:/dev/urandom

                                   

                                  If on your system it's file:/dev/random and your system provides /dev/urandom, yes, you might consider changing it to file:/dev/urandom. Or, if you want to limit the change to just this application and not all uses of the JDK, like you say, use -Djava.security.egd=file:/dev/urandom


                                  That's the workaround listed for this JDK bug:

                                  http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4705093

                                   

                                  The output from /dev/urandom may contain less entropy then that from /dev/random, but it won't block. Whether the decrease in entropy is important for you depends on your application. I'd think it would only be a concern for a very small subset of applications.

                                  1 of 1 people found this helpful
                                  • 14. Re: JBoss 3.2.6 - pauses for a minute during startup
                                    mike.curwen

                                    This is the second app we're migrating to virtual platforms.  The first one does not exhibit this problem.  But.. the first one is also started from a GUI context. there are four console windows that they have open at all times on the server's desktop.  They start one part of the app, mouse over to the second console and start the second part. mouse over to the third console... you get the idea.  (so, plenty of mouse and keyboard input to refresh /dev/random).

                                     

                                    I tried starting this app I'm having the pause with, from a gui context.    We would start/stop the app until the pause occured (generally no more than 3 cycles). Once we had a run cycle that exhibited the pause, we then shook the mouse around, and it un-paused.   Two times we did that.

                                     

                                    I also did the same thing from a command-line only context, by having two copies of run.sh and run.conf.   I would "Drain" the /dev/random by start/stopping the first copy (until it exhibited the pause).  I would then kill -9 that app, and switch to the other version which used /dev/urandom, and it would not pause during startup.   Tried that a couple times as well.

                                     

                                    Perhaps it's naieve to think that by start/stoping I'm "draining" /dev/random... but the pause seems to be repeatable, and switching to /dev/urandom the pause cannot be made to happen, in several tries.

                                     

                                    Thanks for the help!