Analyzing Garbage Collection Log file using GC Viewer

This article is about analysing GC log using GC Viewer.
We can download the software from this link

http://www.tagtraum.com/gcviewer-download.html

In order to capture the GC information we need to start Weblogic Server by adding the following JAVA Option
set MEM_ARGS=-Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log

If you see Out Of Memory errors in you server logs, you should be ready with GC Viewer to anylyze the gc log file.
Out Of Memory occurs due to the exhaustion of the heap. This can be due to an overload condition or programming negligence.If its due to an overload condition, we need to increase the heap size depending on the load. If its due to programming errors, we need to take a deeper look. Take heapdumps and analyze using Memory Analyzer tools.

This has been described in the following article

TROUBLESHOOTING OUT OF MEMORY ERRORS IN WEBLOGIC USING ECLIPSE MEMORY ANANLYSER

There are two types of garbage collection, major and minor. In minor garbage collection only young generation is cleared where as major garbage collection cleans the tenured and the young generation.

e.g.

[GC [PSYoungGen: 40951K->3360K(42432K)] 564334K->526886K(566720K), 0.0720524 secs]
2274304.031: [GC [PSYoungGen: 41632K->3584K(42496K)] 565158K->527274K(566784K), 0.0665242 secs]
2274663.654: [GC [PSYoungGen: 41920K->3296K(42560K)] 565610K->527134K(566848K), 0.0636812 secs]
2275023.726: [GC [PSYoungGen: 41696K->3746K(42560K)] 565534K->527728K(566848K), 0.0642125 secs]
2275428.250: [GC [PSYoungGen: 42210K->3424K(42752K)] 566192K->527574K(567040K), 0.0637819 secs]
2275428.314: [Full GC [PSYoungGen: 3424K->2828K(42752K)] [PSOldGen: 524150K->524287K(524288K)] 527574K->527116K(567040K) [PSPermGen: 88758K->88758K(90112K)], 11.1667328 secs]
2275743.907: [Full GC [PSYoungGen: 38528K->5936K(42752K)] [PSOldGen: 524287K->524287K(524288K)] 562815K->530224K(567040K) [PSPermGen: 88891K->88891K(90112K)], 11.0188252 secs]
2276067.615: [Full GC [PSYoungGen: 38528K->5349K(42752K)] [PSOldGen: 524287K->524287K(524288K)] 562815K->529637K(567040K) [PSPermGen: 88956K->88956K(90112K)], 11.0896643 secs]
2276404.096: [Full GC [PSYoungGen: 38420K->0K(42752K)] [PSOldGen: 524287K->517865K(524288K)] 562707K->517865K(567040K) [PSPermGen: 88987K->88611K(90112K)], 14.6099121 secs]
2276764.208: [GC [PSYoungGen: 38350K->1890K(42752K)] 556215K->519755K(567040K), 0.0890990 secs]
2277126.468: [GC [PSYoungGen: 40482K->1932K(40640K)] 558347K->519797K(564928K), 0.0915124 secs]

Line starting with GC is minor GC and the line starting with Full GC is major GC.

If we take a closer look at a single Full GC

2275428.314: [Full GC [PSYoungGen: 3424K->2828K(42752K)] [PSOldGen: 524150K->524287K(524288K)] 527574K->527116K(567040K) [PSPermGen: 88758K->88758K(90112K)], 11.1667328 secs]

Heap in use in young generation befor GC is 3424K and after is 2828K, whereas the total heap is 42752K.
Similarly for tenured generation heap usage before GC is 88758K and after GC it is 88758K, and the time taken is 11.1667328 secs. The timestamp helps us keep an eye on the frequency of Garbage collection. From the frequency we can deduce whether its a leak or not.

If we see FUll GC happening continuously, its a leak and you can expect an Out Of Memory.

4364435.019: [Full GC [PSYoungGen: 43776K->42364K(48256K)] [PSOldGen: 524288K->524288K(524288K)] 568064K->566652K(572544K) [PSPermGen: 88381K->88381K(90112K)], 12.2471219 secs]
4371857.025: [Full GC [PSYoungGen: 43776K->43776K(48256K)] [PSOldGen: 524288K->524288K(524288K)] 568064K->568064K(572544K) [PSPermGen: 88381K->88381K(90112K)], 12.5911727 secs]
4371869.617: [Full GC [PSYoungGen: 43776K->42364K(48256K)] [PSOldGen: 524288K->524288K(524288K)] 568064K->566652K(572544K) [PSPermGen: 88381K->88381K(90112K)], 12.9294566 secs]
4379280.165: [Full GC [PSYoungGen: 43776K->43776K(48256K)] [PSOldGen: 524288K->524288K(524288K)] 568064K->568064K(572544K) [PSPermGen: 88384K->88384K(90112K)], 13.1517479 secs]
4379293.318: [Full GC [PSYoungGen: 43776K->42364K(48256K)] [PSOldGen: 524288K->524288K(524288K)] 568064K->566652K(572544K) [PSPermGen: 88384K->88384K(90112K)], 13.0984445 secs]
4386653.185: [Full GC [PSYoungGen: 43776K->43776K(48256K)] [PSOldGen: 524288K->524288K(524288K)] 568064K->568064K(572544K) [PSPermGen: 88384K->88384K(90112K)], 13.1889873 secs]
4386666.375: [Full GC [PSYoungGen: 43776K->42364K(48256K)] [PSOldGen: 524288K->524288K(524288K)] 568064K->566652K(572544K) [PSPermGen: 88384K->88384K(90112K)], 13.3019379 secs]

If the heap usage keeps on increasing with time even after FUll GC,it is a memory leak.
In GCViewer it should look something like this

The other thing that we look for is Throughput.(Click the summary tab)
It should ideally be above 97%.

In another article we shall discuss the GC Strategies and Garbage Collector types.
Its pretty late and I need to catch some sleep 🙂