java - 在大堆上使用并行收集器的次要收集时间极长

Question

我正在使用并行收集器在 Java 10 中运行具有大量堆 (80GB) 的重型 Java 数据库进程。通常，次要收集大约需要几百毫秒，这对我的用例来说很好，但有时次要收集会停顿 40 多秒！在进程重新启动并运行一段时间后，这种情况非常可靠地发生。在第一次非常长的失速之后，它似乎不再发生。

以下是与 GC 相关的 JVM 参数：

-Xms82329M
-Xmx82329M
-server
-XX:-UseAdaptiveSizePolicy
-XX:+UseParallelGC
-XX:NewRatio=1
-XX:MetaspaceSize=256M
-XX:MaxMetaspaceFreeRatio=100

年轻一代故意变大，因为应用程序中的终身数据很少，所以大多数东西都是短暂的。我正在使用并行收集器，因为吞吐量比延迟更重要——尽管进行了很多尝试和调整，CMS 和 G1 都没有表现得那么好。

我希望次要集合具有相当一致的暂停时间，对于我正在使用的硬件上的这种大小的堆，它似乎在 100 毫秒 - 1 秒的范围内。但是，在应用程序重新启动后，我会看到这种巨大的暂停：

[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

您会注意到在 GC 日志中间有一个 40 多秒的次要收集，它与周围的其他次要收集具有大部分相同的特征（清理空间、移至老年代等）。所以我真的不明白为什么在 JVM 重新启动后这种情况可靠地发生一次。任何帮助，将不胜感激！

标签： javagarbage-collection