关于GC 的空间大小和 GC时机问题参考

http://www.importnew.com/13954.html

[quote]

[HotSpot VM] 如何降低新生代GC时间？


whb1984的博客

whb1984 2014-10-21

R大及各位好，简单描述下状况：

系统上线10几个小时，CMS回收只有一次还可以接受，现在的问题是minor GC 时间随着系统运行时间越来越长，大部分超过了0.1s。而且大致是随着老年代的内存增加，minor GC时间逐步变长。以我的理解新生代的GC回收时间应该和老年代的占用内存大小没什么关系吧，为啥minor GC时间会越来越长呢？


机器配置：
cpu： Intel(R) Xeon(R) CPU E5430 @ 2.66GHz × 8
memory: 16G

jvm启动参数：
-server -Xloggc:./log/gcviewer.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -verbosegc -Xms2048M -Xmx2048M -Xmn190M -XX:+DisableExplicitGC -XX:+ScavengeBeforeFullGC -XX:ParallelGCThreads=8 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:SurvivorRatio=8 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=31 -XX:+AggressiveOpts -XX:MaxGCPauseMillis=100 -XX:+HeapDumpOnOutOfMemoryError -XX:PermSize=128M -XX:MaxPermSize=256M


gcviewer截图：灰色部分为GC时间，蓝色为内存增长。


