L.Maple
L.Maple

Reputation: 141

G1 Full GC events happens too often due to Allocation Failure

I have a backend service using G1 GC, which has started full gc so frequently after running about 2 days.

the original application gc params(eliminating gc log params for better readability ):

-Xms32g -Xmx32g -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:G1ReservePercent=15 
-XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=20 

GC params in gc log:

OpenJDK 64-Bit Server VM (25.202-b08) for linux-amd64 JRE (1.8.0_202-b08), built on Jan 22 2019 13:35:07 by "jenkins" with gcc 4.8.2 20140120 (Red Hat 4.8.2-15)
Memory: 4k page, physical 263567564k(2925568k free), swap 0k(0k free)
CommandLine flags: 
-XX:CICompilerCount=15 -XX:ConcGCThreads=6 -XX:G1HeapRegionSize=16777216 (16MB)
-XX:G1NewSizePercent=20 -XX:G1ReservePercent=15 -XX:InitialHeapSize=34359738368(32GB) 
-XX:MarkStackSize=4194304 -XX:MaxGCPauseMillis=200 -XX:MaxHeapSize=34359738368 
-XX:MaxNewSize=20602421248 -XX:MinHeapDeltaBytes=16777216 
-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC 

and the full gc logs:

2023-10-06T08:31:44.068+0800: 659309.919: 
[Full GC (Allocation Failure)  23G->21G(32G), 19.5437974 secs] [Eden: 16.0M(6000.0M)->0.0B(6544.0M) Survivors: 544.0M->0.0B 
Heap: 23.8G(32.0G)->21.3G(32.0G)], [Metaspace: 90182K->90182K(94208K)] 
[Times: user=27.33 sys=1.05, real=19.54 secs] 

2023-10-06T09:15:45.544+0800: 661951.395: [Full GC (Allocation Failure)  31G->20G(32G), 14.5219354 secs]
   [Eden: 0.0B(6544.0M)->0.0B(6544.0M) Survivors: 0.0B->0.0B Heap: 31.7G(32.0G)->20.4G(32.0G)], [Metaspace: 90216K->90216K(94208K)]
 [Times: user=19.32 sys=1.00, real=14.52 secs] 

2023-10-06T09:47:37.129+0800: 663862.980: [Full GC (Allocation Failure)  31G->20G(32G), 15.0624531 secs]
   [Eden: 0.0B(6544.0M)->0.0B(6544.0M) Survivors: 0.0B->0.0B Heap: 31.7G(32.0G)->20.5G(32.0G)], [Metaspace: 90217K->90199K(94208K)]
 [Times: user=18.48 sys=2.25, real=15.06 secs] 

2023-10-06T10:11:54.450+0800: 665320.301: [Full GC (Allocation Failure)  31G->20G(32G), 14.5384049 secs]
   [Eden: 0.0B(6544.0M)->0.0B(6544.0M) Survivors: 0.0B->0.0B Heap: 31.7G(32.0G)->20.7G(32.0G)], [Metaspace: 90217K->90202K(94208K)]
 [Times: user=18.65 sys=1.60, real=14.54 secs] 

2023-10-06T10:36:51.857+0800: 666817.708: [Full GC (Allocation Failure)  31G->20G(32G), 14.1996159 secs]
   [Eden: 0.0B(6544.0M)->0.0B(6544.0M) Survivors: 0.0B->0.0B Heap: 31.7G(32.0G)->20.7G(32.0G)], [Metaspace: 90213K->90205K(94208K)]
 [Times: user=18.68 sys=1.30, real=14.20 secs] 

2023-10-06T11:00:10.119+0800: 668215.970: [Full GC (Allocation Failure)  31G->20G(32G), 14.1973267 secs]
   [Eden: 0.0B(6544.0M)->0.0B(6544.0M) Survivors: 0.0B->0.0B Heap: 31.7G(32.0G)->20.8G(32.0G)], [Metaspace: 90218K->90211K(94208K)]
 [Times: user=19.31 sys=0.77, real=14.20 secs] 

the gc param G1ReservePercent=15 means that G1 will ensure at least 15% free space as pointed in gceasy

Sets the percentage of reserve memory to keep free. The default is 10 percent. G1 Garbage collectors will try to keep 10% of the heap to be free always.

Which means g1 will start a (old? mixed?) gc to match the G1ReservePercent constraint when heap grows up to about 27G (85% of 32G).

But the full gc log 31.7G(32.0G)->20.8G(32.0G) shows that the heap has exhausted, it's too late to start a non full gc.

So what's wrong with the full gc problem and why G1ReservePercent param doesn't work.

Upvotes: 0

Views: 126

Answers (0)

Related Questions