[讨论] Sun hotspot JVM 1.6的CMS问题

ningandjin 2012-01-13

各位大牛:

       小弟有一个系统在运行过程中,通过Jconsole观察发现,新生代,年老代都满了,GC日志记录CMS一直在做年老代的回收,但是从Jconsole里面看,一点内存都没回收到,于是,在Jconsole中手动触发了“Perform GC”,内存一下子收下去好大一截。从GC日志来看,这个也是调用的CMS方法回收,为什么自动触发的CMS收不到内存,手动去perform一下GC就行了呢?请各位大牛多多指教,任何提示皆万分感谢......

     (ps:在内存撑满之前,曾出现过一次promotion failed)

RednaxelaFX 2012-01-13
JDK版本、OS版本、参数。这些必备信息先写出来再说。

默认参数下,JConsole的Perform GC触发的是full GC,而不是CMS GC。
如果你看到full GC能回收到内存而CMS GC回收不到,有可能是跟弱引用处理相关。JDK6里的HotSpot VM都有这bug。我们这边用的新的Taobao JDK是自己打补丁把这bug给修了。

相应的bug ID是:7112034: Parallel CMS fails to properly mark reference objects
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7112034

你可以试试用 -XX:-CMSConcurrentMTEnabled 来绕开这个bug。
ningandjin 2012-01-13
JDK 版本:
java version "1.6.0_26"
Java(TM) SE Runtime Environment (build 1.6.0_26-b03)
Java HotSpot(TM) 64-Bit Server VM (build 20.1-b02, mixed mode)

OS:
Linux 158-1-134-113 2.6.32.12-0.7-default #1 SMP 2010-05-20 11:14:20 +0200 x86_64 x86_64 x86_64 GNU/Linux

JVM 参数:
-Xmx4G -Xms4G -server -Dcom.sun.management.jmxremote -XX:+UseCMSCompactAtFullCollection -XX:+UseConcMarkSweepGC -XX:CMSFullGCsBeforeCompaction=10 -XX:SurvivorRatio=18 -Xloggc:$log_dir/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC

非常感谢指导,问问题应该贴上日志文件的,可是原来的那个文件不小心被我覆盖了,我会继续重现这个问题,按照您的建议看看效果,再次感谢。
RednaxelaFX 2012-01-13
这两个参数去掉:
-XX:+UseCMSCompactAtFullCollection
-XX:CMSFullGCsBeforeCompaction=10

第一个参数默认值就是true,没必要显式设置。
第二个参数这样配置的话容易出现promotion failure;默认值是0来的。
ningandjin 2012-01-14
RednaxelaFX 写道
这两个参数去掉:
-XX:+UseCMSCompactAtFullCollection
-XX:CMSFullGCsBeforeCompaction=10

第一个参数默认值就是true,没必要显式设置。
第二个参数这样配置的话容易出现promotion failure;默认值是0来的。


-XX:CMSFullGCsBeforeCompaction这个参数不是用来防止内存碎片,因为我看到文章说
CMS可能会造成内存碎片,所以配置这个参数来没10次CMS做一次内存压缩,不知道我理解得对不对?另外这个参数是不是还有很多副作用啊?
RednaxelaFX 2012-01-14
ningandjin 写道
-XX:CMSFullGCsBeforeCompaction这个参数不是用来防止内存碎片,因为我看到文章说
CMS可能会造成内存碎片,所以配置这个参数来没10次CMS做一次内存压缩,不知道我理解得对不对?另外这个参数是不是还有很多副作用啊?

不知道是你看的文章写错了还是你理解错误。

有一点需要注意的是:CMS并发GC不是“full GC”。HotSpot VM里对concurrent collection和full collection有明确的区分。所有带有“FullCollection”字样的VM参数都是跟真正的full GC相关,而跟CMS并发GC无关的。

