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

Joh*_*esR 6 garbage-collection jvm-hotspot g1gc

我目前正在评估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] 
Run Code Online (Sandbox Code Playgroud)

所有删除的日志行条目都以单位数ms显示运行时.

我想大部分时间都应该花在复制上,对吧?Scan RS需要这么长时间的原因是什么?关于如何调整G1设置的任何想法?JVM开始于

-Xms40960M -Xmx128G -XX:+UseG1GC -verbose:gc -XX:+PrintGCDetails -Xloggc:gc.log
Run Code Online (Sandbox Code Playgroud)

编辑:哦,我忘了......我正在使用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]
Run Code Online (Sandbox Code Playgroud)

正在执行并行运行时,并发GC运行正在继续.我不确定这是否有意,但对我来说似乎有点不对劲.不可否认,这是一个极端的例子,但我确实在我的日志中看到了这种行为.

另一件事是我的JVM进程增长到160克.考虑到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).

Pie*_*rte 6

让我们来看看.

1 - 第一条线索

看起来你的GC配置为使用4个线程(或者你有4个vCPU,但考虑到堆的大小,它不太可能).128GB的堆很低,我期待更多.

GC事件似乎以25秒的间隔发生.但是,您提供的日志提取没有提到已处理的区域数.

=>无论如何,你有没有为G1GC(-XX:MaxGCPauseMillis=N)指定暂停时间目标?

2 - 长扫描RSet时间

"扫描RSet"表示GC扫描记忆集所花费的时间.记住区域集包含与指向该区域的参考对应的卡片.此阶段扫描那些寻找指向集合集的所有区域的引用的卡.

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

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

3 - 长对象复制时间

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

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

4 - 现在该做什么

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

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

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

希望有所帮助!

资料来源: