There are different Java Garbage Collection (GC) algorithms in OpenJDK, such as Serial GC, Parallel GC, CMS GC, G1 GC, Shenandoah GC, ZGC, Epsilon. Serial GC is the oldest GC algorithm in JDK. In this post, let’s discuss how to read and analyze Serial GC log files. The GC log file contains a wealth of information such as:

a. At what time Serial GC event ran

b. How long the Serial GC event took to complete the event

c. How many objects were reclaimed from each JVM Memory region

d. Reason why the Serial GC event was triggered

This information is not only helpful to optimize JVM’s performance but also provide deeper insights to debug memory problems. 

If you are new to Java GC Concepts, we recommend you to learn about Java Garbage Collection fundamentals first from this post.

Video

Here is the short video clip from which you can understand how to read and analyze Serial GC Logs:

How to enable Serial GC Log?

You can configure Serial GC algorithm and generate GC log file, by passing following JVM arguments to your application:

-XX:+UseSerialGC -Xlog:gc*:file=<gc-log-file-path>

This will generate the GC log in the specified file path. You can consider reading this post on GC logging best practices, to capture Serial GC log events in a pristine format.

Serial GC Log Format

Whenever a Serial GC event is triggered in the JVM, it will be logged into the GC log file. Below is the excerpt of a single Serial GC event from the GC log file: 

Fig: Serial GC Event in the Log File

Let’s review the fields in the Serial GC event:

1. Timestamp field indicates the time at which this Young SERIAL GC event ran. From the excerpt you can notice that this event ran at ‘2017-10-24T20:49:01.006’ and the time zone is -0700 (i.e. PST). 

2. GC Event Count field indicates that this was the 8th GC event to run after JVM was started

3. GC Type: There are two types of GC Events (i.e. Young GC and Full GC). This field indicates that this event was the Young GC Event. If it’s a Full GC event, in this field you see the value ‘Full’.

4. GC Reason field Indicates the reason why this GC event was triggered. This Young GC event was triggered because of ‘Allocation Failure’, which means there isn’t sufficient space in the Young Generation to create new objects. 

5. Memory Size field shows the heap memory size. Before the GC event, heap size was 195MB. After the GC event heap size became 163MB (i.e. 32MB was cleared in this GC event). The total allocated Heap size is 233MB. 

6. Time Taken to Complete field indicates the amount of time taken by this GC event to complete. This GC event took 31.909 milliseconds to complete. 

GCeasy Tool to analyze Serial GC Log

As you can see, just trying to read and understand one single Serial GC event turns out to be a tedious task. However our GC log files will contain thousands of GC events. Thus, trying to read all the events manually and correlate them can turn out to be a cumbersome and time-consuming process. Thus, you can use GC log analysis tools like GCeasy which can analyze all formats of GC logs.

Serial GC Log Analysis: Here is the sample GC log report generated by the GCeasy tool by analyzing Serial GC log file. 

Serial GC Metrics and Graphs

GCeasy tool’s report provides several graphs and fine-grained metrics to study the Serial GC behavior in your application. Below are some of the excerpts from the Serial GC log analysis report:

Fig: Serial GC Key Performance Indicators by GCeasy

There is a famous saying: “You can’t optimize, what you can’t measure”. Thus, when it comes to Serial GC tuning you need to be aware of the Key Performance Indicators that you are trying to tune. The above figure shows the Serial GC KPIs that are sourced from the GC log file.

Fig: GC Pause Duration Time

The above graph shows the GC pause time of each Serial GC event. You can notice that Full GC events (i.e. red triangle) are typically in the range of 600 milliseconds and there is one Full GC event taking 900 milliseconds to complete. Towards the left side of the graph you can notice the Young GCs running.

Fig: Recommendations given by GCeasy to optimize Parallel GC performance

Besides the metrics and visuals, the tool also reports the problems and gives recommendations to optimize the Serial GC performance as shown in the above figure. In the above figure, you can notice that the GCeasy tool is pointing out that GC events are running consecutively. Application performance will degrade significantly when GC events runs continuously.

Tune Serial GC Performance

If you are looking to tune Serial GC performance, I would like to share few pointers:

  1. 9 Tips to Reduce GC Pause Time: This post gives general 9 tips to reduce any GC algorithm’s pause time (including Serial GC)
  2. JVM arguments to tune Serial GC Performance: This post talks about important Serial GC arguments that you can use for tuning the GC performance.

Conclusion

Whether you want to reduce pause times, fine-tune JVM arguments, or improve overall memory management, leveraging automated GC analysis can save time and enhance application stability. If you would like to learn more about Serial GC Tuning, please check out my online ‘JVM Performance Engineering & Troubleshooting Master Class’.