In the last article, we discussed 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 on 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 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. We have to pass the JVM arguments to enable the GC log. Below are the options are given for JDK8 Oracle HotSpot JVM.
Note: Set the heap size as low to get the GC log for exercise.
-XX:+DisableExplicitGC -XX:+PrintGCDetails -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCDateStamps -Xloggc:gclog.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2000k
Let us understand the purpose of each option. These options may vary based on the OS/JVM vendor/JAVA version.
DisableExplicitGC: By default this option is disabled. Some times 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, JVM prints more details at each garbage collection.
PrintGCApplicationStoppedTime: By default this option is disabled. If we enable, it prints the information on application pause during the garbage collection.
PrintGCApplicationConcurrentTime: By default this option is disabled. If we enable, it prints the information on the application running time during the GC.
PrintGCDateStamps: By default this option is disabled. If we enable, it prints the date and time details at each GC.
loggc: This is a string option. We have had to pass the gc log file name. In this file, we will get all the GC log information.
UseGCLogFileRotation: This option indicates the JVM to rotate the log file if the file size reaches the 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. The size of the log file at which point 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.
- How often the Young GC and Full GC is occurring? There should be several minutes 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.
- 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. At 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 the garbage collection, the application threads will be in a wait state(GC is stopped the world event). This impacts the user experience.
I have created a sample application to generate a enough GC log. Now, we will understand the same here.
There are some GC log viewers. Here is one of the GC log analyzer(http://gceasy.io/). If you upload the GC log, it will provide a detailed analysis with the charts to understand. Based on the GC analysis, we can tune the heap size, Young gen space, and Tenured space. In the coming article will discuss the different performance-related JVM options. Till then Stay Tuned!!!.
Nice explanation about GC at micro level…
Awesome article! Thanks for writing it up.