CMSFullGCsBeforeCompaction这个参数在HotSpot VM里是这样声明的:
product(bool, UseCMSCompactAtFullCollection, true,                     \
        "Use mark sweep compact at full collections")                  \
                                                                       \
product(uintx, CMSFullGCsBeforeCompaction, 0,                          \
        "Number of CMS full collection done before compaction if > 0") \

然后这样使用的:
  *should_compact =
    UseCMSCompactAtFullCollection &&
    ((_full_gcs_since_conc_gc >= CMSFullGCsBeforeCompaction) ||
     GCCause::is_user_requested_gc(gch->gc_cause()) ||
     gch->incremental_collection_will_fail(true /* consult_young */));

CMS GC要决定是否在full GC时做压缩,会依赖几个条件。其中,
第一种条件,UseCMSCompactAtFullCollection 与 CMSFullGCsBeforeCompaction 是搭配使用的;前者目前默认就是true了,也就是关键在后者上。
第二种条件是用户调用了System.gc(),而且DisableExplicitGC没有开启。
第三种条件是young gen报告接下来如果做增量收集会失败;简单来说也就是young gen预计old gen没有足够空间来容纳下次young GC晋升的对象。

上述三种条件的任意一种成立都会让CMS决定这次做full GC时要做压缩。
(还有另一个参数,CMSCompactWhenClearAllSoftRefs,这个就先不说了,反正你没有配置它,而且默认也是true)

CMSFullGCsBeforeCompaction 说的是,在上一次CMS并发GC执行过后,到底还要再执行多少次full GC才会做压缩。默认是0,也就是在默认配置下每次CMS GC顶不住了而要转入full GC的时候都会做压缩。
把CMSFullGCsBeforeCompaction配置为10,就会让上面说的第一个条件变成每隔10次真正的full GC才做一次压缩(而不是每10次CMS并发GC就做一次压缩,目前VM里没有这样的参数)。这会使full GC更少做压缩,也就更容易使CMS的old gen受碎片化问题的困扰。
本来这个参数就是用来配置降低full GC压缩的频率,以期减少某些full GC的暂停时间。CMS回退到full GC时用的算法是mark-sweep-compact,但compaction是可选的,不做的话碎片化会严重些但这次full GC的暂停时间会短些;这是个取舍。
javas 2012-02-02
在我的测试中 http://blog.csdn.net/firecoder/article/details/7225654
VisualGC 观察到old gen 回收55次,一次Full GC也没有。

我感到很好奇,于是点击了JConsole上的Perform GC,GC Log中出现了一次Full GC,并且回收了一大块Old gen的内存(600m左右降到200m)。

842.717: [Full GC (System) 842.717: [CMS: 692905K->273935K(1033496K), 1.6946010 secs] 703310K->273935K(1071832K), [CMS Perm : 60989K->60840K(86016K)], 1.6949420 secs] [Times: user=1.70 sys=0.00, real=1.69 secs]


从JConsole上看内存占用一直稳定在600m左右;而GC Log,发现CMS在内存900m左右触发

363.045: [GC [1 CMS-initial-mark: 914585K(1033496K)] 920481K(1071832K), 0.0142710 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
...
690.244: [GC [1 CMS-initial-mark: 908936K(1033496K)] 913621K(1071832K), 0.0151350 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]


相当的矛盾。
可能的猜测就是JConsole观察值有时间差。

ol_beta 2012-04-26
今天花时间好好看了这个帖子,受益匪浅,感谢RednaxelaFX的总结!
bryanzhaozl 2012-10-24
我目前也遇到这个问题,cms不停gc,但是回收的内存很少。使用的jdk是1.7最新的。如果是jdk的bug,应该已经修复了。同时我加了RednaxelaFX 提到的参数,问题还是一样。困扰了很长时间,希望有人指点一下。。
RednaxelaFX 2012-10-25
CMS回收的内存少,那么从外部强行触发full gc有怎样的反应?
JConsole或jmap -histo:live都可以
Global site tag (gtag.js) - Google Analytics