Choice of the Java Garbage Collection algorithm heavily influences your application’s performance. The Shenandoah Garbage Collector is one of the latest and low-pause-time GC algorithms introduced by Red Hat for the OpenJDK. Shenandoah GC just like G1 GC is a regionalized GC algorithm, where the heap is maintained as a collection of regions. In this post let’s discuss how to read and analyze Shenandoah GC log files. The GC log file contains a wealth of information such as: 

a. Information about every GC event that in the application 

b. At what time Shenandoah GC event ran

c. How long the Shenandoah GC event took to complete the event

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

e. Reason why the Shenandoah 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 from this post.

Video

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

How to enable Shenandoah GC Log?

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

--XX:+UseShenandoahGC -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 Shenandoah GC log events in a pristine format.

Shenandoah GC Log Format

Whenever a Shenandoah GC event is triggered in the JVM, it will be logged in to the GC log file. Below is the excerpt of a single GC event from the GC log file. One single GC event is printed in multiple log lines.

Fig: Full Shenandoah 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-12-25T00:42:31.696’ and the time zone is +0000 (i.e. UTC). 

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

3. GC Event Phases: In one single Shenandoah GC event there are multiple phases. This field provides the details of each phase:

  1. Pause Init Mark phase is a brief stop-the-world phase where GC identifies and marks all objects directly reachable from GC roots. This phase took 0.640 milliseconds to complete.
  2. Concurrent Marking phase is the background phase where GC traverses the heap and marks all reachable objects while the application continues running. This phase took 492.938 milliseconds to complete.
  3. Pause Final Mark phase is a stop-the-world phase that finalizes marking, ensuring all live objects are correctly identified before proceeding to evacuation. This phase took 14.498 milliseconds to complete.\
  4. Concurrent Cleanup phase is the phase where GC reclaims memory by removing obsolete regions and prepares for the next collection cycle while the application runs. Before this phase, the heap size was 3898 MB. After this phase, the heap size became 3674 MB. The total allocated heap size is 29696 MB. This phase took 0.134 milliseconds to complete.
  5. Concurrent Evacuation phase is the phase where live objects are relocated (evacuated) to compact memory, reducing fragmentation, while the application continues running. This phase took 99.164 milliseconds to complete.
  6. Pause Init Update phase is a short stop-the-world phase where GC prepares the heap for pointer updates due to object relocation. This phase took 0.038 milliseconds to complete.
  7. Concurrent Update phase is the phase where GC updates references to relocated objects across the heap while the application continues execution. This phase took 348.591 milliseconds to complete.
  8. Pause Final Update phase is a brief stop-the-world phase to finalize reference updates and ensure correctness before resuming normal execution. This phase took 0.508 milliseconds to complete.
  9. Concurrent Cleanup phase is the phase where GC reclaims memory by removing obsolete regions and prepares for the next collection cycle while the application runs. Before this phase, heap size was 3894 MB. After this phase, heap size became 871 MB. Total allocated heap size is 29696 MB. This phase took 0.116 milliseconds to complete.

GCeasy Tool to Analyze Shenandoah GC Log

You can notice, just trying to read and digest one single Shenandoah GC event turns out to be a tedious task. Needless to say the complexity that arises when you try to read thousands of GC events that are present in the GC log file. Thus, you can use GC log analysis tools like GCeasy, which can analyze all formats of GC logs including Shenandoah GC log file format.

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

Shenandoah GC Metrics and Graphs

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

Fig: Shenandoah 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 Shenandoah GC tuning, you need to be aware of the Key Performance Indicators that you are trying to tune. The above figure shows the Shenandoah 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 after every Shenandoah GC event. You can notice that after every GC event, memory size drops. In fact it may not be visible from the above image; however you can zoom-in in the real GCeasy report to see what’s actually happening.

Fig: GC Pause Duration Time

Above ‘Pause GC Duration Time’ graph shows the Pause time of each Shenandoah GC event. You can see that most of the GC events are completing under 50 milliseconds, whereas a couple of GC events are in the 800, 900 milliseconds range.

Fig: Recommendations given by GCeasy to optimize Shenandoah GC performance

Besides the metrics and visuals, the tool also gives recommendations and JVM settings to optimize the Shenandoah GC performance as shown in the above figure. In the above figure, you can notice that the GCeasy tool is pointing that memory is over-allocated than the actual need. Reducing the memory allocation will directly reduce the computing cost of the application.

Tune Shenandoah GC Performance

If you are looking to tune Shenandoah 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 Shenandoah GC)
  2. JVM arguments to tune Shenandoah GC Performance: This post talks about important Shenandoah GC arguments that you can use for tuning the GC performance.

Conclusion

Hopefully in this post, you learnt how to enable GC log, how to interpret Shenandoah GC events and how to analyze them. If you would like to learn more about Shenandoah GC Tuning, please check out my online ‘JVM Performance Engineering & Troubleshooting Master Class’.