ZGC is an upcoming popular low pause GC algorithm that is targeted to be used in applications whose memory size is quite large. In this post let’s discuss how to read a ZGC log file. The GC log file contains a wealth of information such as:

a. At what time ZGC event ran

b. How long the ZGC event took to complete the event

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

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

How to enable ZGC Log?

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

XX:+UseZGC -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 ZGC log events in a pristine format.

ZGC Event Log

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

Fig: ZGC Event in the Log File

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

1. TimeStamp field indicates the time at which this ZGC event ran. From the excerpt you can notice that this event ran 16.916 seconds since JVM was started 

2. Event Count field shows the GC event count. This was the 5th GC event that ran since JVM was started

3. GC Reason field indicates the reason why this ZGC event was triggered. In this case it was triggered because of the Allocation Rate. It indicates that this ZGC event was triggered because the application’s object allocation rate was high

4. Time Taken to Complete tells the time taken by the ZGC event to complete. One ZGC event has multiple internal phases such as Pause Mark, Concurrent Process, Concurrent Reset, Concurrent Relocate, Pause Relocate… Time taken by each phase is shown here

5. Metaspace Region Size shows the metaspace region size after the GC event. Metaspace tend to have metadata definitions (such class definitions, method definitions) of your application

6. Heap Size shows the size of your Heap region (i.e. Young Gen and Old Gen). You can notice that before the GC event, heap size was 352MB and after the GC event it dropped to 80MB

Note: There is more granular information in the ZGC event, but I am not documenting to reduce the verbosity of the post. However important fields are described above.

GCeasy Tool to analyze ZGC Log

You can now notice that just trying to read and digest one single ZGC event turns out to  be tedious. Your 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 formats of GC logs including ZGC log file format.

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

ZGC Metrics and Graphs

GCeasy tool gives several graphs and fine-grained metrics to study the ZGC behavior in your application. Below are some of the excerpts from the ZGC log analysis report:

Fig: ZGC Key Performance Indicators by GCeasy

There is a famous saying: “You can’t optimize what you can’t measure”. Thus, when it comes to ZGC tuning you need to be aware of the Key Performance Indicators that you are trying to tune. The above figure shows the ZGC KPIs summary 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 ZGC event. You can notice that after every GC event (i.e. red triangle), memory usage starts to go down. In fact, it may not be visible from the above image, however you can zoom in on the actual report to see what’s actually happening.

Fig: GC Pause Duration Time

The above ‘GC Pause Duration Time’ graph shows the Pause Time incurred by each ZGC event. Since ZGC is a low GC pause algorithm, from the graph, you can notice most of the GC events pause times are in the range of 0.5 – 2 milliseconds.

Fig: Recommendations given GCeasy to optimize ZGC performance

Besides the metrics and visuals, the tool also gives recommendations and JVM settings to optimize the ZGC performance as shown in the above screenshot.

Tune ZGC Performance

If you are looking to tune ZGC performance, herewith 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 ZGC)
  2. JVM arguments to ZGC Performance: The post talks about important ZGC arguments that are available that you can use for tuning the 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 ZGC Tuning, please check out my online ‘JVM Performance Engineering & Troubleshooting Master Class’.