G1GC存在延迟问题

Question

我使用G1GC算法遇到了持续增加的GC暂停时间问题。服务延迟随着时间的推移而不断增长。 一旦这种情况发生，我就重新启动我的服务，延迟时间就会恢复正常。在启动后，延迟时间会再次随着时间的推移而增加。

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

服务延迟的增加与垃圾回收指标的增加相匹配。

服务规格

我在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 原因

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

- Santano

---

嗯嗯……内存泄漏了。你正在填满老年代，因此G1越来越难以找到放置新物品的位置。 - Boris the Spider

而且...如果这是一个内存泄漏，那么调整GC配置也无法解决问题。 - Stephen C

可能与 https://stackoverflow.com/q/41238782/1654233 相关。 - yegodm

我同意其他人的观点，你可能更应该关注为什么你的应用程序如此依赖GC。试着关注GC必须清理的内容，以至于它会导致延迟。你真的关闭了你使用的所有资源（连接、文件、I/O流、SQL语句、结果集、POI工作簿等）吗？在100,000个循环中，你是否有未被注意到的自动装箱（该死的Java这个丑陋的特性）？你是否忘记了数组或集合上的活动引用？ - Honza Zidek

我有一个朋友，她在小公寓里放置所有的东西都有问题。她搬进了一个更大的公寓，但一个月后她的新公寓又挤满了 :) - Honza Zidek

Answer 1

第一点是：

你需要检查你的应用程序中是否存在连接泄漏。

但是在G1GC中可能会有一个参数可以分析：

庞大对象

此时，G1GC的大多数功能和架构已经得到了充分的展开，除了最大的弱点/复杂性——庞大对象。如前所述，任何单个数据分配≥ G1HeapRegionSize/2都被视为庞大对象，这些对象从自由空间的连续区域中分配，然后添加到Tenured。让我们来看一些基本特征以及它们对正常GC生命周期的影响。下面对庞大对象的讨论将提供有关庞大对象不利方面的见解，例如：

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

巨大对象是从Free空间中分配的。分配失败会触发GC事件。如果来自Free空间的分配失败触发了GC，则GC事件将是Full GC，这在大多数情况下非常不可取。为了避免在具有大量巨大对象的应用程序中发生Full GC事件，必须确保Free空间池足够大，以使Eden始终首先填满。通常会过于谨慎，导致应用程序进入Free RAM池相当大且从未完全利用的状态，这定义为浪费RAM。

在MPCMC结束时释放巨大对象。

直到Oracle JDK 8u45左右，巨大对象仅在MPCMC运行结束时收集。 Oracle 8u45-8u65版本的发布说明显示了一些但不是全部的提交，表明一些巨大对象在Minor事件期间被收集。

所以，您可以尝试更新最新的Java。

只能在MPCMC结束时才能收集的巨大对象将增加保留Free空间的要求或更容易触发Full 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

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

但最后，如果您的应用程序存在内存泄漏，则必须解决该问题。

- Sahil Aggarwal

---

有时在分析 Eclipse 内存分析器工具中的堆转储时，很难找到大小较大的对象，在这种情况下，您可以使用 jvisualvm，它显示按大小排序的每个实例列表。 - Sahil Aggarwal

Answer 2

这是一个年轻的收藏，几乎所有东西都死得很快。因此，与上面的评论相反，这似乎不是老一代积压的问题。

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

这基本上是花费大部分时间扫描GC根，其他阶段稍后才能完成。

您有很多线程吗（您只提到了活动的线程）？还是您的应用程序正在泄漏类或动态生成越来越多的字节码？

对于每个服务调用，该应用程序会动态生成很多类，鉴于呼叫量，我怀疑这些类可能存在问题，但不确定如何解决。

首先，您需要确定那些生成的类是否在老年代垃圾回收期间被收集。如果没有收集，您就需要修复应用程序中的泄漏问题。如果它们堆积但最终被收集，您只需要更频繁地进行老年代垃圾回收，例如通过减小年轻代大小（增加老年代压力）或减少IHOP。

