G1 young GC does not free memory - to-space exhausted

Question

I'm using G1GC, jdk 1.7

Java HotSpot(TM) 64-Bit Server VM (24.79-b02) for linux-amd64 JRE (1.7.0_79-b15), built on Apr 10 2015 11:34:48 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 32826020k(12590436k free), swap 33431548k(33358800k free)

CommandLine flags: -XX:AutoBoxCacheMax=3000000 -XX:+DisableExplicitGC 
-XX:G1NewSizePercent=20 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=10737418240 
-XX:InitiatingHeapOccupancyPercent=70 -XX:MaxDirectMemorySize=1073741824 -XX:MaxGCPauseMillis=1000 
-XX:MaxHeapSize=10737418240 
-XX:-OmitStackTraceInFastThrow -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps -XX:+UnlockExperimentalVMOptions 
-XX:+UseCompressedOops -XX:+UseG1GC

Mostly minor GC works fine, but it still start unusual fullGC, about one to two times in an hour.

This is a normal case young GC log

3443.100: [GC pause (young), 0.3021260 secs]
  [Parallel Time: 277.6 ms, GC Workers: 4]
  [GC Worker Start (ms): Min: 3443100.5, Avg: 3443100.6, Max: 3443100.6, Diff: 0.1]
  [Ext Root Scanning (ms): Min: 2.9, Avg: 3.0, Max: 3.1, Diff: 0.2, Sum: 11.9]
  [Update RS (ms): Min: 33.5, Avg: 33.6, Max: 33.9, Diff: 0.4, Sum: 134.5]
     [Processed Buffers: Min: 180, Avg: 204.8, Max: 227, Diff: 47, Sum: 819]
  [Scan RS (ms): Min: 76.0, Avg: 76.2, Max: 76.3, Diff: 0.3, Sum: 304.9]
  [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
  [Object Copy (ms): Min: 164.4, Avg: 164.4, Max: 164.5, Diff: 0.1, Sum: 657.7]
  [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
  [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
  [GC Worker Total (ms): Min: 277.3, Avg: 277.4, Max: 277.4, Diff: 0.1, Sum: 1109.5]
  [GC Worker End (ms): Min: 3443377.9, Avg: 3443378.0, Max: 3443378.0, Diff: 0.0]
  [Code Root Fixup: 0.2 ms]
  [Code Root Migration: 0.3 ms]
  [Clear CT: 2.0 ms]
  [Other: 22.1 ms]
  [Choose CSet: 0.0 ms]
  [Ref Proc: 15.7 ms]
  [Ref Enq: 0.5 ms]
  [Free CSet: 3.2 ms]
  [Eden: 5996.0M(5996.0M)->0.0B(5648.0M) Survivors: 148.0M->196.0M Heap: 8934.5M(10.0G)->2997.2M(10.0G)]
  [Times: user=1.13 sys=0.00, real=0.30 secs]

And this is a unusual GC log before the fullGC. It repeated two to three times, and it didn't clean any memory.

3482.422: [GC pause (young) (to-space exhausted), 3.4878580 secs]
[Parallel Time: 1640.5 ms, GC Workers: 4]
  [GC Worker Start (ms): Min: 3482421.8, Avg: 3482422.4, Max: 3482424.0, Diff: 2.2]
  [Ext Root Scanning (ms): Min: 2.1, Avg: 3.2, Max: 3.8, Diff: 1.7, Sum: 12.6]
  [Update RS (ms): Min: 104.8, Avg: 105.2, Max: 105.6, Diff: 0.8, Sum: 421.0]
     [Processed Buffers: Min: 201, Avg: 221.2, Max: 236, Diff: 35, Sum: 885]
  [Scan RS (ms): Min: 75.1, Avg: 75.2, Max: 75.3, Diff: 0.1, Sum: 300.8]
  [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
  [Object Copy (ms): Min: 1455.9, Avg: 1456.1, Max: 1456.2, Diff: 0.3, Sum: 5824.2]
  [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
  [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
  [GC Worker Total (ms): Min: 1638.2, Avg: 1639.8, Max: 1640.4, Diff: 2.2, Sum: 6559.3]
  [GC Worker End (ms): Min: 3484062.2, Avg: 3484062.2, Max: 3484062.2, Diff: 0.0]
[Code Root Fixup: 0.2 ms]
[Code Root Migration: 0.5 ms]
[Clear CT: 2.0 ms]
[Other: 1844.7 ms]
  [Choose CSet: 0.0 ms]
  [Ref Proc: 60.1 ms]
  [Ref Enq: 0.5 ms]
  [Free CSet: 1.2 ms]
[Eden: 5648.0M(5648.0M)->0.0B(1876.0M) Survivors: 196.0M->172.0M Heap: 9441.9M(10.0G)->9352.3M(10.0G)]
[Times: user=9.29 sys=0.05, real=3.49 secs]

Then it started a fullGC

3490.812: [Full GC 9626M->1879M(10G), 7.6059670 secs]
[Eden: 0.0B(2048.0M)->0.0B(6144.0M) Survivors: 0.0B->0.0B Heap: 9626.3M(10.0G)->1879.5M(10.0G)], [Perm: 33901K->33901K(36864K)]
[Times: user=10.24 sys=0.00, real=7.61 secs]

Why the last youngGC didn't clean any memory?

Answer 1

You are suffering from evacuation failures as can be seen by the to-space exhausted part of the start message for the collection.

This occurs when there is not enough free space on your heap to promote survived or promoted objects (or both) and the heap can not be expanded more.

Monica Beckwith writes the following in Tips for Tuning the Garbage First Garbage Collector

For G1 GC, an evacuation failure is very expensive -

• For successfully copied objects, G1 needs to update the references and the regions have to be tenured.
• For unsuccessfully copied objects, G1 will self-forward them and tenure the regions in place.

Often G1 can't keep up with the allocation rate when forced to do these operations and will eventually be forced to a full GC due to allocation failure. This is probably why you see a full GC after a couple of evacuation failures.

Monica also writes about possible solutions in Garbage First Garbage Collector Tuning

• Increase the value of the -XX:G1ReservePercent option (and the total heap accordingly) to increase the amount of reserve memory for "to-space".

• Start the marking cycle earlier by reducing the -XX:InitiatingHeapOccupancyPercent.

• You can also increase the value of the -XX:ConcGCThreads option to increase the number of parallel marking threads.

Also, increasing the heap is another option that would reduce the likelihood of evacuation failures.