Analysing Garbage Collector logs with IBM Pattern Modeling and Analysis Tool

Steps

1)      Add the following GC parameters to your program

-Xloggc:C:/codelatest1/gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

The GC log will be available at given path : e.g: “C:/ix3codelatest1”

0.951: [GC [PSYoungGen: 65600K->4770K(76480K)] 65600K->4778K(251264K), 0.0033514 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

1.864: [GC [PSYoungGen: 70370K->7520K(76480K)] 70378K->7536K(251264K), 0.0201201 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

2.682: [GC [PSYoungGen: 73120K->10862K(76480K)] 73136K->12362K(251264K), 0.0103230 secs] [Times: user=0.08 sys=0.00, real=0.01 secs]

3.079: [GC [PSYoungGen: 76462K->10865K(142080K)] 77962K->15033K(316864K), 0.0086661 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

12.582: [GC [PSYoungGen: 142065K->10865K(142080K)] 146233K->23858K(316864K), 0.0140113 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

13.182: [GC [PSYoungGen: 142065K->21330K(144896K)] 155058K->34324K(319680K), 0.0156760 secs] [Times: user=0.06 sys=0.02, real=0.01 secs]

15.334: [GC [PSYoungGen: 144082K->23396K(146176K)] 157076K->40923K(320960K), 0.0177733 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

16.214: [GC [PSYoungGen: 146148K->24253K(139648K)] 163675K->44046K(314432K), 0.0144303 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

16.982: [GC [PSYoungGen: 135357K->14211K(142912K)] 155150K->46556K(317696K), 0.0163956 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

17.577: [GC [PSYoungGen: 125315K->6609K(141440K)] 157660K->48635K(316224K), 0.0112545 secs] [Times: user=0.03 sys=0.02, real=0.01 secs]

18.330: [GC [PSYoungGen: 119185K->5550K(142912K)] 161211K->52764K(317696K), 0.0080298 secs] [Times: user=0.08 sys=0.00, real=0.01 secs]

18.383: [GC [PSYoungGen: 118126K->32K(142976K)] 165340K->51356K(317760K), 0.0039696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

18.434: [GC [PSYoungGen: 112672K->64K(112704K)] 163996K->51388K(287488K), 0.0016584 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

18.484: [GC [PSYoungGen: 112704K->32K(143616K)] 164028K->51372K(318400K), 0.0018724 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

18.782: [GC [PSYoungGen: 112416K->2650K(115072K)] 163756K->53991K(289856K), 0.0033702 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

19.697: [GC [PSYoungGen: 115034K->4080K(143872K)] 166375K->57334K(318656K), 0.0052543 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

20.514: [GC [PSYoungGen: 117680K->3504K(142656K)] 170934K->59344K(317440K), 0.0052851 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

.

.

.

.

.

In order to get a meaningful picture of the GC log , IBM Pattern Modeling and Analysis Tool can be used.

“IBM Pattern Modeling and Analysis Tool  - (PMAT) analyzes verbose GC traces by parsing the traces and building pattern models. PMAT recommends key configurations by executing a diagnosis engine and pattern modeling algorithm. If there are any errors related with Java heap exhaustion or fragmentation in the verbose GC trace, PMAT can diagnose the root cause of failures. PMAT provides rich chart features that graphically display Java heap usage.”

“The following features are included:

• GC analysis
• GC table view
• Allocation failure summary
• GC usage summary
• GC duration summary
• GC graph view
• GC pattern analysis
• Zoom in/out/selection/center of chart view
• Option of changing chart color.”

More details available here

The tool can also parse Java HotSpot garbage collector traces, including the following:

• Serial collector
• Throughput/parallel collector
• Concurrent collector
• Incremental/train collector

To run IBM – PMAT ,

========================================================

Download the jar from here

Click file and the  open the GC log.

==========================================================

It will provide details about Out of Memory Errors , GC completed , Overhead etc …