延迟问题，G1GC

Question

我正面临着使用G1GC算法的GC暂停的持续增加。随着时间的推移，服务延迟会继续增长。一旦发生这种情况，我重新启动我的服务，延迟就会恢复正常。启动后，延迟又会随着时间的推移继续增加。

在启动时，服务延迟约为200ms，但在24小时内，它们会上升到350ms，并继续以线性方式增加。

服务延迟的增加与GarbageCollection度量的增加相匹配。

服务规范

我在M4-2X大型EC2机器上运行java应用程序(JDK-8)，每个机器有50个活动线程。服务在12 at的堆上运行。请求的平均延迟约为250ms，传入请求的速率约为每秒20个/盒。

G1G1配置

        <jvmarg line="-Xms12288M"/>
        <jvmarg line="-Xmx12288M"/>

        <jvmarg line="-verbose:gc" />
        <jvmarg line="-XX:+UseG1GC"/>
        <jvmarg line="-XX:+PrintGCDetails" />
        <jvmarg line="-XX:+PrintGCTimeStamps" />
        <jvmarg line="-XX:+PrintTenuringDistribution" />
        <jvmarg line="-XX:+PrintGCApplicationStoppedTime" />
        <jvmarg line="-XX:MaxGCPauseMillis=250"/>
        <jvmarg line="-XX:ParallelGCThreads=20" />
        <jvmarg line="-XX:ConcGCThreads=5" />
        <jvmarg line="-XX:-UseGCLogFileRotation"/>

GC日志

79488.355: Total time for which application threads were stopped: 0.0005309 seconds, Stopping threads took: 0.0000593 seconds
79494.559: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 369098752 bytes, new threshold 15 (max 15)
- age   1:   64725432 bytes,   64725432 total
- age   2:    8867888 bytes,   73593320 total
- age   3:    2503592 bytes,   76096912 total
- age   4:     134344 bytes,   76231256 total
- age   5:    3729424 bytes,   79960680 total
- age   6:     212000 bytes,   80172680 total
- age   7:     172568 bytes,   80345248 total
- age   8:     175312 bytes,   80520560 total
- age   9:     282480 bytes,   80803040 total
- age  10:     160952 bytes,   80963992 total
- age  11:     140856 bytes,   81104848 total
- age  12:     153384 bytes,   81258232 total
- age  13:     123648 bytes,   81381880 total
- age  14:      76360 bytes,   81458240 total
- age  15:      63888 bytes,   81522128 total
, 2.5241014 secs]
   [Parallel Time: 2482.2 ms, GC Workers: 20]
      [GC Worker Start (ms): Min: 79494558.9, Avg: 79494567.4, Max: 79494602.1, Diff: 43.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 140.9, Max: 2478.3, Diff: 2478.3, Sum: 2818.8]
      [Update RS (ms): Min: 0.0, Avg: 5.3, Max: 41.9, Diff: 41.9, Sum: 106.9]
         [Processed Buffers: Min: 0, Avg: 23.2, Max: 80, Diff: 80, Sum: 465]
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 4.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
      [Object Copy (ms): Min: 0.0, Avg: 41.9, Max: 68.7, Diff: 68.7, Sum: 837.9]
      [Termination (ms): Min: 0.0, Avg: 2282.3, Max: 2415.8, Diff: 2415.8, Sum: 45645.3]
         [Termination Attempts: Min: 1, Avg: 21.5, Max: 68, Diff: 67, Sum: 430]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.1, Sum: 1.0]
      [GC Worker Total (ms): Min: 2435.8, Avg: 2470.7, Max: 2482.0, Diff: 46.2, Sum: 49414.5]
      [GC Worker End (ms): Min: 79497037.9, Avg: 79497038.1, Max: 79497041.0, Diff: 3.1]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.9 ms]
   [Other: 40.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 37.7 ms]
      [Ref Enq: 0.8 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 1.3 ms]
   [Eden: 5512.0M(5512.0M)->0.0B(4444.0M) Survivors: 112.0M->128.0M Heap: 8222.2M(12.0G)->2707.5M(12.0G)]
 [Times: user=19.63 sys=0.18, real=2.53 secs]
79497.083: Total time for which application threads were stopped: 2.5252654 seconds, Stopping threads took: 0.0000914 seconds

我正在寻找一些GC配置的帮助。根据我的阅读，我计划将并行线程的数量增加到32，将G1HeapRegionSize设置为16M，并将ConcGCThreads设置为8。

    Mixed   Concurrent Mark Remark  Cleanup initial-mark    Young GC    Total
Count   14  4   4   4   4   263 293
Total GC Time   4 sec 120 ms    0   1 sec 100 ms    70 ms   980 ms  1 min 8 sec 10 ms   1 min 14 sec 280 ms
Avg GC Time     294 ms  0   275 ms  17 ms   245 ms  259 ms  254 ms
Avg Time std dev    127 ms  0   73 ms   4 ms    73 ms   63 ms   79 ms
Min/Max Time    0 / 560 ms  0 / 0   0 / 400 ms  0 / 20 ms   0 / 340 ms  0 / 620 ms  0 / 620 ms
Avg Interval Time   2 min 55 sec 119 ms 12 min 32 sec 443 ms    12 min 32 sec 443 ms    12 min 32 sec 449 ms    12 min 32 sec 423 ms    13 sec 686 ms   51 sec 887 ms

GC原因

