Java - GC运行但不回收任何东西

Question

在过去的几天里,我们看到我们的服务器上的JVM进入一个状态,他们在OldGen的GC中花费100%的CPU时间,时间:

A.他们不需要,因为堆上有足够的空间

B.他们不回收任何东西.

我知道他们在GC中是通过查看堆栈跟踪并将ProcessExplorer中的ThreadID与堆栈转储中的ThreadID相关联.每个GC线程占用大约4%的CPU.

服务器运行16 gig堆(32gig物理RAM)并具有8个核心.正常运行时间通常为30天左右,只需要根据MS补丁要求重新启动,但目前它们在20天内崩溃.

这是持续时间,时间尺度= 19天的图表. http://i45.tinypic.com/257qalu.png

这是该图表尾部的缩放 http://i48.tinypic.com/2duiccw.png

如您所见,持续时间急剧增加.

下面是GC后堆使用情况的图表. http://i48.tinypic.com/znna4h.png

如果这是一个典型的内存泄漏,我希望看到橙色峰值越来越高,直到它们不再达到峰值,但如图所示,剩下大量的堆空间.

我有每个服务器的堆转储,没有什么是有问题的突出.有几个ehCache商店,我可以看到我们的应用程序代码,即只是"正常的东西"

我们在20天前做出的最大改变是实现了一个供应商补丁,它将内部缓存从使用硬引用(以及明显的内存泄漏)的无界散列图更改为由软引用组成的一个,我想知道这是否是原因,即某种程度上在管理这些软引用之后会产生巨大的开销？

有没有人想知道接下来要去哪里,或者有人可以证实我的软参考理论？

这是我的jvm.args:

java.args = -server -Xms16000m -Xmx16000m -Dsun.io.useCanonCaches = false -XX:MaxPermSize = 350m -Xloggc:e:/gcLogs/eRGCLogs.txt -verbose:gc -XX:+ PrintGCDetails -XX:+ PrintGCTimeStamps - XX:+ PrintGCDateStamps -XX:+ UseParallelGC -XX:+ UseParallelOldGC -Dnet.sf.ehcache.sizeof.filter = D:/jo3/java_ehCacheOpenSource/sizeOfExclusions.config -Xbatch -Dcoldfusion.rootDir = {application.home}/../-Dcoldfusion.libPath = {application.home} /../ lib -Dcoldfusion.classPath = {application.home} /../ lib/updates,{application.home} /../ lib,{application.home} /../gateway/lib/,{application.home}/../wwwroot/WEB-INF/flex/jars,{application.home}/../wwwroot/WEB-INF/cfform/jars,d:/ jo3/JAVA,d:/ jO3/java_ehCacheOpenSource /,d:/ jo3/java_ehCacheMonitorProbe

我们在Coldfusion上,这有点像一个位于java之上的庞大框架.

JVM版本:1.6.0_29

根据要求,"正常"GC日志如下所示:

2013-03-19T22:11:36.670 + 1100:1288665.702:[GC [PSYoungGen:4695800K-> 471119K(4722112K)] 9301727K-> 5077046K(15644800K),0.3584434 secs] [次:用户= 5.01 sys = 0.00,real = 0.36秒] 2013-03-19T22:14:55.078 + 1100:1288864.099:[GC [PSYoungGen:4722063K-> 498009K(4783104K)] 9327990K-> 5103936K(15705792K),0.3766889 secs] [次:用户= 5.37 sys = 0.00 ,实际= 0.38秒] 2013-03-19T22:17:46.749 + 1100:1289035.760:[GC [PSYoungGen:4654489K-> 517299K(4673792K)] 9260416K-> 5123227K(15596480K),0.4130828 secs] [次:用户= 5.80 sys = 0.00,real = 0.41 secs] 2013-03-19T22:21:08.762 + 1100:1289237.763:[GC [PSYoungGen:4673779K-> 522660K(4738880K)] 9279707K-> 5143831K(15661568K),0.4005516 secs] [次: user = 5.97 sys = 0.00,real = 0.40 secs] 2013-03-19T22:23:42.683 + 1100:1289391.675:[GC [PSYoungGen:4582628K-> 530998K(4590976K)] 9203799K-> 5186242K(15513664K),0.4317352 secs] [时间:用户= 6.24 sys = 0.00,实际= 0.43秒] 2013-03-19T22:26:11.096 + 1100:1289540.080:[GC [PSYoungGen:4590966K-> 518331K(4724096K)] 9246210K-> 5 206959K(15646784K),0.3914401 secs] [次:用户= 5.99 sys = 0.00,real = 0.39 secs] 2013-03-19T22:27:44.076 + 1100:1289633.055:[GC [PSYoungGen:2602730K-> 447527K(4732864K)] 7291358K-> 5208743K(15655552K),0.3725317 secs] [次:用户= 5.80 sys = 0.00,实际= 0.37秒] 2013-03-19T22:27:44.448 + 1100:1289633.428:[全GC(系统)[PSYoungGen:447527K] - > 0K(4732864K)] [ParOldGen:4761215K-> 4628296K(10922688K)] 5208743K-> 4628296K(15655552K)[PSPermGen:352378K-> 352287K(352832K)],4.2955639 secs] [次:用户= 57.70 sys = 0.06,实际= 4.30秒] 2013-03-19T22:30:37.950 + 1100:1289806.920:[GC [PSYoungGen:4004416K-> 70948K(4690432K)] 8632712K-> 4699245K(15613120K),0.1062227 secs] [次:用户= 0.76 sys = 0.00,实= 0.11秒] 2013-03-19T22:33:27.154 + 1100:1289976.115:[GC [PSYoungGen:4054116K-> 109175K(4092352K)] 8682413K-> 4737472K(15015040K),0.1347919 secs] [时间:用户= 1.03 sys = 0.00,real = 0.13 secs] 2013-03-19T22:36:32.120 + 1100:1290161.070:[GC [PSYoungGen:4092343K-> 147318K(4712320K)] 8720640K-> 4775615K(15 635008K),0.1593523秒] [时间:用户= 1.58 sys = 0.00,实际= 0.16秒] 2