- the8472

---

所有应用程序线程都是活动的。这些盒子在一个带有48个连接的VIP后面运行，每个盒子运行50个线程。 - Santano

我在问题中添加了tenuring摘要，并且我看到对象移动到老年代的分布比较均匀。应用程序为每个服务调用动态生成许多类，鉴于呼叫量，我怀疑这些类可能是一个问题，但不确定如何解决它。 - Santano

您希望并发循环运行更频繁，而不是更少，这样类就可以被卸载，从而使年轻的收集变得更便宜。这是在假设它们只是被终身使用而没有实际泄漏的情况下。此外，终身分布不会与我所说的任何内容相矛盾，因为大多数东西都死在伊甸园。 - the8472

不，减少IHOP - the8472

Answer 3

如果我处于你的位置，这是我会做的事情：

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

调整G1垃圾收集器以适应您的服务非常重要。没有任何调整的G1可能对某些服务非常糟糕，例如我们遇到的情况，表现比Parallel收集器差得多。但是现在通过特定的调整，在我们具有64个核心和256 GB RAM的服务器上运行得更好了。

- keerthi

Answer 4

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

G1疏散暂停 263 259毫秒 560毫秒 1分钟8秒50毫秒 91.61％。

根据这个。

[Eden: 5512.0M(5512.0M)->0.0B(4444.0M) Survivors: 112.0M->128.0M Heap: 8222.2M(12.0G)->2707.5M(12.0G)] [Object Copy (ms): Min: 0.0, Avg: 41.9, Max: 68.7, Diff: 68.7, Sum: 837.9] [Update RS (ms): Min: 0.0, Avg: 5.3, Max: 41.9, Diff: 41.9, Sum: 106.9] Ref Proc: 37.7 ms [Ext Root Scanning (ms): Min: 0.0, Avg: 140.9, Max: 2478.3, Diff: 2478.3, Sum: 2818.8]

这段内容是关于管理不同区域之间对象的。看起来你有很多短生命周期的对象，但花费了很多时间在不同区域对象之间的管理上。尝试调整年轻代大小。一方面，你可以增加它，这样你将花费更少的时间进行对象复制。这也可能增加根分析的时间。如果大多数对象都已死亡，那么这样做是可以的。但如果不是，相反地，你应该减小年轻代大小，这样G1会更频繁地被调用，但每次调用所需的时间更短，这提供了更可预测的行为和延迟。正如我们所看到的，最大的时间花费在根分析上，我建议从减小年轻代大小开始尝试，将其设置为3GB，看看会发生什么。

第二个问题是

终止时间（ms）：最小值：0.0，平均值：2282.3，最大值：2415.8，差异：2415.8，总和：45645.3]

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

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

每个工作线程平均尝试21.5次并不算多。如果工作线程成功窃取任务，则会继续执行。你的并发性很高，我认为你可以减少GC线程的数量。

附注：选择GC时应使用以下方法：

1. 如果不适合，请使用Parallel GC；

2. 如果不适合，请使用G1；

3. 使用调整过的CMS与ParNew。

如果是我，我会在您的位置上使用CMS与ParNew来提供此场景的良好延迟。

另请参见理解G1日志。

- egorlitvinenko

Answer 5

我主要关注这个问题

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

在这篇文章中，有人问你是否正在生成大量的动态类。如果是的话，那么 Ext Root Scanning 时间长也许就是真的。

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

当你只有 8 个核心时，你将 GC worker 的数量设置为 20。结果很可能会导致甚至调度 Gc worker 都存在争用。还可能有其他系统资源也在争用 CPU。因此，GC worker 线程可能会被延迟调度，导致 Root Scanning 阶段看起来很长。

这也会导致终止阶段变得很长。因为其他线程会先完成。

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

我看到这篇文章是很久以前问的。如果你成功解决了它，我很想知道你是怎么做的。

- Laxman Prabhu