Xml and More: Understanding Garbage Collector Output of Hotspot VM

If garbage collection becomes a bottleneck, you will most likely have to customize the total heap size as well as the sizes of the individual generations. Before any tuning, you need to check the verbose garbage collector output and then explore the sensitivity of your individual performance metric to the garbage collector parameters.

In this article, we are going to examine the verbose output of garbage collector from Hotspot VM. For all the needed background, please read [1-6].

Hotspot VM Options

Our test case used the following space-related settings:

-server -XX:+UseParallelGC -Xms2048m -Xmx2048m -XX:PermSize=384m -XX:MaxPermSize=384m -XX:SurvivorRatio=10

The command line option -verbose:gc causes information about the heap and garbage collection to be printed at each collection. Our test case included the following report-related settings:

-Xloggc:/<path-to-output>/gc_0.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintReferenceGC

Note that there is little additional overhead in the HotSpot VM to report garbage collection data. In fact, the overhead is so small it is recommended to collect garbage collection data in production environments^[7].

Analysis of Heap Spaces

At the bottom of gc_0.log file, you can find the following heap information:

Heap
 PSYoungGen      total 642048K, used 511911K [0x00000007d5400000, 0x0000000800000000, 0x0000000800000000)
  eden space 583680K, 81% used [0x00000007d5400000,0x00000007f2737e78,0x00000007f8e00000)
  from space 58368K, 57% used [0x00000007f8e00000,0x00000007faeb1ed0,0x00000007fc700000)
  to   space 58368K, 0% used [0x00000007fc700000,0x00000007fc700000,0x0000000800000000)
 ParOldGen       total 1398784K, used 728598K [0x000000077fe00000, 0x00000007d5400000, 0x00000007d5400000)
  object space 1398784K, 52% used [0x000000077fe00000,0x00000007ac585ad0,0x00000007d5400000)
 PSPermGen       total 393216K, used 229261K [0x0000000767e00000, 0x000000077fe00000, 0x000000077fe00000)
  object space 393216K, 58% used [0x0000000767e00000,0x0000000775de3728,0x000000077fe00000)

Because of our heap size settings:

-Xms2048m -Xmx2048m

the total heap space should be 2048MB which is confirmed from the output:

  Heap Total = PSYoungGen Total + ParOldGen Total 

           = 642048K + 1398784K

           = 2048M 

Our settings for Permanent Generation are:

-XX:PermSize=384m -XX:MaxPermSize=384m

which is confirmed from the output:

  PSPermGen       total 393216K

Finally, we have set the survivor ratio to be 10, this is also confirmed by the output:

eden space /from space = 583680K/58368K = 10

Note that survivor space consists of two ping-pong buffers (i.e., from space and to space).

Full Garbage Collection

In the HotSpot VM, the default behavior on a full garbage collection is to garbage collect the young generation, old generation, and permanent generation spaces. In addition, the old generation and permanent generation spaces are compacted along with any live objects in young generation space being promoted to the old generation space. Hence, at the end of a full garbage collection, young generation space is empty, and old generation and permanent generation spaces are compacted and hold only live objects.

828.560: [Full GC828.930:

  [SoftReference, 0 refs, 0.0000060 
secs]828.930:

  [WeakReference, 30056 refs, 0.0048320 secs]828.935:

  [FinalReference, 4333 refs, 0.0400380 secs]828.975:

  [PhantomReference, 
28 refs, 0.0000130 secs]828.975:

  [JNI Weak Reference, 0.0000090 secs]

  [PSYoungGen: 41219K->0K(651136K)]

  [ParOldGen: 
1360914K->639030K(1398784K)]

  1402134K->639030K(2049920K)

  [PSPermGen: 228218K->226531K(393216K)], 2.6372320 secs]

  [Times: 
user=12.85 sys=0.07, real=2.64 secs] 

There are three pieces of GC information in GC output line:

Time
Buffer Size
Count

All Full GC output lines are timestamped. For example, numbers like 828.560 and 828.930 are elapsed time in seconds since server started. There are also three measurement times (i.e., user, system and real ) at the end of line. User time (i.e., 12.85) is total user CPU time used by the garbage collector which includes all GC task threads (note that we have eight GC task threads in our case). System time (i.e., 0.07) is the CPU time used by the operating system on behalf of the garbage collector. Real time (i.e., 2.64 secs) is the wall clock time or elapsed time used by the garbage collector.

To look at space reclaimed after a Full GC, we will use Old Generation space as an example. The numbers before and after the arrow (e.g., 1360914K->639030K from the ParOldGen section) indicate the combined size of live objects before and after garbage collection, respectively. The next number in parentheses (e.g., (1398784K) ) is the committed size of the Old Generation space.

As for the counts, it requires no explanation. They are reference counts of objects in different categories: softly referenced, weakly referenced, etc.

Minor Garbage Collection

A minor GC collects the young generation space. The young generation is divided into 3 spaces:

Eden-space
From-space
To-space

After a minor collection completes, both eden and the from-survivor space are empty. However, these details are not shown in the following sample output line from a Minor GC.

828.465: [GC828.543:

  [SoftReference, 0 refs, 0.0000060 secs]828.543:

  [WeakReference, 5399 refs, 0.0008020 secs]828.544:

  [FinalReference, 1366
 refs, 0.0079250 secs]828.552:

  [PhantomReference, 0 refs, 0.0000050 
secs]828.552:

  [JNI Weak Reference, 0.0000030 secs]

  [PSYoungGen: 
646557K->41219K(651136K)]

  1974687K->1402134K(2049920K), 0.0947580 
secs]

  [Times: user=0.53 sys=0.02, real=0.09 secs] 

Final Words

The heap size settings (including -XX:SurvivorRatio=10) we have chosen here turned out to be a bad choice. So, don't just copy and paste for your own environment.

Finally, to tune for throughput or latency, you tend to set: