Home > Articles > Programming > Java

Java Reference Guide

Hosted by

Toggle Open Guide Table of ContentsGuide Contents

Close Table of ContentsGuide Contents

Close Table of Contents

Obtaining Sun Heap Information

Last updated Mar 14, 2003.

Several APIs will give you information about a 1.4.x heap, but the one that I want to focus on is the JVM's logging capabilities. By providing specific parameters to the JVM on startup, you can ask the JVM to provide information, by way of a log file, of the details of each garbage collection that occurs in the heap. You can use this information to better size the regions in the heap to enhance performance.

The key parameters that you can send to the JVM are summarized below:

  • -verbose:gc - Prints some GC info
  • -XX:+PrintGCDetails - PrintGC details
  • -XX:+PrintGCTimeStamps - Adds timestamp info to GC details
  • -XX:+PrintHeapAtGC - Prints detailed GC info including heap occupancy before and after GC
  • -XX:+PrintTenuringDistribution - Prints object aging or tenuring information
  • -XX:+PrintHeapUsageOverTime - Print heap usage and capacity with timestamps
  • -Xloggc:filename - Prints GC info to a log file

The impact of debug information is in direct proportion to the selected options. In a production environment that you are trying to learn more about the behavior of garbage collection I would suggest enabling verbose:gc as well as Xloggc:filename. With these two options, the JVM will log each garbage collection to a log file of your choosing. The other options that increase overhead, but help your tuning ability are XX:+PrintGCDetails, XX:PrintGCTimeStamps, and XX:PrintHeapAtGC. With these options, you will know when garbage collection occurs (not expensive) and the state of the heap before and after a garbage collection (a little more expensive.) Looking at the output of this call yields the following results, just a snapshot of launching JBoss with the default configuration and the following options enabled somewhere in your run.bat/sh file:

set JAVA_OPTS=%JAVA_OPTS% -verbose:gc -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC

A snippet from gc.log shows the following:

280.677: [GC {Heap before GC invocations=39:
Heap
 def new generation  total 9152K, used 9151K [0x10010000, 0x109f0000, 0x12770000)
 eden space 8192K, 99% used [0x10010000, 0x1080fff0, 0x10810000)
 from space 960K, 100% used [0x10900000, 0x109f0000, 0x109f0000)
 to  space 960K,  0% used [0x10810000, 0x10810000, 0x10900000)
 tenured generation  total 121024K, used 27200K [0x12770000, 0x19da0000, 0x30010000)
  the space 121024K, 22% used [0x12770000, 0x142003d8, 0x14200400, 0x19da0000)
 compacting perm gen total 17664K, used 17618K [0x30010000, 0x31150000, 0x34010000)
  the space 17664K, 99% used [0x30010000, 0x31144910, 0x31144a00, 0x31150000)
280.677: [DefNew: 9151K->960K(9152K), 0.0215941 secs] 36352K->29413K(130176K) Heap after GC invocations=40:
Heap
 def new generation  total 9152K, used 960K [0x10010000, 0x109f0000, 0x12770000)
 eden space 8192K,  0% used [0x10010000, 0x10010000, 0x10810000)
 from space 960K, 100% used [0x10810000, 0x10900000, 0x10900000)
 to  space 960K,  0% used [0x10900000, 0x10900000, 0x109f0000)
 tenured generation  total 121024K, used 28453K [0x12770000, 0x19da0000, 0x30010000)
  the space 121024K, 23% used [0x12770000, 0x14339560, 0x14339600, 0x19da0000)
 compacting perm gen total 17664K, used 17618K [0x30010000, 0x31150000, 0x34010000)
  the space 17664K, 99% used [0x30010000, 0x31144910, 0x31144a00, 0x31150000)
} , 0.0217424 secs]

In this snapshot, you can see that at 280.677 seconds a minor collection was run. In that collection the new generation changed from 9151K to 960K, eden went from 99% used to 0% used, the from and to spaces remained the same while the old generation (the tenured generation) went from 27200K to 28453K.

