I'm running a heavy Java database process with a massive heap (80GB) in Java 10 using the parallel collector. Typically, minor collections take about a few hundred milliseconds which is fine for my use case, but occasionally a minor collection will stall for 40+ seconds! This happens pretty reliably after the process has been restarted and has run for a little while. It doesn't seem to happen again after that first really long stall.
Here are the GC-related JVM arguments:
-Xms82329M
-Xmx82329M
-server
-XX:-UseAdaptiveSizePolicy
-XX:+UseParallelGC
-XX:NewRatio=1
-XX:MetaspaceSize=256M
-XX:MaxMetaspaceFreeRatio=100
The young generation is purposefully big because there is very little tenured data in the application, so most stuff is short-lived. And I am using the parallel collector because throughput is more important than latency -- both CMS and G1 have not performed as well despite a lot of attempts and tuning.
I'd expect minor collections to have pretty consistent pause times, which seems to be in the 100ms - 1s range for a heap of this size on the hardware I am using. However, I'll see this massive pause once after the application restarts:
[755.986s][info][gc,start ] GC(36) Pause Young (Allocation Failure)
[756.634s][info][gc,heap ] GC(36) PSYoungGen: 35519441K->5123933K(36883968K)
[756.634s][info][gc,heap ] GC(36) ParOldGen: 3724708K->3858421K(42152960K)
[756.634s][info][gc,metaspace] GC(36) Metaspace: 80750K->80750K(83968K)
[756.634s][info][gc ] GC(36) Pause Young (Allocation Failure) 38324M->8771M(77184M) 647.490ms
[756.634s][info][gc,cpu ] GC(36) User=8.19s Sys=0.18s Real=0.65s
[794.053s][info][gc,start ] GC(37) Pause Young (Allocation Failure)
[794.563s][info][gc,heap ] GC(37) PSYoungGen: 36738909K->4366281K(36883968K)
[794.563s][info][gc,heap ] GC(37) ParOldGen: 3858421K->3963277K(42152960K)
[794.563s][info][gc,metaspace] GC(37) Metaspace: 80798K->80798K(83968K)
[794.563s][info][gc ] GC(37) Pause Young (Allocation Failure) 39645M->8134M(77184M) 509.611ms
[794.563s][info][gc,cpu ] GC(37) User=6.58s Sys=0.00s Real=0.51s
[815.779s][info][gc,start ] GC(38) Pause Young (GCLocker Initiated GC)
[857.527s][info][gc,heap ] GC(38) PSYoungGen: 35981257K->4362580K(36883968K)
[857.527s][info][gc,heap ] GC(38) ParOldGen: 3964998K->4400719K(42152960K)
[857.527s][info][gc,metaspace] GC(38) Metaspace: 80829K->80829K(83968K)
[857.527s][info][gc ] GC(38) Pause Young (GCLocker Initiated GC) 39010M->8557M(77184M) 41747.938ms
[857.527s][info][gc,cpu ] GC(38) User=490.02s Sys=37.81s Real=41.75s
[891.176s][info][gc,start ] GC(39) Pause Young (Allocation Failure)
[892.388s][info][gc,heap ] GC(39) PSYoungGen: 35977556K->3944941K(36883968K)
[892.388s][info][gc,heap ] GC(39) ParOldGen: 4400819K->4562823K(42152960K)
[892.388s][info][gc,metaspace] GC(39) Metaspace: 81005K->81005K(83968K)
[892.388s][info][gc ] GC(39) Pause Young (Allocation Failure) 39432M->8308M(77184M) 1211.876ms
[892.388s][info][gc,cpu ] GC(39) User=15.71s Sys=0.00s Real=1.21s
[908.175s][info][gc,start ] GC(40) Pause Young (GCLocker Initiated GC)
[909.530s][info][gc,heap ] GC(40) PSYoungGen: 35559917K->4160137K(36883968K)
[909.530s][info][gc,heap ] GC(40) ParOldGen: 4689915K->4869881K(42152960K)
[909.530s][info][gc,metaspace] GC(40) Metaspace: 81022K->81022K(83968K)
[909.530s][info][gc ] GC(40) Pause Young (GCLocker Initiated GC) 39306M->8818M(77184M) 1355.504ms
[909.530s][info][gc,cpu ] GC(40) User=17.56s Sys=0.00s Real=1.35s
[939.139s][info][gc,start ] GC(41) Pause Young (Allocation Failure)
[939.980s][info][gc,heap ] GC(41) PSYoungGen: 35775113K->3953721K(36883968K)
[939.980s][info][gc,heap ] GC(41) ParOldGen: 4869884K->4950314K(42152960K)
[939.980s][info][gc,metaspace] GC(41) Metaspace: 81049K->81049K(83968K)
[939.980s][info][gc ] GC(41) Pause Young (Allocation Failure) 39692M->8695M(77184M) 840.700ms
[939.980s][info][gc,cpu ] GC(41) User=11.30s Sys=0.00s Real=0.84s
[957.230s][info][gc,start ] GC(42) Pause Young (Allocation Failure)
[957.713s][info][gc,heap ] GC(42) PSYoungGen: 35568697K->2973501K(36883968K)
[957.713s][info][gc,heap ] GC(42) ParOldGen: 4950314K->5124031K(42152960K)
[957.713s][info][gc,metaspace] GC(42) Metaspace: 81110K->81110K(83968K)
[957.713s][info][gc ] GC(42) Pause Young (Allocation Failure) 39569M->7907M(77184M) 482.476ms
[957.713s][info][gc,cpu ] GC(42) User=6.07s Sys=0.11s Real=0.49s
[971.819s][info][gc,start ] GC(43) Pause Young (GCLocker Initiated GC)
[972.230s][info][gc,heap ] GC(43) PSYoungGen: 34588477K->3388436K(36883968K)
[972.230s][info][gc,heap ] GC(43) ParOldGen: 5126669K->5177301K(42152960K)
[972.230s][info][gc,metaspace] GC(43) Metaspace: 81144K->81144K(83968K)
[972.230s][info][gc ] GC(43) Pause Young (GCLocker Initiated GC) 38784M->8364M(77184M) 410.974ms
[972.231s][info][gc,cpu ] GC(43) User=5.29s Sys=0.00s Real=0.40s
You'll notice in the middle of the GC logs there is a 40+ second minor collection that has most of the same characteristics as the other minor collections around it (space cleaned up, moved to old generation, etc). So I really can't understand why this reliably happens once after the JVM has been restarted. Any help would be appreciated!