[讨论] [HotSpot VM] 关于 CMS 后内存无法回收的问题

denger 2015-03-21
JVM args:
-Xms20g -Xmx20g -Xmn6g -XX:PermSize=512m -XX:MaxPermSize=512m -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+UseCMSCompactAtFullCollection -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly  -XX:CMSInitiatingOccupancyFraction=70

采用是 CMS , 当内存使用到达 70% 之后,JVM 则开始频繁 CMS, 通过 jstat 观察, 原因是 old 区的占用在CMS 后仍然保持在 70%+,以下是 CMS 日志:

2015-03-20T23:46:03.873+0800: 524564.008: [GC [1 CMS-initial-mark: 10354037K(14680064K)] 14581136K(20342400K), 0.7414240 secs] [Times: user=0.74 sys=0.00, real=0.74 secs]
2015-03-20T23:46:04.615+0800: 524564.749: [CMS-concurrent-mark-start]
2015-03-20T23:46:10.836+0800: 524570.971: [CMS-concurrent-mark: 6.206/6.222 secs] [Times: user=18.87 sys=0.04, real=6.22 secs]
2015-03-20T23:46:10.836+0800: 524570.971: [CMS-concurrent-preclean-start]
2015-03-20T23:46:10.877+0800: 524571.012: [CMS-concurrent-preclean: 0.040/0.041 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
2015-03-20T23:46:10.877+0800: 524571.012: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2015-03-20T23:46:16.276+0800: 524576.411: [CMS-concurrent-abortable-preclean: 5.298/5.399 secs] [Times: user=5.42 sys=0.00, real=5.40 secs]
2015-03-20T23:46:16.279+0800: 524576.414: [GC[YG occupancy: 4288018 K (5662336 K)]2015-03-20T23:46:16.279+0800: 524576.414: [Rescan (parallel) , 0.7708160 secs]2015-03-20T23:46:17.050+0800: 524577.185: [weak refs processing, 0.0003580 secs]2015-03-20T23:46:17.051+0800: 524577.185: [scrub string table, 0.0027650 secs] [1 CMS-remark: 10354037K(14680064K)] 14642055K(20342400K), 0.7741700 secs] [Times: user=7.51 sys=0.02, real=0.78 secs]
2015-03-20T23:46:17.054+0800: 524577.189: [CMS-concurrent-sweep-start]
2015-03-20T23:46:21.254+0800: 524581.389: [CMS-concurrent-sweep: 4.200/4.200 secs] [Times: user=4.33 sys=0.02, real=4.20 secs]
2015-03-20T23:46:21.254+0800: 524581.389: [CMS-concurrent-reset-start]
2015-03-20T23:46:21.287+0800: 524581.422: [CMS-concurrent-reset: 0.033/0.033 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2015-03-20T23:46:23.291+0800: 524583.426: [GC [1 CMS-initial-mark: 10353762K(14680064K)] 14669606K(20342400K), 0.8579510 secs] [Times: user=0.86 sys=0.00, real=0.85 secs]
2015-03-20T23:46:24.149+0800: 524584.284: [CMS-concurrent-mark-start]
2015-03-20T23:46:30.105+0800: 524590.240: [GC2015-03-20T23:46:30.105+0800: 524590.240: [ParNew: 5228321K->144930K(5662336K), 0.0965630 secs] 15582084K->10503133K(20342400K), 0.0969580 secs] [Times: user=0.45 sys=0.00, real=0.10 secs]
2015-03-20T23:46:30.580+0800: 524590.715: [CMS-concurrent-mark: 6.200/6.431 secs] [Times: user=21.44 sys=0.13, real=6.43 secs]
2015-03-20T23:46:30.580+0800: 524590.715: [CMS-concurrent-preclean-start]
2015-03-20T23:46:30.654+0800: 524590.789: [CMS-concurrent-preclean: 0.072/0.074 secs] [Times: user=0.13 sys=0.00, real=0.08 secs]
2015-03-20T23:46:30.654+0800: 524590.789: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2015-03-20T23:46:36.270+0800: 524596.405: [CMS-concurrent-abortable-preclean: 5.315/5.616 secs] [Times: user=6.46 sys=0.04, real=5.61 secs]
2015-03-20T23:46:36.273+0800: 524596.408: [GC[YG occupancy: 1219534 K (5662336 K)]2015-03-20T23:46:36.273+0800: 524596.408: [Rescan (parallel) , 0.2391060 secs]2015-03-20T23:46:36.513+0800: 524596.647: [weak refs processing, 0.0003360 secs]2015-03-20T23:46:36.513+0800: 524596.648: [scrub string table, 0.0025970 secs] [1 CMS-remark: 10358202K(14680064K)] 11577737K(20342400K), 0.2422820 secs] [Times: user=2.34 sys=0.01, real=0.24 secs]
2015-03-20T23:46:36.516+0800: 524596.651: [CMS-concurrent-sweep-start]


随后便通过 jmap dump 出 jvm 内存,使用 MAT 分析,发现存在大量的 unreachable objects

于是,便通过尝试去调用 Runtime.gc() ,代码方法如下:
	private void gc() {
		Runtime.getRuntime().gc();
	}


在调用后FullGC 次数 +1, 且 old 区内存已被释放,Full GC 日志如下:
2015-03-21T00:24:42.753+0800: 526882.887: [Full GC2015-03-21T00:24:42.753+0800: 526882.888: [CMS: 10693558K->3120408K(14680064K), 12.6300420 secs] 12463065K->3120408K(20342400K), [CMS Perm : 136904K->132561K(524288K)], 12.6304580 secs] [Times: user=12.61 sys=0.00, real=12.63 secs]
 
可见 old 区直接回收了 7G 左右的内存空间,接着重新 dump heap ,那些 unreachable objects 已经没有了。于是手工触发执行了一次 Runtime.gc 后,old 区内存使用直接降到  5%.


那么问题来了,为什么  CMS 没法将那些 不可达 对象 GC 掉? Full GC 会在什么情况下进行执行? 这种问题出现的原因是什么如何避免或解决?

谢谢!
RednaxelaFX 2015-03-21
啥版本的JDK?
有些版本的CMS有弱引用处理的问题,会导致很多只被弱引用留活的对象无法被回收,要到full GC才能回收得了。
denger 2015-03-21
RednaxelaFX 写道
啥版本的JDK?
有些版本的CMS有弱引用处理的问题,会导致很多只被弱引用留活的对象无法被回收,要到full GC才能回收得了。


感谢 R 大回复~

JDK Version:

openjdk version "1.7.0-internal"
OpenJDK Runtime Environment (build 1.7.0-internal-b00)
OpenJDK 64-Bit Server VM (build 24.60-b09, mixed mode)

看上去是内部编译过的, 该版本会存在你所说的弱引用无法 GC 的问题吗?  另外,FullGC 的执行条件之一就是 old 区空间不足,当前配置的阀值是 70% 开始 CMS,  即使到了70%,JVM 认为空间也是足的吧,所以还达不到 FullGC 的条件吗?

那,有什么办法解决这个问题吗?
RednaxelaFX 2015-03-22
这对应的是7u60的HotSpot。是哪里的build?
这个版本的CMS有什么问题我回头查一下
denger 2015-03-22
RednaxelaFX 写道
这对应的是7u60的HotSpot。是哪里的build?
这个版本的CMS有什么问题我回头查一下


这个公司内部build 出来的版本,所有环境都是统一该版本。

好的,麻烦如果有什么进展和我说一下。这个问题太困扰人了,谢谢哇!!~~
denger 2015-05-05
RednaxelaFX 写道
这对应的是7u60的HotSpot。是哪里的build?
这个版本的CMS有什么问题我回头查一下

请问这个版本的 cms 有问题吗? 
如果我想直接重现这个问题的话,是不是直接模拟 old  区潢然后使用 cms 看是否会 gc ?
nijiaben 2015-05-10
引用
随后便通过 jmap dump 出 jvm 内存,使用 MAT 分析,发现存在大量的 unreachable objects。


jmap如果加了live参数做dump,在cms gc下其实并没有做全量的full gc,说白了其实没有做ygc,而只做了cms gc,这样就能解释为什么会有那么多unreachable对象了,因为这些对象都是新生代的不可达对象

而你接着做一次System.gc,此时会对new和old都做一次gc,因此不可达对象没了
denger 2015-05-14
nijiaben 写道
引用
随后便通过 jmap dump 出 jvm 内存,使用 MAT 分析,发现存在大量的 unreachable objects。


jmap如果加了live参数做dump,在cms gc下其实并没有做全量的full gc,说白了其实没有做ygc,而只做了cms gc,这样就能解释为什么会有那么多unreachable对象了,因为这些对象都是新生代的不可达对象

而你接着做一次System.gc,此时会对new和old都做一次gc,因此不可达对象没了


我的年轻代是 6G 哇~~~ 可是 unreachable objects 达到了 > 7G。另外,在执行 ygc 和 cms gc 后多次 dump 数据对比,发现之前那些 unreachable 并没有减少啊,可见它确实存在于 old 区。
yong 区已经被分为三个区了,即使全部持续100%也不太可能装得了这些对象啊,

在执行 full gc 后,再 dump 发现 old 区直接下降了。
Global site tag (gtag.js) - Google Analytics