Analyzing the business impact of this (what it really means applied to our application), the eden partition of the young generation cleared itself well while 1253K was moved through the heap from the young generation to the old generation. Most of the eden space was freed, meaning short-lived objects (which is a good thing), but at the same time the survivor spaces were filled and data was promoted to the old generation before it could be collected. Looking at this heap, being in its default configuration, eden and its survivor spaces are sized too small. In a better configuration, the surviving data would be moved to the first and second survivor spaces, and never make their way to the old generation.

Another aspect to this is the analysis of what was happening in the system when this occurred. In this case, I started JBoss and then closed it a few minutes later. There is a chance that it needs the data that was allocated in the heap, but because of the timestamp I doubt it; this snapshot was taken during a relatively idle mode. Under stress this could be acceptable, but during an idle time, it proves that we are unintelligently filling the old generation.

It is important to recall the reason for having a young generation in the first place. It can be demonstrated that most objects are created and destroyed relatively quickly, therefore we want to "inexpensively" create and destroy these objects in the heap before we have to run a "stop-the-world" major garbage collection.

I built a set of three classes that can read the results of a garbage collection log file and turn it into an XML file that you can import into your applications. It captures the important data and then aggregates the data into summary form for better business value interpretation. Listings 1 – 3 show the source code for these classes; listing 4 shows the result of running the HeapAgent against a garbage collection log file.

Listing 1. HeapSnapshot.java

package com.javasrc.tuning.agent.heap;

import java.io.*;
import java.util.*;
import org.jdom.*;

public class HeapSnapshot implements java.io.Serializable
{
  private long newGeneration;
  private long newGenerationUsed;
  private long eden;
  private long edenUsed;
  private long from;
  private long fromUsed;
  private long to;
  private long toUsed;
  private long oldGeneration;
  private long oldGenerationUsed;
  private long permGeneration;
  private long permGenerationUsed;


  public HeapSnapshot( BufferedReader br )
  {
    try
    {
      String line = br.readLine();

      // Handle the new generation
      int index = line.indexOf( "total" );
      if( index != -1 )
      {
        newGeneration = new Long( line.substring( index + 6, line.indexOf( 'K', index + 6 ) ) ).longValue();
        index = line.indexOf( "used" );
        newGenerationUsed = new Long( line.substring( index + 5, line.indexOf( 'K', index + 5 ) ) ).longValue();
      }

      // Handle Eden
      line = br.readLine();
      index = line.indexOf( "eden space" );
      if( index != -1 )
      {
        int kIndex = line.indexOf( 'K', index + 11 );
        eden = new Long( line.substring( index + 11, kIndex ) ).longValue();
        String percentString = line.substring( kIndex + 2, line.indexOf( '%', kIndex + 2 ) );
        int percent = new Integer( percentString.trim() ).intValue();
        //int percent = new Integer( line.substring( kIndex + 2, line.indexOf( '%', kIndex + 2 ) ) ).intValue();
        edenUsed = ( long )( ( double )percent / 100.0d * ( double )eden );
      }

      // Handle from space
      line = br.readLine();
      index = line.indexOf( "from space" );
      if( index != -1 )
      {
        int kIndex = line.indexOf( 'K', index + 11 );
        from = new Long( line.substring( index + 11, kIndex ) ).longValue();
        String percentString = line.substring( kIndex + 2, line.indexOf( '%', kIndex + 2 ) );
        int percent = new Integer( percentString.trim() ).intValue();
        fromUsed = ( long )( ( double )percent / 100.0d * ( double )from );
      }

      // Handle to space
      line = br.readLine();
      index = line.indexOf( "to  space" );
      if( index != -1 )
      {
        int kIndex = line.indexOf( 'K', index + 11 );
        to = new Long( line.substring( index + 11, kIndex ) ).longValue();
        String percentString = line.substring( kIndex + 2, line.indexOf( '%', kIndex + 2 ) );
        int percent = new Integer( percentString.trim() ).intValue();
        toUsed = ( long )( ( double )percent / 100.0d * ( double )to );
      }

      // Handle old generation: tenured generation
      line = br.readLine();
      index = line.indexOf( "total" );
      if( index != -1 )
      {
        oldGeneration = new Long( line.substring( index + 6, line.indexOf( 'K', index + 6 ) ) ).longValue();
        index = line.indexOf( "used" );
        oldGenerationUsed = new Long( line.substring( index + 5, line.indexOf( 'K', index + 5 ) ) ).longValue();
      }
      line = br.readLine();

      // Handle perm space
      line = br.readLine();
      index = line.indexOf( "total" );
      if( index != -1 )
      {
        permGeneration = new Long( line.substring( index + 6, line.indexOf( 'K', index + 6 ) ) ).longValue();
        index = line.indexOf( "used" );
        permGenerationUsed = new Long( line.substring( index + 5, line.indexOf( 'K', index + 5 ) ) ).longValue();
      }
      line = br.readLine();
    }
    catch( Exception e )
    {
      e.printStackTrace();
    }
  }

