Choice of the Java Garbage Collection algorithm heavily influences your application’s performance. In this post let’s discuss how to read and analyze CMS GC log files. Even though the CMS GC algorithm has been removed from JDK 14, still some of you might want to optimize the CMS GC performance. The CMS GC log file contains a wealth of information such as:

a. Information about every GC event that ran in the application 

b. At what time did CMS GC event ran

c. How long did the CMS GC event took to complete the event

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

e. Reason why the CMS 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 analyze CMS GC Logs:

How to enable CMS GC Log?

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

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

CMS GC Log Format

Whenever a CMS 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 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 CMS 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 CMS GC event ran. From the excerpt you can notice that this event ran at ‘2024-10-24T20:43:12.112’ and the time zone is -0700 (i.e. PST). 

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

3. GC Type field indicates that this event was the Young GC Event. 

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. GC Worker Thread Count: Indicates the number GC worker threads that are used for this GC Event. For this application 4 GC worker threads are used. You may visit this post to learn more on how to change GC worker threads count. 

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

  1. Before the GC event, Young Gen size is 38720KB. After the event, it became 4288KB. The allocated Young Gen size is 38720KB
  2. Before the GC event, Old Gen size is 29612KB. After the event, it became 46851KB i.e. objects are promoted from Young Gen to Old Gen, that’s why Old Gen size has grown during this event.
  3. Before the GC event, Metaspace size is 4123KB. After the event, it became 4123KB i.e. there is no change in size. The allocated Young Gen size is 1056768KB
  4. Before the GC event, Overall Heap size was 66MB. After the event, it became 49MB. The allocated Heap Size is 121MB.

7. 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.01 seconds (i.e. refer ‘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 CMS GC Event in the Log File

One single Full 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 Full GC event ran. From the excerpt you can notice that this event ran at ‘2024-10-24T20:43:12.124’ and the time zone is -0700 (i.e. PST). 

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

3. Full GC event has 7 internal phases. Details of each phase are printed in the GC log file. 

  1. Initial Mark Phase is the brief stop-the-world phase where GC marks all objects directly reachable from GC roots. Before this phase Heap size was 49MB. After this phase Heap size became 49MB. The allocated Heap size is 121MB. This phase took 2.457 milliseconds to complete
  2. Concurrent Mark Phase is the background process where GC traces and marks live objects while the application continues running. This phase took 27.046 milliseconds to complete
  3. Concurrent Preclean Phase is the phase where GC identifies objects modified during marking to minimize work in the next stop-the-world phase. This phase took 7.623 milliseconds to complete
  4. Concurrent Abortable Preclean Phase is the adaptive phase that attempts further precleaning but may be aborted based on heuristics. This phase took 38.606 milliseconds to complete
  5. Pause Remark Phase is the stop-the-world phase where GC finalizes the marking process to ensure completeness. Before this phase Heap size was 101MB. After this phase Heap size became 101MB. The allocated Heap size is 121MB. This phase took 2.281 milliseconds to complete
  6. Concurrent Sweep Phase is the background phase where GC reclaims memory by removing unreachable objects. This phase took 10.136 milliseconds to complete
  7. Concurrent Reset Phase is the final phase where GC prepares internal data structures for the next collection cycle. This phase took 1.482 milliseconds to complete

GCeasy Tool to Analyze CMS GC Log

You can notice, just trying to read and digest one single CMS 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 CMS GC log file format.

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

CMS GC Metrics and Graphs

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

Fig: CMS 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 CMS GC tuning you need to be aware of the Key Performance Indicators that you are trying to tune. The above figure shows the CMS 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 CMS GC event. You can notice that after every GC event, memory size drops. You can zoom-in in the real GCeasy report to see how memory usage is dropping.

Fig: GC Pause Duration Time

Above ‘GC Duration Time’ graph shows the Pause time of each CMS GC event. You can notice that the Full GC events (i.e. red triangle) take more time than Young GC events (i.e. blue squares). You can see that most of the Young GC events are completed in under 1 second, whereas Full GC events are taking around 40 seconds. This is because Full GC events runs all the 3 regions of the JVM Memory (i.e., Young Gen, Old Gen and Metaspace), whereas Young GC runs only on 1 region (i.e., Young Gen).

Fig: Recommendations given by GCeasy to optimize CMS GC performance

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

Tune CMS GC Performance

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

Conclusion

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