G1GC的延迟问题

Posted

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了G1GC的延迟问题相关的知识，希望对你有一定的参考价值。

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

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

服务延迟的增加与GarbageCollection指标的增加相匹配。

服务规格

我在M4-2X Large EC2盒子上运行一个java应用程序（JDK-8），每盒有50个活动线程。服务运行在12GB堆。请求的平均延迟约为250毫秒，传入请求的速率约为每箱约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 Causes

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%

Tenuring summary

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
答案

第一点是

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

但是G1GC中可以有一个参数，您可以分析：

Humongous Objects

此时，除了最大的弱点/复杂性Humongous对象之外，G1GC的大部分功能和体系结构已被刷新。如前所述，任何单个数据分配≥G1HeapRegionSize/ 2都被视为Humongous对象，它是从Free space的连续区域分配的，然后将其添加到Tenured。让我们了解一些基本特征以及它们如何影响正常的GC生命周期。以下关于Humongous对象的讨论将提供对Humongous对象的缺点的深入了解，例如：

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

Humongous对象是从Free Space分配的。分配失败会触发GC事件。如果来自可用空间的分配失败触发GC，则GC事件将是完整GC，这在大多数情况下是非常不合需要的。为了避免在具有大量Humongous对象的应用程序中发生完整GC事件，必须确保自由空间池足够大，与伊甸园相比，Eden将始终首先填满。人们通常最终会过于谨慎，应用程序最终处于Free ram池非常庞大并且从未被充分利用的状态，根据定义，浪费RAM。

在MPCMC结束时释放出巨大的物体

直到Oracle JDK 8u45周围，确实只在MPCMC运行结束时收集了Humongous对象。 Oracle 8u45-8u65版本的发行说明中有一些提交，表明在Minor事件期间收集了一些但不是全部的Humongous对象。

所以，你可以尝试更新最新的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

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

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

另一答案

这是一个年轻的收藏品，几乎所有的东西都很年轻，所以与上面的评论相反，这似乎不是老一代填补的问题。

[Ext Root Scanning (ms): Min: 0.0, Avg: 140.9, Max: 2478.3, Diff: 2478.3, Sum: 2818.8]

它基本上花费大部分时间扫描GC根，然后其他阶段等待这个阶段完成。

你有很多线程（你只提到活跃的线程）？或者您的应用程序泄漏类或动态生成越来越多的字节码？

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

您首先必须弄清楚这些生成的类是否在旧代集合中被收集。如果没有，你有泄漏，需要修复你的应用程序。如果它们堆积起来但最终被收集起来，你只需要更频繁地收集老一代，例如通过减少年轻一代的规模（这对老一代产生更大的压力）或减少IHOP。

另一答案

如果我在你的位置，这就是我要做的。

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

调整G1垃圾收集器以适合您的服务非常重要。没有任何调整的G1可能对我们的一些服务非常糟糕，这些服务的性能比并行收集器差得多。但现在通过特定的调整，它现在在我们的服务器上运行得更好，它有64个内核和256 GB RAM。

另一答案

首先，你花了很多时间在几代之间复制对象。

G1疏散暂停263 259 ms 560 ms 1 min 8 sec 50 ms 91.61％

根据这个

[伊甸园：5512.0M（5512.0M） - > 0.0B（4444.0M）幸存者：112.0M-> 128.0M堆：8222.2M（12.0G） - > 2707.5M（12.0G）]

[对象复制（毫秒）：最小值：0.0，平均值：41.9，最大值：68.7，差值：68.7，总和：837.9]

[更新RS（毫秒）：最小值：0.0，平均值：5.3，最大值：41.9，差值：41.9，总和：106.9]

参考程序：37.7毫秒

[Ext Root Scanning（ms）：Min：0.0，Avg：140.9，Max：2478.3，Diff：2478.3，Sum：2818.8]

这都是关于管理区域之间的对象。看起来你有很多短时间的生活对象，但是花了很多时间来管理区域之间的对象。尝试使用Young Gen大小。从一侧你可以增加它，这样你就可以花更少的时间来复制对象。它也可以增加根分析的时间。如果大多数物体都死了就没问题。但如果没有，你应该相反地减少Young Size，然后更频繁地调用G1，但是一次调用花费的时间更少，这提供了更多的预测行为和延迟。我们可以看到最大的时间用在根分析上，我会先将Young Gen的大小减少到3GB，看看会发生什么。

第二是

终止（ms）：Min：0.0，Avg：2282.3，Max：2415.8，Diff：2415.8，Sum：45645.3]

你的G1花了很多时间在终止进程上，它尝试完成线程工作，但在此之前，它会检查所有队列并窃取任务。你可以看到有很多偷窃的企图：

终止尝试：最小值：1，平均值：21.5，最大值：68，差值：67，总和：430

每个工作线程21.5次尝试不是一点点。如果工作线程成功窃取任务，它将继续。你在这里有很大的并发性，我想你可以减少GC线程的数量。

附：要选择GC，您应该使用：

  1. 并行GC，如果不合适那么......
  2. G1，如果不合适则......
  3. 使用ParNew调整CMS。

如果我是你，我会在你的地方使用带有ParNew的CMS来为这种情况提供良好的延迟。

另见understanding G1 logs

另一答案

我主要关心的是这个

[Ext Root Scanning（ms）：Min：0.0，Avg：140.9，Max：2478.3，Diff：2478.3，Sum：2818.8]

这篇文章中的某个人询问你是否生成了大量的动态类。如果你这样做，那么为什么Ext Root Scanning会很长。

另一方面，争夺资源可能是另一个原因。你说你使用的是M4-2X Large EC2盒子。根据这个[https://aws.amazon.com/ec2/instance-types/][1]，这台机器有8个虚拟核心。

当只有8个核心时，将GC工作器的数量设置为20。因此，即使安排Gc工作人员也存在争议。可能还有其他系统资源正在竞争CPU。因此，GC工作线程可能会被安排延迟，导致根扫描阶段显得很大。

它还会导致终止阶段很大。因为其他线程会先完成。

你谈到增加Gc工作线程，将其设置为8或更低可能甚至6可能有帮助。这值得一试。

我看到这篇帖子很久以前就被问过了。如果你确实设法解决它，我很想知道你做了什么。

以上是关于G1GC的延迟问题的主要内容，如果未能解决你的问题，请参考以下文章

片段未附加到上下文 - 延迟的 UI 更改

angularJS使用ocLazyLoad实现js延迟加载

片段布局加载延迟

# Java 常用代码片段

# Java 常用代码片段

Android：BottomNavigationView第一个片段开关超级延迟