  public long getNewGeneration()
  {
    return this.newGeneration;
  }

  public long getNewGenerationUsed()
  {
    return this.newGenerationUsed;
  }

  public long getEden()
  {
    return this.eden;
  }

  public long getEdenUsed()
  {
    return this.edenUsed;
  }

  public long getFromSpace()
  {
    return this.from;
  }

  public long getFromSpaceUsed()
  {
    return this.fromUsed;
  }

  public long getToSpace()
  {
    return this.to;
  }

  public long getToSpaceUsed()
  {
    return this.toUsed;
  }

  public long getOldGeneration()
  {
    return this.oldGeneration;
  }

  public long getOldGenerationUsed()
  {
    return this.oldGenerationUsed;
  }

  public long getPermGeneration()
  {
    return this.permGeneration;
  }

  public long getPermGenerationUsed()
  {
    return this.permGenerationUsed;
  }

  /**
   * Returns the heap information as an XML Element
   */
  public Element toXML( String nodeName )
  {
    Element heap = new Element( nodeName );

    // Handle the young generation
    Element youngGenerationElement = new Element( "young-generation" );
    youngGenerationElement.setAttribute( "size", Long.toString( newGeneration ) );
    youngGenerationElement.setAttribute( "used", Long.toString( newGenerationUsed ) );

    // Handle young: eden
    Element edenElement = new Element( "eden" );
    edenElement.setAttribute( "size", Long.toString( eden ) );
    edenElement.setAttribute( "used", Long.toString( edenUsed ) );
    youngGenerationElement.addContent( edenElement );

    // Handle young: ss1 (from-space)
    Element fromElement = new Element( "from-survivor-space" );
    fromElement.setAttribute( "size", Long.toString( from ) );
    fromElement.setAttribute( "used", Long.toString( fromUsed ) );
    youngGenerationElement.addContent( fromElement );

    // Handle young: ss2 (to-space)
    Element toElement = new Element( "to-survivor-space" );
    toElement.setAttribute( "size", Long.toString( to ) );
    toElement.setAttribute( "used", Long.toString( toUsed ) );
    youngGenerationElement.addContent( toElement );

    heap.addContent( youngGenerationElement );

    // Handle the old generation
    Element oldGenerationElement = new Element( "old-generation" );
    oldGenerationElement.setAttribute( "size", Long.toString( oldGeneration ) );
    oldGenerationElement.setAttribute( "used", Long.toString( oldGenerationUsed ) );
    heap.addContent( oldGenerationElement );

    // Handle the perm generation
    Element permGenerationElement = new Element( "permanent-generation" );
    permGenerationElement.setAttribute( "size", Long.toString( permGeneration ) );
    permGenerationElement.setAttribute( "used", Long.toString( permGenerationUsed ) );
    heap.addContent( permGenerationElement );

    // Return our XML
    return heap;
  }

