3 Replies Latest reply: Mar 12, 2012 5:37 PM by Peter Johnson RSS

Interpreting GC verbose data for JBoss Server

todd.beckwith Newbie

Greetings All. TIA for any guidance you may be able to provide.

 

Prior to the beginning of last week, the only thing I knew about JBoss was that we used it in providing our internal users access to webpages created in a production called Natural for Ajax. I've been working in my current position for about 6 months and prior to that, developed applications for Telnet screens in a language called Natural. My IT director in my current position has been unhappy with performance of the webpages created in Natural for Ajax but I started my crash course in JBoss after fulfilling a request to add a new menu system to all of the webpages in our new system. All was well as we slowly shifted users to the new menus but once we opened it up to everyone, we began getting performance complaints. The users were experiencing 8 to 10 second hangs during round trips with the server. We ultimately had to remove a majority of users from the new menu system. After ruling out other components of the system and extensive Internet searching, I began to suspect garbage collection may be the problem.

 

I have since made a few changes that allow me to capture the GC statistics. I immediately noted that full GC was occuring every two minutes, even on our test system without any users. Other than the changes to capture GC data, the only other change I've made to date is to set -XX:+DisableExplicitGC. I do not have statistics on GC with all users on the new menu but I have little doubt that we will see a performance impact if we throw everyone back on it without making additional changes.

 

So, my question is, now that I have a days worth of GC data, how do I go about interpreting it? My gut tells me that new gen space is probably too small right now but I'm not sure how to determine a new size for new gen or calculate a survivor space ratio based on the data collected. Does anyone have a good link to information on how to make heads or tails out of what I am seeing in the GC logs?

 

I have attached the current GC data. Users don't really start hitting our system until the 149049.856 mark in the file.

 

Below are the current parameters being used.

 

JBoss Version:4.2.3.GA

 

Current heap size:1,266,187 kbytes
Maximum heap size:2,796,224 kbytes
Committed memory:2,071,552 kbytes
Uptime:2 days 0 hours 12 minutes
Garbage collector:Name = 'PS MarkSweep', Collections = 5, Total time spent = 48.361 seconds
Garbage collector:Name = 'PS Scavenge', Collections = 1,318, Total time spent = 1 minute

 

Operating System:HP-UX B.11.31
Architecture:IA64N
Number of processors:4
Committed virtual memory:-1 kbytes
Total physical memory:33,451,448 kbytes
Free physical memory:19,695,784 kbytes
Total swap space:16,777,216 kbytes
Free swap space:16,777,216 kbytes

 

VM arguments:

  -Dprogram.name=run.sh

  -Xms3g

  -Xmx3g

  -Dsun.rmi.dgc.client.gcInterval=3600000

  -Dsun.rmi.dgc.server.gcInterval=3600000

  -Dcom.sun.management.jmxremote

  -verbose:gc

  -Xloggc:/SAG/java/jboss_gc_20120310133545.log

  -XX:+PrintGCDetails

  -XX:+PrintGCTimeStamps

  -XX:+DisableExplicitGC

  -Djava.endorsed.dirs=/opt/jboss/jboss-4.2.3.GA/lib/endorsed

 

Thank you.

  • 1. Re: Interpreting GC verbose data for JBoss Server
    Peter Johnson Master

    For suggestions on how to gather GC data and analyze it, see these white papers:

    Java Garbage Collection Statistical Analysis 101

    Java Garbage Collection Performance Analysis 201

    at http://www.cmg.org/cgi-bin/search.cgi?q=java+peter+johnson&x=30&y=10

     

    Which version of the JVM are you using? If earlier than 1.6, you should also set the young generation size. I recommend about 1/3 to 1/4 the heap size, so 1g should be about right (see the white papers for details).

     

    The full GC every 2 minutes seems to indicate that there is a thread that runs every two minutes and calls Syste,.gc(). I assume that once you set -XX:+DisableExplicitGC that you no longer see the full GCs every two minutes.

  • 2. Re: Interpreting GC verbose data for JBoss Server
    todd.beckwith Newbie

    Peter,

     

    The Java version is 1.6.0.02.

     

    DisableExplicitGC did help with no reported problems from the users. It took about 2 hours for the first full GC and they are now occuring about every 45 minutes. This change alone has resulted in a significant reduction in the number of full collections and time spent in data collection. Based on some of my previous reading, I suspect there may still be room to increase the young generation and further reduce the number of full collections. I'll take a look at the membership requirements for the link you provided and see if the info there can help me out.

     

    Thanks Peter.

  • 3. Re: Interpreting GC verbose data for JBoss Server
    Peter Johnson Master

    My experience with the 1.6.0 version of the JVM is that it does a very good job of automatically sizing the young generation, usually using 1/3 the heap size. So for 1.6.0 you don't need to set the young gen size. (The white papers I mentioned are fairly old and concern mostly 1.3.1 and 1.4.2, though the techniques described are still valid. Some of my later papers cover 1.5 and 1.6 and some of the tuning differences.)