Java GC log analysis: Long GC pause times

Customer requirements

A business team member provided the following feedback:

1. The application frequently experiences long pause times during runtime. This causes health checks to fail and leads to other problems.

2. The application performs offline data processing. Latency is not a critical requirement. The main goal is to keep most pause times under 1200 ms and avoid extremely long pauses. Application throughput is a higher priority.

3. The application currently uses CMS GC. The customer wants to upgrade to G1 GC to adopt modern technology and resolve the previously mentioned issues.

GC log analysis

First, examine the severity of the problem when using CMS. After uploading the file, adjust the analysis configuration:

In the Analysis Configuration dialog, set the following parameters:

• Long Pause Time Threshold: 1200 ms

• Young GC Interval Threshold: 5000 ms

• Old GC Interval Threshold: 15000 ms

• Full GC Interval Threshold: 60000 ms

The problem diagnosis shows that many Full GC, Final Remark, and Young GC pause times exceed 1200 ms.

The pause view shows that timeouts are frequent.

The customer then modified the JVM startup parameters to upgrade from CMS GC to G1 GC. After the application ran for a period of time, a new GC log was uploaded for analysis.

In the GC Phases tab, the statistics for each phase are as follows:

• Young GC: occurred 298 times, average interval 4.06s (triggered alert), maximum duration 573ms, total duration 48.2s

• Mixed GC: occurred 6 times, average interval 1.03s (triggered alert), maximum duration 173ms, total duration 615ms

• Concurrent Mark Cycle: occurred 2 times, average interval 3.87min, maximum duration 11.3s, total duration 21.8s

After the upgrade to G1 GC, the application's pause times mostly meet the requirements. However, G1 GC by default attempts to keep application pauses under 200 ms. Because the application's pauses are generally long, G1 controls pause times by making the young generation space very small. This results in more frequent GC, which reduces overall application throughput. The "GC Pause Time Percentage" metric, which reflects application throughput, increased from 2.38% to 3.87%.

To reduce the frequency of Young GC and increase the size of the young generation space, the application was tuned by adding the following JVM parameters:

-XX:MaxGCPauseMillis=400 -XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=40

After the application ran for a period, this change resolved the frequent GC issue. However, the minimum size of the young generation space was set too high. This setting impaired the auto-tuning capability of G1 GC and caused new Full GC and To-space Exhausted events, which in turn led to long pauses.

GC log details show that Young GC pause times gradually increased (from approximately 1.98s to 43.9s and 38.6s), the old generation grew from 5.68GB to 25GB (approaching the full heap limit), and ultimately a Full GC was triggered due to Allocation Failure, with object promotion reaching as high as 7.78GB.

The JVM parameters were tuned again as follows:

-XX:G1NewSizePercent=20 -XX:-XX:InitiatingHeapOccupancyPercent=40

After the application ran for a period with the new parameters, no new issues occurred, and the G1 GC upgrade was considered complete. Using the Java GC log analysis tool, the customer was able to resolve the latency problem through JVM parameter tuning while maintaining application throughput. The overall result was satisfactory.