  public Element toXML()
  {
    return toXML( "heap" );
  }
}

Listing 2. GarbageCollection.java

package com.javasrc.tuning.agent.heap;

import java.io.*;
import java.util.*;
import org.jdom.*;

public class GarbageCollection implements java.io.Serializable
{
  public static final int MINOR = 0;
  public static final int MAJOR = 1;

  private double time;
  private int collectionType;
  private int invocationCount;
  private HeapSnapshot ssBefore;
  private HeapSnapshot ssAfter;
  private double collectionDuration;
  private boolean success = false;

  public GarbageCollection( BufferedReader br )
  {
    try
    {
      // Handle the header
      String line = br.readLine();
      if( line == null )
      {
        // End of file
        return;
      }
      time = new Double( line.substring( 0, line.indexOf( ':' ) ) ).doubleValue();
      String collectionStr = line.substring( line.indexOf( '[' ) + 1, line.indexOf( '{' ) );
      if( collectionStr.startsWith( "Full GC" ) )
      {
        this.collectionType = MAJOR;
      }
      else
      {
        this.collectionType = MINOR;
      }
      this.invocationCount = new Integer( line.substring( line.indexOf( "invocations=" ) + 12,
                                line.lastIndexOf( ":" ) ) ).intValue();

      // Skip over the "Heap" line
      line = br.readLine();

      // Handle the before snapshot
      ssBefore = new HeapSnapshot( br );

      // Handle the summary
      line = br.readLine();
      line = br.readLine();

      // Handle the after snapshot
      ssAfter = new HeapSnapshot( br );

      // Handle the tail
      line = br.readLine();
      int startIndex = line.indexOf( ", " ) + 2;
      this.collectionDuration = new Double( line.substring( startIndex, line.indexOf( " ", startIndex ) ) ).doubleValue();

      this.success = true;
    }
    catch( Exception e )
    {
      e.printStackTrace();
    }
  }

  public boolean isMajor()
  {
    return this.collectionType == GarbageCollection.MAJOR;
  }

  public boolean isSuccess()
  {
    return this.success;
  }

  public Element toXML()
  {
    Element gcElement = new Element( "garbage-collection" );
    gcElement.setAttribute( "time", Double.toString( time ) );
    if( isMajor() )
    {
      gcElement.setAttribute( "type", "major" );
    }
    else
    {
      gcElement.setAttribute( "type", "minor" );
    }
    gcElement.setAttribute( "duration", Double.toString( collectionDuration ) );
    gcElement.setAttribute( "invocation-count", Integer.toString( invocationCount ) );
    gcElement.setAttribute( "delta-young-generation", Long.toString( ssAfter.getNewGenerationUsed() - ssBefore.getNewGenerationUsed() ) );
    gcElement.setAttribute( "delta-eden", Long.toString( ssAfter.getEdenUsed() - ssBefore.getEdenUsed() ) );
    gcElement.setAttribute( "delta-from-space", Long.toString( ssAfter.getFromSpaceUsed() - ssBefore.getFromSpaceUsed() ) );
    gcElement.setAttribute( "delta-to-space", Long.toString( ssAfter.getToSpaceUsed() - ssBefore.getToSpaceUsed() ) );
    gcElement.setAttribute( "delta-old-generation", Long.toString( ssAfter.getOldGenerationUsed() - ssBefore.getOldGenerationUsed() ) );
    gcElement.setAttribute( "delta-perm-generation", Long.toString( ssAfter.getPermGenerationUsed() - ssBefore.getPermGenerationUsed() ) );
    gcElement.addContent( ssBefore.toXML( "heap-before" ) );
    gcElement.addContent( ssAfter.toXML( "heap-after" ) );
    return gcElement;
  }

}

