G1 GC — 极长的终止时间答案

【问题标题】：G1 GC — extremely long termination timeG1 GC — 极长的终止时间
【发布时间】：2017-08-23 20:05:15
【问题描述】：

G1 GC 有时会在终止阶段花费大量时间。正如您所见，GC 工作人员的平均时间为 442.9，终止时间为 327.3。那是处理大量消息的高性能低延迟应用程序。事件处理数据必须由 yong gc 收集。通常事件处理时间不超过 150 毫秒。

硬件：x24 Intel(R) Xeon(R) CPU E5-2620 v3 @ 2.40GHz，32Gb mem，8Gb mem 是免费的 JVM 选项：-server -XX:+UseG1GC -XX:MaxGCPauseMillis=60 -XX:ParallelGCThreads=24 -Xmx12g -Xms12g -Xss256k Linux 2.6.32-696.6.3.el6.x86_64 java版本“1.8.0_102”

通常 G1 将新大小设置为 7Gb，young GC 暂停为 50ms，终止时间仅为 6ms，收集之间的间隔为 3 秒。

如果应用程序产生了很多长生命周期的对象，那么年轻的停顿会增加，这也会导致年轻的 GC 大小减小。但在这种情况下，终止时间保持不变。我想知道为什么终止时间会如此显着增加。

请注意此暂停的大系统时间。通常 GC 暂停的系统时间为 0-10ms。对于这个，它是 1 秒。

2017-08-23T13:21:37.690-0400: 1509.022: [GC pause (G1 Evacuation Pause) (young), 0.4474119 secs]
   [Parallel Time: 443.2 ms, GC Workers: 24]
      [GC Worker Start (ms): Min: 1509022.9, Avg: 1509023.0, Max: 1509023.4, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 2.1, Avg: 22.5, Max: 90.4, Diff: 88.3, Sum: 539.7]
      [Update RS (ms): Min: 0.0, Avg: 2.2, Max: 5.0, Diff: 5.0, Sum: 54.0]
         [Processed Buffers: Min: 0, Avg: 24.7, Max: 67, Diff: 67, Sum: 592]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 26.1, Avg: 106.1, Max: 435.6, Diff: 409.6, Sum: 2545.3]
      [Termination (ms): Min: 0.0, Avg: 312.0, Max: 327.3, Diff: 327.3, Sum: 7488.6]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 4, Diff: 3, Sum: 36]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.6]
      [GC Worker Total (ms): Min: 442.5, Avg: 442.9, Max: 443.0, Diff: 0.5, Sum: 10628.9]
      [GC Worker End (ms): Min: 1509465.9, Avg: 1509465.9, Max: 1509465.9, Diff: 0.1]
   [Code Root Fixup: 0.4 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 3.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.3 ms]
   [Eden: 476.0M(476.0M)->0.0B(556.0M) Survivors: 136.0M->56.0M Heap: 4480.6M(12.0G)->4016.3M(12.0G)]
 [Times: user=4.23 sys=1.08, real=0.45 secs]

【问题讨论】：

由于 Object Copy 次数较高：可能与 Java garbage collector G1GC taking long for 'Object Copy' (Evacuation Pause) 重复

标签： java garbage-collection g1gc

【解决方案1】：

我有一个建议。有时，当系统上运行其他进程时，它们会与您的 Java GC 工作人员竞争。

[对象复制（毫秒）：最小值：26.1，平均值：106.1，最大值：435.6，差异：409.6，总和：2545.3] [Ext Root Scanning (ms): Min: 2.1, Avg: 22.5, Max: 90.4, Diff: 88.3, Sum: 539.7]

从上面的日志中，看起来 GC 工作人员正在做不成比例的工作。这意味着大多数 GC 线程提前完成，其中一些仍在工作。当这种情况发生时，已完成的线程会尝试从其他人那里窃取工作。这反映在终止时间上。因此，终止时间不是原因，而只是副作用。

[终止（毫秒）：Min：0.0，Avg：312.0，Max：327.3，Diff：327.3，Sum：7488.6]

您有一台 24 核机器和 24 个 GC 工作线程。如果有其他进程或系统活动需要 CPU 资源，则可能有一些 GC 工作人员因争用而延迟调度。

值得尝试将线程数减少到 18 个并试一试。

您还可以增加 gc 日志级别，当您这样做时，它会打印每个线程的开始时间。这有助于调试应用程序。

【讨论】：