Enabling and Analyzing the Garbage Collection Log

In the last article we discussed on the Garbage Collection process. In this article we will learn how to enable the garbage collection log and see what insights we will get from the GC log to tune the JVM.

As a developer, everyone will get a question about enabling the GC log on production servers. Is it advisable to enable GC log on production server? Yes, it is recommended to enable the GC log on production servers. The overhead by enabling the GC log on the JVM is minimal. As per Standard Performance Evaluation Corporation (SPEC), the world record high performance Java Enterprise production servers are running with GC log enabled. First, have to pass the JVM arguments to enable the GC log. Below are the options given for JDK8 Oracle HotSpot JVM.

Note: Set the heap size as low to get the GC log for this exercise:

Let us understand the purpose of each option. These options may vary based on the OS, JVM vendor, and Java version.

DisableExplicitGC: By default this option is disabled. Sometimes developers might have invoked garbage collection pragmatically by calling System.gc() or Runtime.getRuntime().gc(). This is not advisable. Hence in production systems we enable this option so that the pragmatic invocation of garbage collection is disabled.

PrintGCDetails: By default this option is disabled. If we enable this option, the JVM prints more details at each garbage collection.

PrintGCApplicationStoppedTime: By default this option is disabled. If we enable it, it prints the information on application pause during GC.

PrintGCApplicationConcurrentTime: By default this option is disabled. If we enable it, it prints the information on application running time during GC.

PrintGCDateStamps: By default this option is disabled. If we enable it, it prints the date and time details at each GC.

loggc: This is a string option. We have have to pass the gc log file name. In this file we will get all the GC log information.

UseGCLogFileRotation: This option makes the JVM rotate the log file if the file size reaches a specified size.

NumberOfGCLogFiles: The default value is 1. This sets the number of files to use when rotating logs.

GCLogFileSize: The default value is 8KB, which is the size of the log file before the point the where the log will be rotated.

By setting the above options, we are ready to get the GC log. To tune the JVM, it is better to enable these options during the load test and take the GC log on different loads for analysis. From the GC log we have to observe the below parameters.

1. How often are the Young GC and Full GC occurring? There should be a several-minute time gap between the GC events. If the Young GC is happening more often, then we might need to look at the allocated Young Gen space. If the Full GC is happening more often, then we need to look at the allocated heap size. 
2. How much time each GC event is taking to complete? Ideally the Young GC will take a couple of milliseconds, and the Full GC will take a couple of milliseconds to seconds. In any circumstance, if the GC is taking several seconds to minutes, then we have to look at the Heap size tuning. If the GC thread takes more time to complete than garbage collection, the application threads will be in a wait state (GC is a stop the world event). This impacts the user experience.

I have created a sample application to generate a GC log. Now, we will understand the issues here.

There are some GC log viewers. Here is the one of the GC log analyzers (http://gceasy.io/). If you upload the GC log, it will provide detailed analysis with the charts to understand it. Based on the GC analysis, we can tune the heap size, young gen space, and tenured space. In future articles, we will discuss the different performance-related JVM options. Stay Tuned!