Decipher Garbage Collection Log

Refer to Garbage Collection index page at the following URL:
http://mylearningcafe.blogspot.in/2015/05/garbage-collection-gc.html

Today lets look at analyzing the garbage collection logs.

Why are Garbage Collection (GC) logs important?
Via GC Logs, one can see the usage of the heap and can look at improving the same.
This can help the application throughput immensely.

How does one print GC logs in an application?
We have various flags for GC. They are listed below.

-XX:+PrintGC OR -verbose:GC
The most basic logging. It prints a line for every young GC and every full GC.

Whats young GC and Full GC?
Refer following URL: http://mylearningcafe.blogspot.in/2014/02/serial-vs-parallel-gc.html

The basic GC log will look like:

[GC heap_before_GC -> heap_after_GC (heap_capacity), time_taken_to_clear_heap]
[Full GC heap_before_Full_GC -> heap_after_Full_GC (heap_capacity), time_taken_to_clear_heap]

e.g.

[GC 78786K->32K(168896K), 0.0386790 secs]
[Full GC 1765598K->628983K(1864192K), 3.0560280 secs]

The above implies:

Young GC:

• Heap Memory occupied before GC: 78786K
• Heap Memory after GC: 32K
• Heap Capacity: 168896K
• Time taken to clear heap: 0.0386790 sec

Full GC:

• Heap Memory occupied before GC: 1765598K
• Heap Memory after GC: 628983K
• Heap Capacity: 1864192K
• Time taken to clear heap: 3.0560280 sec

As mentioned, the above is simple GC logging.

-XX:+PrintGCDetails
This parameter gives detailed logging.

[GC [PSYoungGen: young_heap_before_GC -> young_heap_after_GC(young_heap_capacity)] total_heap_before_GC -> total_heap_after_GC (total_heap_capacity), time_taken_to_clear_heap]

[GC [PSYoungGen: 78786K->32K(168896K)] 1844377K->1765630K(2033088K), 0.0386790 secs]

Above is Young GC output in detailed format.

[Full GC [PSYoungGen: young_heap_before_GC -> young_heap_after_GC(young_heap_capacity)] [PSOldGen: Old_heap_before_GC -> Old_heap_after_GC(Old_heap_capacity)] total_heap_before_GC -> total_heap_after_GC (total_heap_capacity) [PSPermGen: Perm_heap_before_GC -> Perm_heap_after_GC(Perm_heap_capacity)], time_taken_to_clear_heap]

[Full GC [PSYoungGen: 32K->0K(168896K)] [PSOldGen: 1765598K->628983K(1864192K)] 1765630K->628983K(2033088K) [PSPermGen: 82932K->82932K(83328K)], 3.0560280 secs]

Above is Full GC output in detailed format.

If one captures this data and wants to plot a chart, you will realize that the date/time is missing.
For the same, lets look at another parameter below.

-XX:+PrintGCTimeStamps and -XX:+PrintGCDateStamps

These paramaters add the date and time to the above mentioned logs.

-XX:+PrintGCTimeStamps will give:

0,185:[GC [PSYoungGen: 78786K->32K(168896K)] 1844377K->1765630K(2033088K), 0.0386790 secs]

Here, 0.185 is the timestamp reflecting the real time passed in seconds since JVM started.

and

-XX:+PrintGCDateStamps will give:
2015-03-03T12:04:17.101-0010:[GC [PSYoungGen: 78786K->32K(168896K)] 1844377K->1765630K(2033088K), 0.0386790 secs]

reflects the full date and time.

Refer to Garbage Collection index page at the following URL:
http://mylearningcafe.blogspot.in/2015/05/garbage-collection-gc.html