How do I analyze Java garbage collection logging?

Environment

• Java
• OpenJDK
• Oracle JDK
• IBM JDK
• HP JDK

Issue

How to analyze Java garbage collection logging?

Resolution

Disclaimer :
Links contained herein to external website(s) are provided for convenience only. Red Hat has not reviewed the links and is not responsible for the content or its availability. The inclusion of any link to an external website does not imply endorsement by Red Hat of the website or their entities, products or services. You agree that Red Hat is not responsible or liable for any loss or expenses that may result due to your use of (or reliance on) the external site or content.

OpenJDK / Sun JDK

There are a couple of tools available

• The latest version of Content from mgm3746.github.io is not included.garbagecat will parse Java garbage collection logging and analyze collectors, triggers, JVM version, JVM options, and OS information and report error/warn/info level analysis and recommendations to support JVM tuning and troubleshooting for OpenJDK and Sun/Oracle JDK.

• Content from github.com is not included.GCViewer - A graphical tool which charts GC log data.

It's also possible to read the logs by any text editor, but note the GC logs only contains information for the JVM Heap and PermGen and not native memory.

Take for instance the following log snippet:

2013-07-15T12:15:09.277+0530: 2.088: [GC [PSYoungGen: 6282K->1810K(8448K)] 24670K->20830K(32384K), 0.0080180 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

In the above output, you can see that the GC is performed on Young generation in which 8448 kb is the total allocated memory to young generation out of which 6282 Kb is consumed by the objects in young generation and the memory still occupied by objects after performing GC is 1810 Kb.

Similarly, see a full GC triggered which is performed on young + old + perm:

2013-07-15T12:48:11.554+0530: 1984.365: [Full GC [PSYoungGen: 4096K->4089K(8192K)] [ParOldGen: 24560K->24560K(24576K)] 28656K->28650K(32768K) [PSPermGen: 54838K->54838K(54848K)], 0.1204910 secs] [Times: user=0.27 sys=0.00, real=0.12 secs] 

28656K->28650K(32768K) this means 32768Kb is the total allocated memory to the heap (i.e young + old) and 28656Kb is the memory consumed by objects on the heap and 28650Kb is the memory occupied by objects after GC is performed. Hence you can calculate free space of heap i.e.: 32768 - 28650 = 4118 is the free memory left.

[PSPermGen: 54838K->54838K(54848K)] this means 54848Kb is the total memory allocated to perm gen and 54838Kb is the memory occupied and 54838Kb is the memory still occupied by the objects after GC is performed.

Useful references:

• Java garbage collection long pause times
• Concurrent Mark Sweep (CMS) garbage collector "concurrent mode interrupted" appears in GC logs
• Concurrent Mark Sweep (CMS) garbage collector "concurrent mode failure" appears in GC logs
• Relationship between sys / user/ real time
• Real time significantly larger than the user and sys time for Full GC
• Should min and max heap and perm gen space be equal?

IBM

IBM Pattern Modeling and Analysis Tool for Java Garbage Collector: Content from www.ibm.com is not included.Content from www.ibm.com is not included.https://www.ibm.com/support/pages/ibm-pattern-modeling-and-analysis-tool-java-garbage-collector-pmat

HP

Xverbosegc option: Content from support.hpe.com is not included.Content from support.hpe.com is not included.https://support.hpe.com/hpesc/public/docDisplay?docId=c01895128&docLocale=en_US

Note : Also see How do I enable Java garbage collection logging?

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.