截出部分gc日志：
刚开始时：开始还可以接受，0.02～0.03s
2014-10-21T16:12:00.390+0800: 333.022: [GC 333.022: [ParNew: 169158K->17105K(175104K), 0.0196470 secs] 853779K->701725K(2077696K), 0.0203990 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
2014-10-21T16:12:02.701+0800: 335.333: [GC 335.333: [ParNew: 172753K->14227K(175104K), 0.0230520 secs] 857373K->698847K(2077696K), 0.0238350 secs] [Times: user=0.15 sys=0.00, real=0.03 secs]
2014-10-21T16:12:04.020+0800: 336.652: [GC 336.652: [ParNew: 169875K->16849K(175104K), 0.0217180 secs] 854495K->701470K(2077696K), 0.0224960 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2014-10-21T16:12:05.425+0800: 338.057: [GC 338.057: [ParNew: 172497K->17403K(175104K), 0.0208420 secs] 857118K->702024K(2077696K), 0.0215930 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
2014-10-21T16:12:06.712+0800: 339.344: [GC 339.345: [ParNew: 173051K->15236K(175104K), 0.0201730 secs] 857672K->699857K(2077696K), 0.0209250 secs] [Times: user=0.15 sys=0.00, real=0.02 secs]
2014-10-21T16:12:08.034+0800: 340.666: [GC 340.667: [ParNew: 170884K->17870K(175104K), 0.0200380 secs] 855505K->702491K(2077696K), 0.0208180 secs] [Times: user=0.15 sys=0.01, real=0.02 secs]
2014-10-21T16:12:09.602+0800: 342.234: [GC 342.235: [ParNew: 173518K->16237K(175104K), 0.0223470 secs] 858139K->700858K(2077696K), 0.0230970 secs] [Times: user=0.17 sys=0.00, real=0.03 secs]
2014-10-21T16:12:11.041+0800: 343.673: [GC 343.674: [ParNew: 171885K->19456K(175104K), 0.0208920 secs] 856506K->704101K(2077696K), 0.0216500 secs] [Times: user=0.15 sys=0.00, real=0.02 secs]

运行一段时间：慢慢升高，已经0.12s了
2014-10-21T20:58:10.920+0800: 17503.552: [GC 17503.553: [ParNew: 175104K->18907K(175104K), 0.1173460 secs] 1065519K->909322K(2077696K), 0.1181020 secs] [Times: user=0.91 sys=0.01, real=0.12 secs]
2014-10-21T20:58:17.784+0800: 17510.416: [GC 17510.417: [ParNew: 174555K->18403K(175104K), 0.1167540 secs] 1064970K->908818K(2077696K), 0.1175530 secs] [Times: user=0.92 sys=0.00, real=0.12 secs]
2014-10-21T20:58:23.240+0800: 17515.872: [GC 17515.872: [ParNew: 174051K->16445K(175104K), 0.1189100 secs] 1064466K->906861K(2077696K), 0.1197100 secs] [Times: user=0.92 sys=0.01, real=0.12 secs]
2014-10-21T20:58:31.390+0800: 17524.022: [GC 17524.022: [ParNew: 172093K->19456K(175104K), 0.1188790 secs] 1062509K->909974K(2077696K), 0.1196710 secs] [Times: user=0.93 sys=0.00, real=0.12 secs]
2014-10-21T20:58:35.824+0800: 17528.456: [GC 17528.457: [ParNew: 175104K->18279K(175104K), 0.1181890 secs] 1065622K->908798K(2077696K), 0.1189490 secs] [Times: user=0.93 sys=0.00, real=0.12 secs]
2014-10-21T20:58:44.207+0800: 17536.839: [GC 17536.840: [ParNew: 173927K->16366K(175104K), 0.1174270 secs] 1064446K->906884K(2077696K), 0.1182030 secs] [Times: user=0.92 sys=0.00, real=0.12 secs]

最高的一段时间：大概快到了0.2s了。
2014-10-22T03:36:12.582+0800: 41385.215: [GC 41385.215: [ParNew: 175104K->19456K(175104K), 0.1745820 secs] 692711K->537299K(2077696K), 0.1754410 secs] [Times: user=1.37 sys=0.00, real=0.18 secs]
2014-10-22T03:36:19.549+0800: 41392.181: [GC 41392.182: [ParNew: 175104K->19456K(175104K), 0.1753550 secs] 692947K->537562K(2077696K), 0.1761940 secs] [Times: user=1.38 sys=0.00, real=0.18 secs]
2014-10-22T03:36:25.216+0800: 41397.848: [GC 41397.848: [ParNew: 175104K->19456K(175104K), 0.1746610 secs] 693210K->537878K(2077696K), 0.1754360 secs] [Times: user=1.37 sys=0.01, real=0.18 secs]
2014-10-22T03:36:29.907+0800: 41402.539: [GC 41402.539: [ParNew: 175104K->19456K(175104K), 0.1751190 secs] 693526K->538168K(2077696K), 0.1759340 secs] [Times: user=1.38 sys=0.01, real=0.17 secs]
2014-10-22T03:36:35.684+0800: 41408.317: [GC 41408.317: [ParNew: 175104K->19456K(175104K), 0.1750010 secs] 693816K->538480K(2077696K), 0.1758160 secs] [Times: user=1.38 sys=0.00, real=0.18 secs]
2014-10-22T03:36:40.335+0800: 41412.967: [GC 41412.967: [ParNew: 175104K->19456K(175104K), 0.1753520 secs] 694128K->538801K(2077696K), 0.1761410 secs] [Times: user=1.38 sys=0.01, real=0.18 secs]

最后总结下问题：
1. jvm参数设置及垃圾收集器设置是否合理？
2. 为什么minor gc时间会越来越长（190m的新生代，每次gc花费0.1s~0.2s的时间是什么概念？ 是否属于时间过长？）
3. 如何减少minor gc时间？ (现在cms gc时间可以忽略不计，主要是minor gc时间过长)


Spinner


youlong699的博客

youlong699 2014-10-22

-Xmn190M 太小了点。 目测你的S区每次都被占满，这样每次minorgc会有大量对象被promotion到old区。可以用jstat -gcutil 看下S0/S1的占用率

并且，随着old区可用内存减少、碎片增多（几次cmsgc之后），在old区分配空间耗时会变长。

建议，尝试增大Xmn . 如果你有比较大量的长寿对象，比如一些缓存之类的，old是要占用比例较大，但是你这个比例未免差异太大了 ：）

Spinner


whb1984的博客

whb1984 2014-10-22


youlong699 写道

-Xmn190M 太小了点。 目测你的S区每次都被占满，这样每次minorgc会有大量对象被promotion到old区。可以用jstat -gcutil 看下S0/S1的占用率

并且，随着old区可用内存减少、碎片增多（几次cmsgc之后），在old区分配空间耗时会变长。

建议，尝试增大Xmn . 如果你有比较大量的长寿对象，比如一些缓存之类的，old是要占用比例较大，但是你这个比例未免差异太大了 ：）


感觉上面朋友的回复，关于你说的原因我再补充说明下：

引用

随着old区可用内存减少、碎片增多（几次cmsgc之后），在old区分配空间耗时会变长

1. 这个根据上面的gcviewer图和gc日志能看到，在jvm的第一次cms之前，minorgc的时间就已经能够达到0.12s左右，这个时候jvm还没做过cms，所以是不是可以排除和cms的关系呢？
2. "old区可用内存减少，在old区分配空间耗时会变长"，这个原因是什么呢？ 是因为minor gc会发生old promotion操作吗？但是比如下面这次minorgc，新生代回收的内存和总的内存回收一样多(175104 - 18907 = 1065519 - 909322)，说明是没有发生promotion，但是gc时间也要0.12s。像这种没有promotion的minorgc还有很多，而且时间也比较长。

引用

2014-10-21T20:58:10.920+0800: 17503.552: [GC 17503.553: [ParNew: 175104K->18907K(175104K), 0.1173460 secs] 1065519K->909322K(2077696K), 0.1181020 secs] [Times: user=0.91 sys=0.01, real=0.12 secs]

3. 关于增大young generation size。这个也尝试过，可以说，新生代分配的内存增大，minorgc频率会变低，单次gc time会变长，但总体来说throughput会有提高。 但是现在我们把throughput放在第二位，只是希望minor gc 能降低些，哪怕牺牲些throughput。 关于新生代190m内存其实还可以降低，但是再低些会导致gc过于频繁，吞吐量降低太多，这也是不太可取。

这是我的一些个人理解，希望大家能给些建议。
Spinner


pulsar_lxl的博客

pulsar_lxl 2014-11-05

我遇到的问题和楼主类似，我的基本配置是Xmx=3g, NewRatio=8, parNew + CMS，随着老年代使用内存不断增加，响应时间逐渐变长，系统吞吐也下降的厉害。

youlong699 写道


并且，随着old区可用内存减少、碎片增多（几次cmsgc之后），在old区分配空间耗时会变长。


这位仁兄的说法有什么理论依据没有，我只知道CMS使用空闲链表分配内存，空闲链表相对碰撞指针性能有下降，但是不知道随着old区内存使用量越来越多，空闲链表分配性能会越来越低吗？

Spinner


xxd82329的博客

xxd82329 2014-11-13

简单的说，做Minor GC的时候，JVM必须要扫描Old gen，因为Old gen里面的对象可能会有指向Young gen的引用。所以，当Old gen越来越大的时候，这种扫描所花的时间也就会越来越多了。

本人也同意第一位朋友的说法，Young gen设的太小了。一般来说，我倾向于把Young gen设到Heap的三分之一，甚至有时候会到二分之一。。。

希望对楼主有用。

Spinner


youlong699的博客

youlong699 2015-02-03

看到gc maillist里提到这个话题，想到这个帖子，顺道来贴一下再。
总结来说，就是perm gen 、code cache增大，由于需要扫描其对young gen的引用，导致扫描时间变长：
http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2015-January/002100.html

Spinner


rink1969的博客

rink1969 2015-02-13

最近也遇到一个类似现象的问题，补充一下，方便大家查找。
我那个问题最后发现是jvmti agent的问题。agent里面持续创建了很多jvmti对象和jni对象。这些也是strong root，要在YGC的时候扫描的。
但是经过一次CMS GC之后，这些都回收掉了，YGC就正常了。

Spinner


fh63045的博客

fh63045 2015-03-24

-server -Xloggc:./log/gcviewer.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -verbosegc -Xms2048M -Xmx2048M -Xmn190M -XX:+DisableExplicitGC -XX:+ScavengeBeforeFullGC -XX:ParallelGCThreads=8 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:SurvivorRatio=8 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=31 -XX:+AggressiveOpts -XX:MaxGCPauseMillis=100 -XX:+HeapDumpOnOutOfMemoryError -XX:PermSize=128M -XX:MaxPermSize=256M

1. 新生代太小, 通用设置1-1.5倍FGC后老年代大小
2. 设置年龄太长了 使用 -XX:+PrintTenuringDistribution 判断具体年龄分布.


[/quote]