How to read the Garbage Collector output (for Sun JVM)

[desiree_matas]

As already mentioned in the first weblog (How to read the Garbage Collector output (for IBM JVM)) of this series, there are lots of applications to make the output of the *–verbose:gc* parameter easy to read, but still it may be useful to have a general idea of the meaning of the "numbers" in the gc log file... The language to describe the memory areas for the Sun JVM is slightly different to the one used for IBM JVM. Also the parameters are quite different, and they cannot be mixed up! As we can see in the following diagram, there is a *heap area *(divided in *young *and *tenured* areas) and a *perm* area. The most important parameters to define the different areas are indicated too: Besides that, the output of the *-verbose:gc *parameter may be quite different depending on the additional parameters we set. For example:

• *-XX:+PrintGCTimeStamps* will print a time stamp before each collection line.
• *-XX:+PrintGCDetails *will print more details at garbage collection.  h3. Minor Garbage Collection: As per the description provided by Sun, the minor collection output created by parameters *-verbosegc -XX:+PrintGCDetails *looks like:
  
  

  *+[GC [ secs]+*

  + +

  Let’s see a more real example:

  

  *83.304: *This is the start time of the collection since the VM started.

  *GC* indicates that this is a minor garbage collector. If the executed collection is a global one, then we will see *FullGC* instead of GC.

  

  *DefNew:* This is the *collector type *used for the minor collection. The most common values here are DefNew and ParNew. This depends again on the parameters we set for the JVM, for example *-XX:+UseParNewGC *(for the Parallel New garbage collector).

  *890K: *This value refers to the size of the young generation which is allocated before GC takes place.

  *64K: *This value is the young area allocated after GC (ideally, it should be smaller).

  *960K:* This value is the maximum young area available (Eden + one of the survivor areas). *0.004494 secs: T*his is the pause time for the minor collection. *890K: *This is the occupancy of the entire heap before GC.

  *217K: * This is the occupancy of the entire heap after GC. *5056K: *Maximum heap available (max heap – one of the survivor areas).

  *0.004606 secs: *Pause time for the entire garbage collection.     h3. Full Garbage Collection: As we have alredy mentioned, when a full garbage collection takes place, the tag *Full GC *appears in the GC output, as you can see in the following example:

   

  *3074.315:* This is the start time of the collection since the VM started.

  

  *1738752K: *This is the size of the tenured area allocated before the GC.

  *1738751K: *This is the size of the tenured area allocated after GC (this should be a smaller value).

  **1738752K: This is the maximum tenured area available (MaxHeap – Young).

  

  *2007551K: *This is the heap allocated before GC.

  *1773223K:* This is the heap allocated after GC. *2007552K: *This is the maximum available heap (MaxHeap – one of the survivor areas).

  

  *246227K: * This is the perm area allocated before GC. *246227K:*  This is the perm area allocated after GC.