Garbage collection statistics

Garbage collection statistics are critical and should be enabled in production. The statistics can be used to understand the behavior of the JVM heap management and the efficiency of the JVM.

This section describes the garbage collection statistics.

IBM® provides excellent documentation on their garbage collector and how to interpret their GC statistics (see IBM Developer Kit and Runtime Environment, Java™ Technology Edition, Diagnostic Guide, Version 5.0, SC34-6650).

Here is a sample of the GC log:


   <af type="tenured" id="100" timestamp="Sun Nov 25 15:56:09 2007" 
intervalms="120245.593">
     <minimum requested_bytes="10016" />
     <time exclusiveaccessms="0.045" />
     <tenured freebytes="2704" totalbytes="1073741824" percent="0" >
       <soa freebytes="2704" totalbytes="1073741824" percent="0" />
       <loa freebytes="0" totalbytes="0" percent="0" />
     </tenured>
     <gc type="global" id="100" totalid="100" intervalms="120245.689">
       <refs_cleared soft="0" threshold="32" weak="0" phantom="0" />
       <finalization objectsqueued="0" />
       <timesms mark="35.301" sweep="5.074" compact="0.000" total="40.426" />
       <tenured freebytes="808526296" totalbytes="1073741824" percent="75" >
         <soa freebytes="808526296" totalbytes="1073741824" percent="75" />
         <loa freebytes="0" totalbytes="0" percent="0" />
       </tenured>
     </gc>
     <tenured freebytes="808516280" totalbytes="1073741824" percent="75" >
       <soa freebytes="808516280" totalbytes="1073741824" percent="75" />
       <loa freebytes="0" totalbytes="0" percent="0" />
     </tenured>
     <time totalms="40.569" />
   </af>

In the example above, <af type="tenured" id="100" indicates that this is the 100th time an attempt to allocate memory failed and as a result, a GC was initiated. An allocation failure is not an error in the system or code. When there is not enough free space in the heap, the JVM automatically initiate a garbage collection. The last time an allocation failure occurred was 120245.593 ms ago (or 120.245 seconds).

The lines starting with <gc type="global" id="100" provides information on the collection process. In the example above, garbage collection initiated the mark and sweep phases which completed in 35.301 and 5.074 milliseconds respectively. The JVM determined that the heap was not fragmented and hence did not require to compact the heap. At the end of the GC, the heap became 808,516,280 bytes free.

Frequency of GC health check

You should check how often GCs are occurring by looking at the time between allocation failures.

GC times

You should monitor the amount of time the JVM spends in GC. Typically, your JVM should:

Spend less than 0.5 seconds in each GC cycle.
The percentage of time in garbage collection should be less than 3% - This percentage can be calculated by dividing the sum of the garbage collection times over an interval by the interval. The interval could be a fixed 20 minutes or the last 20 GCs.

Potential memory leak

If the JVM is running for a while and the percentage free is continually decreasing with each successive GC, that JVM could be heading to an OutOfMemory condition. This could indicate that either the Java application is keeping a lot of active objects (e.g., reference data caching) or there is a memory leak.

By default, the IBM JVM produces a HeapDump when it runs out of memory. You can also configure the IBM JVM to produce a HeapDump on a signal. See Heapdump below.