为什么 Java G1 gc 花费这么多时间扫描 RS？

我目前正在评估 G1 垃圾收集器及其在我们的应用程序中的执行情况。查看 gc-log，我注意到很多集合都有很长的“Scan RS”阶段：

7968.869: [GC pause (mixed), 10.27831700 secs]
   [Parallel Time: 10080.8 ms]
   (...)
      [Scan RS (ms):  4030.4  4034.1  4032.0  4032.0
       Avg: 4032.1, Min: 4030.4, Max: 4034.1, Diff:   3.7]
      [Object Copy (ms):  6038.5  6033.3  6036.7  6037.1
       Avg: 6036.4, Min: 6033.3, Max: 6038.5, Diff:   5.2]
   (...)
    [Eden: 19680M(19680M)->0B(20512M) Survivors: 2688M->2624M Heap:
     75331M(111904M)->51633M(115744M)]
 [Times: user=40.49 sys=0.02, real=10.28 secs] 

所有删除的日志行条目均以个位数毫秒显示运行时间。

我想大部分时间应该花在抄写上吧？ Scan RS 花费这么长时间的原因可能是什么？关于如何调整 G1 设置有什么想法吗？ JVM 启动于

-Xms40960M -Xmx128G -XX:+UseG1GC -verbose:gc -XX:+PrintGCDetails -Xloggc:gc.log

编辑：哦，我忘了......我正在使用 Java 7u25

Update:我还注意到另外两件奇怪的事情：

16187.740: [GC concurrent-mark-start]
16203.934: [GC pause (young), 2.89871800 secs]
(...)
16218.455: [GC pause (young), 4.61375100 secs]
(...)
16237.441: [GC pause (young), 4.46131800 secs]
(...)
16257.785: [GC pause (young), 4.73922600 secs]
(...)
16275.417: [GC pause (young), 3.87863400 secs]
(...)
16291.505: [GC pause (young), 3.72626400 secs]
(...)
16307.824: [GC pause (young), 3.72921700 secs]
(...)
16325.851: [GC pause (young), 3.91060700 secs]
(...)
16354.600: [GC pause (young), 5.61306000 secs]
(...)
16393.069: [GC pause (young), 17.50453200 secs]
(...)
16414.590: [GC concurrent-mark-end, 226.8497670 sec]

在执行并行运行的同时，并发 GC 运行仍在继续。我不确定这是否是有意的，但对我来说这似乎有点不对。诚然，这是一个极端的例子，但我确实在我的日志中看到了这种行为。

另一件事是我的 JVM 进程增长到了 160g。考虑到 128g 的堆大小，这是一个相当大的开销。这是预期的结果，还是 G1 内存泄漏？关于如何找出答案有什么想法吗？

PS：我不太确定我是否应该为更新提出新问题...如果你们中有人认为这会有所帮助，请告诉我；）

更新2：我猜 G1 确实可能存在内存泄漏：http://printfdebugger.tumblr.com/post/19142660766/how-i-learned-to-love-cms-and-had-my-heart-broken-by-g1由于目前这是一个破坏性的事情，我不会花更多的时间来解决这个问题。 我尚未尝试的事情是配置区域大小（-XX：G1HeapRegionSize）并降低堆占用率（-XX：InitiatingHeapOccupancyPercent）。

让我们来看看。

1 - 第一个线索

看起来您的 GC 已配置为使用 4 个线程（或者您有 4 个 vCPU，但考虑到堆的大小，这不太可能）。对于 128GB 堆来说，这个值相当低，我本来期望更多。

GC 事件似乎以 25 秒以上的间隔发生。但是，您提供的日志摘录并未提及已处理的区域数量。

=> 无论如何，您是否为 G1GC 指定了暂停时间目标（-XX:MaxGCPauseMillis=N) ?

2 - 长扫描 RSet 时间

“Scan RSet”是指 GC 扫描 Remembered Sets 所花费的时间。区域的记住集包含与指向该区域的引用相对应的卡片。此阶段扫描那些卡片，查找指向集合集所有区域的引用。

那么在这里，我们还有一个问题：

=> 在该特定集合期间处理了多少个区域（即 CSet 有多大）

3 - 对象复制时间长

复制时间，顾名思义，是每个工作线程将活动对象从集合集中的区域复制到其他区域所花费的时间。

如此长的复制时间可能表明处理了很多区域，并且您可能需要减少该数量。它还可能建议交换，但考虑到日志末尾的用户/实际值，这种可能性很小。

4 - 现在该怎么办

您应该在 GC 日志中检查已处理的区域数量。将此数字与您的区域大小相关联，并推断出扫描的内存量。

然后，您可以设置较小的暂停时间目标（例如，使用 500 毫秒）-XX:MaxGCPauseMillis=500）。这会

• 增加 GC 事件的数量，
• 减少每个 GC 周期释放的内存量
• 减少 YGC 期间 STW 暂停

希望有帮助！

资料来源：

• https://blogs.oracle.com/poonam/entry/understanding_g1_gc_logs
• http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/G1GettingStarted/index.html
• http://jvm-options.tech.xebia.fr/