【问题标题】:Why is the Java G1 gc spending so much time scanning RS?为什么 Java G1 gc 花费这么多时间扫描 RS?
【发布时间】:2013-07-12 12:18:35
【问题描述】:

我目前正在评估 G1 垃圾收集器以及它在我们的应用程序中的性能。查看 gc-log,我注意到很多集合都有很长的“扫描 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

更新: 我注意到另外两件奇怪的事情:

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)。

【问题讨论】:

  • 160 GB?哇!你在做什么?
  • 全球供应链的内存规划/报告。不是说不能减少占用空间,但对于大客户来说绝对可以是大量数据。
  • 如果你有这么多内存,使用它是有意义的。 JVM 可以处理这么多(尽管我看到了你的问题),这很棒。

标签: garbage-collection jvm-hotspot g1gc


【解决方案1】:

让我们看看。

1 - 第一条线索

看起来您的 GC 配置为使用 4 个线程(或者您有 4 个 vCPU,但考虑到堆的大小,这不太可能)。对于 128GB 的​​堆来说,它是相当低的,我期待更多。

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

=> 有没有给 G1GC (-XX:MaxGCPauseMillis=N) 指定暂停时间目标?

2 - 长扫描 RSet 时间

“Scan RSet”是指GC在扫描Remembered Sets上花费的时间。区域的记忆集包含与指向该区域的引用相对应的卡片。这个阶段扫描那些卡片,寻找指向集合集中所有区域的引用。

所以在这里,我们还有一个问题:

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

3 - 对象复制时间长

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

如此长的复制时间可能表明处理了很多区域,您可能希望减少该数量。它也可能建议交换,但考虑到日志末尾的用户/实际值,这不太可能。

4 - 现在该做什么

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

然后您可以设置一个较小的暂停时间目标(例如,使用-XX:MaxGCPauseMillis=500 设置为 500 毫秒)。这将

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

希望有帮助!

来源:

【讨论】:

  • 没有额外的命令行开关,所以暂停时间目标应该是标准的 200 毫秒。 JVM 本身在分配了 4 个内核的 VM 中运行(我认为),物理机肯定应该有更多,所以这是可以尝试的。目前最大的问题是内存开销,所以现在我们没有进一步研究 G1。
  • 根据 Oracle 网站,G1 的占用空间应小于总内存的 6%,因此在您的情况下
  • 我不得不承认我在某个时候通过 JVisualVM 触发了完整的 GC。我想我在某处读到这些可能会导致内存泄漏......但话又说回来,我看到巨大的内存在一段时间后增加了很多,所以我想这不是问题。我们自己的代码没有使用任何本机的东西或 DirectMemoryBuffers,但是通过 JDBC 完成了很多持久化,并且这些库可能会这样做。这可能会导致内存泄漏,因为 G1 没有调用它们的终结器(只是猜测,但我上面的链接中提到了类似的事情)。无论如何,感谢您的帮助!
猜你喜欢
  • 2021-06-01
  • 1970-01-01
  • 2016-08-24
  • 1970-01-01
  • 2017-11-15
  • 1970-01-01
  • 1970-01-01
  • 2017-11-12
  • 1970-01-01
相关资源
最近更新 更多