Java 6 G1GC - Repeated full GC

Question

We have a Java application which is configured to use Java 6 with G1GC collector. Recently we observed that Full GC gets stuck in repeated attempts even though there is enough memory (per GC logs). Has anyone come across such scenario for Java 6 G1GC combination?

GC Config:

-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M -XX:-OmitStackTraceInFastThrow -XX:`enter code here`+UseG1GC -XX:InitiatingHeapOccupancyPercent=72  -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false

GC Logs:

9  172169595.9  172169595.9  172169595.9  172169595.9]
      [Other:   0.4 ms]
   [Clear CT:   0.8 ms]
   [Other:   2.1 ms]
      [Choose CSet:   0.0 ms]
   [ 6526M->6456M(14848M)]
 [Times: user=0.20 sys=0.00, real=0.02 secs]
2018-03-08T15:51:22.822+0000: 172169.607: [Full GC 6456M->4080M(14848M), 6.7084910 secs]
 [Times: user=11.75 sys=0.02, real=6.70 secs]
172177.358: [GC pause (young), 0.01637700 secs]
   [Parallel Time:  13.9 ms]
      [GC Worker Start Time (ms):  172177359.4  172177359.5  172177359.5  172177359.5  172177359.5  172177359.5  172177359.6  172177359.6  172177359.6  172177359.6  172177359.7  172177359.7  172177359.7  172177359.7  172177359.8  172177359.8  172177359.8  172177359.8]
      [Update RS (ms):  2.5  1.5  2.2  2.2  2.3  2.2  2.3  2.1  2.2  2.5  1.5  1.5  1.0  1.5  2.3  1.6  1.9  2.2
       Avg:   2.0, Min:   1.0, Max:   2.5]
         [Processed Buffers : 12 106 62 1 1 1 1 1 1 83 113 149 62 136 1 76 1 1
          Sum: 808, Avg: 44, Min: 1, Max: 149]
      [Ext Root Scanning (ms):  4.6  5.6  5.5  5.4  5.2  5.4  5.3  5.3  5.0  4.4  5.4  5.3  5.9  5.3  5.1  5.2  5.2  5.1
       Avg:   5.2, Min:   4.4, Max:   5.9]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Object Copy (ms):  6.3  6.3  5.7  5.8  5.8  5.7  5.7  5.9  6.1  6.3  6.3  6.3  6.3  6.3  5.7  6.3  6.0  5.7
       Avg:   6.0, Min:   5.7, Max:   6.3]
      [Termination (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Termination Attempts : 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1
          Sum: 18, Avg: 1, Min: 1, Max: 1]
      [GC Worker End Time (ms):  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9  172177372.9]
      [Other:   0.6 ms]
   [Clear CT:   0.3 ms]
   [Other:   2.2 ms]
      [Choose CSet:   0.0 ms]
   [ 6543M->6473M(14848M)]
 [Times: user=0.22 sys=0.00, real=0.01 secs]
2018-03-08T15:51:30.598+0000: 172177.384: [Full GC 6473M->4098M(14848M), 6.7136020 secs]
 [Times: user=11.72 sys=0.01, real=6.71 secs]
172185.070: [GC pause (young), 0.02292200 secs]
   [Parallel Time:  19.0 ms]
      [GC Worker Start Time (ms):  172185071.9  172185072.0  172185072.0  172185072.1  172185072.1  172185072.2  172185072.2  172185072.2  172185072.2  172185072.3  172185072.3  172185072.3  172185072.3  172185072.4  172185072.4  172185072.4  172185072.5  172185072.5]
      [Update RS (ms):  5.4  5.5  4.1  5.2  9.9  3.7  5.0  4.2  4.5  3.8  3.7  4.7  3.8  3.7  4.8  4.5  3.8  5.5
       Avg:   4.8, Min:   3.7, Max:   9.9]
         [Processed Buffers : 3 2 3 2 2 109 3 2 2 58 68 100 107 69 62 121 97 2
          Sum: 812, Avg: 45, Min: 2, Max: 121]
      [Ext Root Scanning (ms):  5.8  5.5  5.7  5.3  6.0  5.5  5.4  5.6  5.2  5.3  5.4  4.5  5.3  5.3  4.3  4.5  5.1  5.1
       Avg:   5.3, Min:   4.3, Max:   6.0]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1]

Answer 1

I also think you should update your JVM. However, I understand that some times this is not so easy here you can see some improvements on the GC1 when the JDK8 is compared with JDK7

Source: https://www.redhat.com/en/blog/part-1-introduction-g1-garbage-collector

A few humongous objects may not cause a problem, but a steady allocation of them can lead to significant heap fragmentation and a noticeable performance impact. Prior to JDK8u40, humungous objects could only be collected through a Full GC so the potential for this to impact JDK7 and early JDK8 users is very high. This is why it’s critical to understand both the size of objects your application produces and what G1 is defining for region size. Even in the latest JDK8, if you are doing significant numbers of humongous allocations, it is a good idea to evaluate and tune away as many as possible

Furthermore, within this article you can see this:

Finally and unfortunately, G1 also has to deal with the dreaded Full GC. While G1 is ultimately trying to avoid Full GC’s, they are still a harsh reality especially in improperly tuned environments. Given that G1 is targeting larger heap sizes, the impact of a Full GC can be catastrophic to in-flight processing and SLAs. One of the primary reasons is that Full GCs are still a single-threaded operation in G1. Looking at causes, the first, and most avoidable, is related to Metaspace.

By the way, it seems to be the newest version of Java (10) is going to include a G1 with the capability of executing Full GCs in parallel.

https://www.opsian.com/blog/java-10-with-g1/

Java 10 reduces Full GC pause times by iteratively improving on its existing algorithm. Until Java 10 G1 Full GCs ran in a single thread. That’s right - your 32 core server and it’s 128GB will stop and pause until a single thread takes out the garbage.