JAVA GARBAGE COLLECTION LOGGING

Java’s built-in garbage collection logging provides a quick, easy, and free way to profile or troubleshoot your Java application.  It can help you understand your application in terms of:

• memory usage (object count and size)
• heap size (initial and over time)
• GC metrics (frequency, pause time, and amount freed)

So, now you can answer questions like “how much memory is my app using,” “how much time is being spent doing garbage collection,” and “how big is the heap over time.” For help analyzing and visualizing a GC log file, be sure to check out GCViewer, a garbage collection and heap analysis tool.

GC logging is enabled using JVM arguments; below are the arguments I use. (Note: the log file specified as file is reset each time the VM starts.)

-verbose:gc -Xloggc:file

Dan Evans, in his garbage collection talk at DevNexus 2013, recommends the following GC flags in addition to the above.

-XX:+PrintGCDetails -XX:+PrintTenuringDistribution

Here’s an example GC log file which shows three GC events including one full GC.

[GC 19062K->7172K(60800K), 0.0087190 secs]
[GC 9346K->7525K(60800K), 0.0052810 secs]
[Full GC 7525K->7477K(60800K), 0.0615190 secs]

In the first event, garbage collection takes just under nine thousandths of a second to collect 11,890K memory used by objects (19,062K to 7,172K) while the heap is 60,800K.  The last event is a full GC lasting just over six hundredths of a second to free up 48K with no change in the heap.