3 Replies Latest reply on Aug 27, 2010 12:55 PM by Peter Johnson

    GC running at startup

    Andreas Melvanius Newbie

      Hi,

       

      I'm running the JBoss AS 4.0.3SP1 and suddenly I'v gotten problems with GC messages just after I start the JBoss server. The startup log looks like this.

       

      linux-java-test01:/u01/jboss/bin# =========================================================================

       

        JBoss Bootstrap Environment

       

        JBOSS_HOME: /u01/jboss

       

        JAVA: /opt/jdk1.6.0_18/bin/java

       

        JAVA_OPTS: -server -Xms1024m -Xmx1024m -Xss256k -XX:+DisableExplicitGC -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -XX:NewSize=128m -XX:MaxNewSize=128m -XX:PermSize=64m -XX:MaxPermSize=128m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled -XX:SoftRefLRUPolicyMSPerMB=10000 -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintGCDetails  -Dprogram.name=run.sh

       

        CLASSPATH: /u01/jboss/bin/run.jar:/opt/jdk1.6.0_18/lib/tools.jar

       

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

       

      14:40:34,052 INFO  [Server] Starting JBoss (MX MicroKernel)...
      14:40:34,060 INFO  [Server] Release ID: JBoss [Zion] 4.0.3SP1 (build: CVSTag=JBoss_4_0_3_SP1 date=200510231054)
      14:40:34,061 INFO  [Server] Home Dir: /u01/jboss
      14:40:34,062 INFO  [Server] Home URL: file:/u01/jboss/
      14:40:34,063 INFO  [Server] Patch URL: null
      14:40:34,063 INFO  [Server] Server Name: default
      14:40:34,063 INFO  [Server] Server Home Dir: /u01/jboss/server/default
      14:40:34,063 INFO  [Server] Server Home URL: file:/u01/jboss/server/default/
      14:40:34,063 INFO  [Server] Server Temp Dir: /u01/jboss/server/default/tmp
      14:40:34,064 INFO  [Server] Root Deployment Filename: jboss-service.xml
      14:40:34,495 INFO  [ServerInfo] Java version: 1.6.0_18,Sun Microsystems Inc.
      14:40:34,496 INFO  [ServerInfo] Java VM: Java HotSpot(TM) 64-Bit Server VM 16.0-b13,Sun Microsystems Inc.
      14:40:34,496 INFO  [ServerInfo] OS-System: Linux 2.6.26-2-amd64,amd64
      14:40:34,988 INFO  [Server] Core system initialized
      14:40:36,901 INFO  [WebService] Using RMI server codebase: http://linux-java-test01:8083/
      14:40:36,914 INFO  [Log4jService$URLWatchTimerTask] Configuring from URL: resource:log4j.xml
      {Heap before GC invocations=0 (full 0):
      def new generation   total 118016K, used 104960K [0x00007f558cf90000, 0x00007f5594f90000, 0x00007f5594f90000)
        eden space 104960K, 100% used [0x00007f558cf90000, 0x00007f5593610000, 0x00007f5593610000)
        from space 13056K,   0% used [0x00007f5593610000, 0x00007f5593610000, 0x00007f55942d0000)
        to   space 13056K,   0% used [0x00007f55942d0000, 0x00007f55942d0000, 0x00007f5594f90000)
      concurrent mark-sweep generation total 917504K, used 0K [0x00007f5594f90000, 0x00007f55ccf90000, 0x00007f55ccf90000)
      concurrent-mark-sweep perm gen total 65536K, used 18571K [0x00007f55ccf90000, 0x00007f55d0f90000, 0x00007f55d4f90000)
      5.878: [GC 5.879: [DefNew: 104960K->9800K(118016K), 0.0447440 secs] 104960K->9800K(1035520K), 0.0448350 secs] [Times: user=0.05 sys=0.00, real=0.04 secs]
      Heap after GC invocations=1 (full 0):
      def new generation   total 118016K, used 9800K [0x00007f558cf90000, 0x00007f5594f90000, 0x00007f5594f90000)
        eden space 104960K,   0% used [0x00007f558cf90000, 0x00007f558cf90000, 0x00007f5593610000)
        from space 13056K,  75% used [0x00007f55942d0000, 0x00007f5594c62178, 0x00007f5594f90000)
        to   space 13056K,   0% used [0x00007f5593610000, 0x00007f5593610000, 0x00007f55942d0000)
      concurrent mark-sweep generation total 917504K, used 0K [0x00007f5594f90000, 0x00007f55ccf90000, 0x00007f55ccf90000)
      concurrent-mark-sweep perm gen total 65536K, used 18571K [0x00007f55ccf90000, 0x00007f55d0f90000, 0x00007f55d4f90000)
      }
      {Heap before GC invocations=1 (full 0):
      def new generation   total 118016K, used 114760K [0x00007f558cf90000, 0x00007f5594f90000, 0x00007f5594f90000)
        eden space 104960K, 100% used [0x00007f558cf90000, 0x00007f5593610000, 0x00007f5593610000)
        from space 13056K,  75% used [0x00007f55942d0000, 0x00007f5594c62178, 0x00007f5594f90000)
        to   space 13056K,   0% used [0x00007f5593610000, 0x00007f5593610000, 0x00007f55942d0000)
      concurrent mark-sweep generation total 917504K, used 0K [0x00007f5594f90000, 0x00007f55ccf90000, 0x00007f55ccf90000)
      concurrent-mark-sweep perm gen total 65536K, used 25674K [0x00007f55ccf90000, 0x00007f55d0f90000, 0x00007f55d4f90000)
      8.770: [GC 8.770: [DefNew: 114760K->9934K(118016K), 0.0722620 secs] 114760K->19637K(1035520K), 0.0723560 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]
      Heap after GC invocations=2 (full 0):
      def new generation   total 118016K, used 9934K [0x00007f558cf90000, 0x00007f5594f90000, 0x00007f5594f90000)
        eden space 104960K,   0% used [0x00007f558cf90000, 0x00007f558cf90000, 0x00007f5593610000)
        from space 13056K,  76% used [0x00007f5593610000, 0x00007f5593fc3ad0, 0x00007f55942d0000)
        to   space 13056K,   0% used [0x00007f55942d0000, 0x00007f55942d0000, 0x00007f5594f90000)
      concurrent mark-sweep generation total 917504K, used 9702K [0x00007f5594f90000, 0x00007f55ccf90000, 0x00007f55ccf90000)
      concurrent-mark-sweep perm gen total 65536K, used 25674K [0x00007f55ccf90000, 0x00007f55d0f90000, 0x00007f55d4f90000)
      }

       

       

      And it continue with the "Heap after GC invocations" messages if I browse to the server. I only get these messages when running on linux (debian and red-hat), not in windows. The really strange thing is that I can't remember that I had these GC messages in the startup a couple of months ago and no changes has been done to the Jboss installation or deployments to the server, but I could be wrong (maybe just missed them before). However I would like to know if they are serious, and if they are, what I can do to configure my server the right way so it doesn't have to run GC all the time. My linux servers are virtual servers that are based on VMware if that maybe has an impact. The virtual server has 4GB of memory so it shouldn't be a problem with available memory.

       

      /Andreas

        • 1. Re: GC running at startup
          jaikiran pai Master
          -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps  -XX:+PrintHeapAtGC -XX:+PrintGCDetails

          Looks like someone added those params to the run.conf file. As a result you see these verbose level logs during GC. If you don't need the GC logs, you can remove those JVM params from the run.conf file

          • 2. Re: GC running at startup
            Andreas Melvanius Newbie

            Thank you for your answer. I know how to remove these GC actions logging by removing the params that you talk about, but that doesn't really answer my question. What I really want to know is if it's normal that the jboss server does this GC directly after the start. I think it's strange that it does GC just after restart.

            • 3. Re: GC running at startup
              Peter Johnson Master

              Yes, this is normal. There are a few places during bootstrap and startup when the app server calls System.gc() to clean up garbage - that is why those collecitons are major collections. Any minor collections that appear are of course because the young generation gets filles up and needs to be collected, which will happen a few times during startup.

               

              If you really dislike having the major GCs run (in a way, there is really no need for them), set -XX:+DisableExplicitGC