Cause   Count   Avg Time    Max Time    Total Time  Time %
G1 Evacuation Pause     263 259 ms  560 ms  1 min 8 sec 50 ms   91.61%
GCLocker Initiated GC   15  272 ms  400 ms  4 sec 80 ms 5.49%
Others  12  n/a n/a 1 sec 250 ms    1.68%
G1 Humongous Allocation     3   300 ms  340 ms  900 ms  1.21%
Total   293 n/a n/a 1 min 14 sec 280 ms 99.99%

租期总结

Desired Survivor Size: 448.0 mb,

Max Threshold: 15

Age Survival Count  Average size (kb)   Average Total 'To' size (kb)
age 1   281 54856.84    54856.84
age 2   273 32935.6 89227.65
age 3   258 29812.41    122175.68
age 4   235 28499.48    158266.46
age 5   214 27909.13    196528.23
age 6   192 26896.33    237892.45
age 7   180 25759.58    272516.81
age 8   174 23565.21    299092.37
age 9   166 21745.62    320927.73
age 10  149 19323.6 340228.24
age 11  125 17400.14    357569.6
age 12  96  13995.26    372030.12
age 13  55  10909.19    378053.14
age 14  38  10197.95    389146.13
age 15  22  5996.65 395657.37

Answer 1

第一点是

您需要检查应用程序中是否有任何连接泄漏。

但在G1GC中可以有一个参数，您可以对其进行分析：

宏大对象

在这一点上，除了最大的弱点/复杂性的，巨大的对象之外，G1GC的大部分功能和体系结构都已经被淘汰了。如前所述，任何单个数据分配≥G1HeapRegionSize/2都被认为是一个巨大的对象，它是从空闲空间的连续区域中分配出来的，然后将这些区域添加到租期中。让我们来看一下一些基本特征以及它们如何影响正常的GC生命周期。以下关于大型对象的讨论将深入了解大型对象的缺点，例如：

Increase the risk of running out of Free space and triggering a Full GC
Increase overall time spent in STW

巨大的对象被分配到可用空间之外。分配失败会触发GC事件。如果来自可用空间的分配失败触发了GC，则GC事件将是一个完整的GC，这在大多数情况下是非常不可取的。为了避免在包含大量大型对象的应用程序中发生完整的GC事件，必须确保与Eden相比，可用空间池足够大，Eden总是首先填满。人们通常会过于谨慎，并且应用程序最终会处于空闲RAM池非常大且从未充分利用的状态，这是浪费ram的定义。

大型对象在MPCMC结束时被释放

在OracleJDK8u45之前，确实只在MPCMC运行结束时收集大型对象。Oracle8u45-8u65版本的发行说明有一些提交，表明在小事件期间收集了一些(但不是全部)大型对象。

因此，您可以尝试更新最新的java。

只有在MPCMC结束时才能收集的大型对象会增加对保留可用空间的要求，或者更有可能触发完整的GC。

计算巨型对象的数量：

步骤1.：在gc.log上运行以下命令

命令1：

grep "source: concurrent humongous allocation" /tmp/gc.log | sed 's/.*allocation request: \([0-9]*\) bytes.*/\1/' > humoungous_humongoud_size.txt

命令2：

awk -F',' '{sum+=$1} END{print sum;}' humoungous_humongoud_size.txt

它将提供在我的应用程序中生成的巨大对象的大小。

但最后，如果你的应用程序有内存泄漏，你必须解决这个问题。

Answer 2

这是一个年轻的集合，几乎所有的东西都在年轻时死亡，所以与上面的评论相反，这似乎不是老一辈人填满的问题。

扩展根扫描(毫秒)：最小: 0.0，平均: 140.9，最大: 2478.3，差异: 2478.3，总和: 2818.8

它基本上花费了大部分时间扫描GC根，然后其他阶段被搁置，等待此阶段完成。

你有很多线程吗(你只提到那些活跃的线程)？或者您的应用程序正在泄漏类或动态生成越来越多的字节码？

应用程序为每个服务调用动态生成许多类，考虑到调用量，我怀疑这些类可能是一个问题，但不确定如何解决它。

您首先必须弄清楚这些生成的类在老一代收集过程中是否会被收集。如果没有，你就会有漏洞，需要修复你的应用程序。如果它们堆积在一起，但最终被收集，你只需要更频繁地收集老一代，例如，通过减少年轻一代的大小(这对老一代施加了更大的压力)或通过减少IHOP。

Answer 3

如果我处在你的位置，我就会这么做。

1. 获取几天的GC日志，并将其加载到http://gceasy.io/，以评估内存增长情况。
2. 将垃圾收集机制从G1临时更改为并行收集器。我建议使用并行收集器，因为它以线性方式分配内存，并且相对容易地检查是否有内存泄漏。您还可以将其与G1进行很好的比较。这并不意味着你必须永久地移到并行，它只是暂时的比较。
3. 如果堆以线性方式连续增长而没有被垃圾收集，那么它肯定是内存泄漏，你必须找到它。
4. 如果你看不到任何内存泄漏的证据，那么你可以考虑调整垃圾收集设置。

调整G1垃圾收集器以适应您的服务是非常重要的。没有任何调整的G1可能会对我们所拥有的一些服务非常不利，它们的性能比并行收集器差得多。但现在通过特定的调整，它现在在我们的服务器上工作得更好了，它有64个内核和256 GB的RAM。