Listing 3. HeapAgent.java

package com.javasrc.tuning.agent.heap;

import java.io.*;
import java.util.*;

import org.jdom.*;
import org.jdom.output.*;

public class HeapAgent
{
  private String filename;
  private List gcs = new ArrayList();

  public HeapAgent( String filename )
  {
    try
    {
      this.filename = filename;
      BufferedReader br = new BufferedReader( new FileReader( filename ) );
      GarbageCollection gc = new GarbageCollection( br );
      boolean success = gc.isSuccess();
      while( success )
      {
        this.gcs.add( gc );
        gc = new GarbageCollection( br );
        success = gc.isSuccess();
      }
    }
    catch( Exception e )
    {
      e.printStackTrace();
    }
  }

  public Element toXML()
  {
    Element gcsElement = new Element( "garbage-collections" );
    for( Iterator i=this.gcs.iterator(); i.hasNext(); )
    {
      GarbageCollection gc = ( GarbageCollection )i.next();
      gcsElement.addContent( gc.toXML() );
    }
    return gcsElement;
  }

  public static void main( String[] args )
  {
    if( args.length == 0 )
    {
      System.out.println( "Usage: HeapAgent gc-log-filename" );
      System.exit( 0 );
    }
    try
    {
      HeapAgent ha = new HeapAgent( args[ 0 ] );
      XMLOutputter out = new XMLOutputter();
      out.output( ha.toXML(), System.out );
    }
    catch( Exception e )
    {
      e.printStackTrace();
    }
  }
}

Listing 4. gc.log -> XML output

<garbage-collections>
    <garbage-collection time="0.0" type="minor" duration="0.0156922" invocation-count="0" delta-young-generation="-7389" delta-eden="-8046" delta-from-space="729" delta-to-space="0" delta-old-generation="0" delta-perm-generation="0">
  <heap-before>
   <young-generation size="9088" used="8127">
     <eden size="8128" used="8046" /><from-survivor-space size="960" used="0" />
     <to-survivor-space size="960" used="0" />
   </young-generation><old-generation size="121024" used="0" />
   <permanent-generation size="4096" used="3755" />
  </heap-before>
  <heap-after> 
   <young-generation size="9088" used="738"><eden size="8128" used="0" />
     <from-survivor-space size="960" used="729" />
     <to-survivor-space size="960" used="0" />
   </young-generation>
   <old-generation size="121024" used="0" />
  <permanent-generation size="4096" used="3755" />
  </heap-after>
  </garbage-collection>
  <garbage-collection time="2.66" type="minor" duration="0.0162107" invocation-count="1" delta-young-generation="-8132" delta-eden="-8046" delta-from-space="0" delta-to-space="0" delta-old-generation="657" delta-perm-generation="0">
  ...
  </garbage-collection>
</garbage-collections>

Now you can take this XML file and import it into your own analysis engine;. It provides aggregated information that you can draw conclusions from:

  • The type of collection occurred
  • The duration of the collection
  • The time of the collection (to determine frequency)
  • The changes in each part of the heap (eden, from space, to space, old generation, permanent generation)

The key to proper analysis of garbage collection is observing the frequency of garbage collections and the duration of each collection as it occurs. The goal is to maintain a steady state of minor collections that run very quickly and minimize occurrences of major collections. You also want to measure the total deltas of the collections and compare the range of the deltas with the total size of heap: if you have a range that is in significant proportion to the total size of the heap (usually the result of a major collection) then you want to increase the sizes of the young generation allocations to increase occurrences of minor collections.

To summarize, you want to maximize quick minor collections and minimize major collections.

Summary

In this series I am relating information about engagements that I have been on over the past nine months tuning J2EE enterprise applications. Thus far we have looked at the most common problem that I have seen: misconfigured heaps. I hope that after reading about how the heap works that you will be better equipped to understand and handle problems as they occur.