当我们处于故障模式时,GC日志看起来像:

2013-03-22T10:03:47.619 + 1100:1504185.901:[GC [PSYoungGen:0K-> 0K(5452736K)] 4413907K-> 4413907K(16375424K),0.0114248 secs] [次:用户= 0.16 sys = 0.00,real = 0.01秒] 2013-03-22T10:03:47.631 + 1100:1504185.912:[全GC [PSYoungGen:0K-> 0K(5452736K)] [ParOldGen:4413907K-> 4412613K(10922688K)] 4413907K-> 4412613K(16375424K)[ PSPermGen:358399K-> 358278K(358400K)],5.4435442 secs] [次:用户= 73.74 sys = 0.14,real = 5.44 secs] 2013-03-22T10:03:53.145 + 1100:1504191.426:[GC [PSYoungGen:269219K- > 7734K(5449088K)] 4681833K-> 4422114K(16371776K),0.0298728秒] [时间:用户= 0.34 sys = 0.00,实际= 0.03秒] 2013-03-22T10:03:53.175 + 1100:1504191.456:[Full GC [ PSYoungGen:7734K-> 0K(5449088K)] [ParOldGen:4414379K-> 4415189K(10922688K)] 4422114K-> 4415189K(16371776K)[PSPermGen:358399K-> 358371K(358400K)],2.6033684 secs] [次:用户= 36.33 sys = 0.00,实际= 2.60秒] 2013-03-22T10:03:55.788 + 1100:1504194.069:[GC [PSYoungGen:94969K-> 826K(5451328K)] 4510158K-> 4416015K(16374016K),0.0133588 secs] [次 :user = 0.16 sys = 0.00,real = 0.01 secs] 2013-03-22T10:03:55.802 + 1100:1504194.082:[Full GC [PSYoungGen:826K-> 0K(5451328K)] [ParOldGen:4415189K-> 4415348K(10922688K) )] 4416015K-> 4415348K(16374016K)[PSPermGen:358399K-> 358389K(358400K)],2.7156884 secs] [次:用户= 38.11 sys = 0.00,real = 2.71 secs] 2

Answer 1

正如许多人在评论中提到的那样,PermGen的空间不足很可能是你的原因.这可能是由于整个代码中的字符串过度实际导致PermGen"爆炸" - 也加载了很多类(通常通过在后台为你做的框架)也可能导致这种情况.

此外,正如上面提到的评论之一 - 使用CMS集合(并发标记和扫描)可以减少您的停止世界 GC,假设问题在于老一代的容量.它还可以通过减少延迟来提高性能,无论当前问题如何都可以.

此外,如果您发布GC日志的片段,这有助于指向正确的方向.

关于jstat工具,您可以通过以下方式使用它来获取有用的信息:

jstat -gcutil <pid> <interval> 

我通常使用1000毫秒的间隔.-gcutil为您提供GC利用率(%) - 这样您就可以看到任何一代是否接近100%.

您还可以使用jstat -gc <pid> ...并获得老一代的确切容量.

编辑:审查GC日志后

根据您的GC日志,它确认了您的PermGen正在填满的原始前提.在10:03:47和10:03:55之间的时间范围内,我可以看到PermGen始终达到它的最大值,并且GC以某种方式移除了大约10-100 KB的数据:

见下文:

2013-03-22T10:03:47.631+1100: 1504185.912: [Full GC [... [PSPermGen: 358399K->358278K(358400K)]...
2013-03-22T10:03:53.175+1100: 1504191.456: [Full GC [... [PSPermGen: 358399K->358371K(358400K)]...
2013-03-22T10:03:55.802+1100: 1504194.082: [Full GC [... [PSPermGen: 358399K->358389K(358400K)]...

如果你看看老年人和年轻人你可以看到他们都没有达到他们的最大值,OldGen在10GB中消耗4GB - 所以这不是原因.

根据您收集的数据,我无法判断PermGen填充的速率是否与流程的正常运行时间一致 - 这意味着PermGen看起来应该在一天内填满,而不是20天.所以很难说什么是明确的解决方案,但这里有一些建议:

1. 检查你的代码,以确保你没有滥用String的intern()方法 - 如果你在代码中使用太广泛,没有充分理由这可能是你的根本原因.
2. 如果它们动态生成类,请检查您正在使用的框架 - 这也将消耗PermGen空间,但在某种程度上.
3. 如果可以,请每周重新启动进程以防止此停机
4. 考虑增加PermGen空间,但监视它,因为增加它可能只会延长你的20天时间,但不能解决问题.在该过程足够长时间之后,PermGen应该保持静止.
5. 使用字符串Coldfusion PermGen在Google上进行搜索会产生许多报告问题的点击 - 尝试按照这些搜索来关注您的调查.