Choice of the Java GC algorithm heavily influences your application’s performance. Parallel GC is the default GC algorithm from JDK 5 to JDK 8. In this post let’s discuss how to read and analyze Parallel GC log files. The GC log file contains a wealth of information such as:

a. At what time Parallel GC event ran

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

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

d. Reason why the Parallel 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 Parallel GC Logs:

How to enable Parallel GC Log?

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

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

This will generate the GC log in the specified file path.

If time permits, we recommend you to read GC logging best practices post, to capture Parallel GC log events in a pristine format.

Parallel GC Log Format

Whenever a Parallel GC event is triggered in the JVM, it will be logged into the GC log file. In the GC log file, you are going to notice two types of GC events reported:

  1. Young GC: This Event runs only on the Young Generation of the JVM
  2. Full GC: This Event runs only Young Generation, Old Generation and Metaspace regions of the JVM. 

The log format slightly varies based on the GC event type. Let’s see them in detail.

Young GC Event Log Format

Below is the excerpt of a single Young GC event from the GC log file: 

Fig: Young GC Event in the Log File

One single Young GC event information is printed across several lines. Let’s review the important fields in the Young GC event:

1. Timestamp field indicates the time at which this Young GC event ran. From the excerpt you can notice that this event ran on 2024-08-31T02:33:20.326’ and the time zone is +0000 (i.e. UTC). 

2. GC Type field indicates that this event was the Young GC Event. If it’s a Full GC event, you will see the text ‘Full GC’ printed in this field. 

3. 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. 

4. Memory Size field shows the internal memory region sizes before and after the event.

  1. Before the GC event, the Young Generation size was 2097664KB. After the event, it became 11337KB. The allocated size of Young Generation is 2446848KB
  2. Before the GC event, the overall heap size was 2123061KB. After the event it became 36742KB. Total Overall allocated Heap Size is 8039424KB.

5. Time Taken to Complete field indicates the amount of time taken by this GC event to complete. You can see this GC event took 0.33 seconds (i.e. refer to ‘real’ field) to complete. If you like, you can learn about user and sys time fields from this post.

Full GC Event Log Format

Below is the excerpt of a single Full GC event from the GC log file: 

Fig: Full GC Event in the Log File

1. Timestamp field indicates the time at which this Full GC event ran. From the excerpt you can notice that this event ran at ‘2024-08-31T01:09:19.416’ and the time zone is +0000 (i.e. UTC). 

2. GC Type field indicates that this event was the Full GC Event. 

3. GC Reason field Indicates the reason why this GC event was triggered. This Full GC event was triggered because of ‘Metadata GC Threshold’. 

4. Memory Size field shows the internal memory region sizes before and after the event.

  1. Before the GC event, the Young Generation size was 18495KB. After the event, it became 0KB. The allocated size of Young Generation is 2446848KB
  2. Before the GC event, the Old Generation size was 24KB. After the event, it became 17366KB. You can observe that Old Gen size has increased during this event. This is happening because objects are promoted from the Young Gent to Old Gen. The allocated size of Old Generation is 5592576KB
  3. Before the GC event the Overall Heap size was 18519KB. After the GC event it became 17366KB. Total Overall allocated Heap Size is 8039424KB.
  4. Before the GC event, Metaspace size was 20781KB. After the event, Metaspace became 20781KB. There is no change in the Metaspace size in this event. The allocated size of Metaspace is 1067008KB

Note: Since this is a Full GC event, Old Generation and Metaspace region sizes are printed, whereas they will not be printed in the Young GC Event.

5. Time Taken to Complete field indicates the amount of time taken by this GC event to complete. You can see this GC event took 0.04 seconds (i.e. refer ‘real’ field) to complete. If you like, you can learn about user and sys time fields from this post.

GCeasy Tool to analyze Parallel GC Log

You can now notice that just trying to read and digest one single GC event turns out to  be a tedious task. Our GC log file will contain thousands of such 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 GC log formats.

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

Parallel GC Metrics and Graphs

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

Fig: Parallel 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 Parallel GC tuning you need to be aware of the Key Performance Indicators that you are trying to tune. Above figure shows the Parallel GC KPIs that are sourced from the GC log file.

Fig: Heap Usage Graph generated by GCeasy

In the above graph you can notice the Heap usage trend over the time period. You can notice that towards the right end of the graph, heap usage starts to go high. It’s because traffic starts to come to the application during this time window 

Fig: GC Pause Duration Time

The above ‘GC Duration Time’ graph shows the Pause Time incurred by each Parallel GC event. You can notice that pause time is running from a few milliseconds to 2000 milliseconds (i.e. 2 seconds). Also, you can observe the pause trends. Toward the right end of the graph pause times are increasing and more frequently running, as application traffic starts to increase.

Fig: Recommendations given by GCeasy to optimize Parallel GC performance

Besides the metrics and visuals, tool also spots the problems in the configurations and gives recommendations to optimize the Parallel GC performance as shown in the above screenshot. In the above screenshot, you can notice that the GCeasy tool is pointing that the heap size is over allocated by 32% than the actual need. This overall location will lead to increased computing costs.

Tune Parallel GC Performance

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

  1. 9 Tips to Reduce GC Pause Time: This post gives 9 general tips to reduce any GC algorithm’s pause time (including Parallel GC)
  2. JVM arguments to tune Parallel GC Performance: This post talks about important Parallel 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 Parallel GC Tuning, please check out my online ‘JVM Performance Engineering & Troubleshooting Master Class’.