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

Question

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

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

B. 他们没有回收任何东西。

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

服务器运行 16 gig 堆(32 gig 物理 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] [Times: user=5.01 sys=0.00, real=0.36 secs] 2013-03-19T22:14:55.078+1100: 1288864.099: [GC [PSYoungGen: 4722063K->498009K(4783104K)] 9327990K->5103936K(15705792K), 0.3766889 secs] [Times: user=5.37 sys=0.00, real=0.38 secs] 2013-03-19T22:17:46.749+1100: 1289035.760: [GC [PSYoungGen: 4654489K->517299K(4673792K)] 9260416K->5123227K(15596480K), 0.4130828 secs] [Times: user=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] [Times: 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] [Times: user=6.24 sys=0.00, real=0.43 secs] 2013-03-19T22:26:11.096+1100: 1289540.080: [GC [PSYoungGen: 4590966K->518331K(4724096K)] 9246210K->5206959K(15646784K), 0.3914401 secs] [Times: user=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] [Times: user=5.80 sys=0.00, real=0.37 secs] 2013-03-19T22:27:44.448+1100: 1289633.428: [Full GC (System) [PSYoungGen: 447527K->0K(4732864K)] [ParOldGen: 4761215K->4628296K(10922688K)] 5208743K->4628296K(15655552K) [PSPermGen: 352378K->352287K(352832K)], 4.2955639 secs] [Times: user=57.70 sys=0.06, real=4.30 secs] 2013-03-19T22:30:37.950+1100: 1289806.920: [GC [PSYoungGen: 4004416K->70948K(4690432K)] 8632712K->4699245K(15613120K), 0.1062227 secs] [Times: user=0.76 sys=0.00, real=0.11 secs] 2013-03-19T22:33:27.154+1100: 1289976.115: [GC [PSYoungGen: 4054116K->109175K(4092352K)] 8682413K->4737472K(15015040K), 0.1347919 secs] [Times: user=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(15635008K), 0.1593523 secs] [Times: user=1.58 sys=0.00, real=0.16 secs] 2

当我们处于故障模式时，GC 日志如下所示:

2013-03-22T10:03:47.619+1100: 1504185.901: [GC [PSYoungGen: 0K->0K(5452736K)] 4413907K->4413907K(16375424K), 0.0114248 secs] [Times: user=0.16 sys=0.00, real=0.01 secs] 2013-03-22T10:03:47.631+1100: 1504185.912: [Full GC [PSYoungGen: 0K->0K(5452736K)] [ParOldGen: 4413907K->4412613K(10922688K)] 4413907K->4412613K(16375424K) [PSPermGen: 358399K->358278K(358400K)], 5.4435442 secs] [Times: user=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 secs] [Times: user=0.34 sys=0.00, real=0.03 secs] 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] [Times: user=36.33 sys=0.00, real=2.60 secs] 2013-03-22T10:03:55.788+1100: 1504194.069: [GC [PSYoungGen: 94969K->826K(5451328K)] 4510158K->4416015K(16374016K), 0.0133588 secs] [Times: 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] [Times: user=38.11 sys=0.00, real=2.71 secs] 2

Answer 1

正如许多人在评论中提到的那样，PermGen 空间不足很可能是您的原因。这可能是由于在整个代码中过多地插入字符串导致的，这可能导致永久代“爆炸”——加载大量类(通常通过在后台为您执行的框架)也可能导致这种情况。

此外，作为提到的评论之一 - 使用 CMS 集合(并发标记和扫描)可以减少您的 Stop the World GC，假设问题出在老年代的容量上。它还可以通过减少延迟来提高您的性能，无论当前问题如何，这都是很好的。

此外，如果您发布 GC 日志的片段，这有助于为您指明正确的方向。

关于 jstat 工具，可以通过以下方式使用，获取有用信息:

jstat -gcutil <pid> <interval> 

我通常使用 1000 毫秒的间隔。 -gcutil 为您提供 GC 利用率(以 % 为单位) - 因此您可以查看是否有任何一代接近 100%。

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

EDIT :查看GC日志后

根据您的 GC 日志，它确认了您的 PermGen 正在填满的原始前提。
在 10:03:47 和 10:03:55 之间的时间范围内，我可以看到 PermGen 不断达到它的最大值，并且以某种方式删除了大约 10 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)]...

如果您查看 Old 和 Young 代，您会发现它们都没有达到最大值，OldGen 消耗了 10GB 中的 4GB - 所以这不是原因。

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

检查您的代码以确保您没有滥用 String 的 intern() 方法 - 如果您在代码中无缘无故地过度使用它，这可能是您的根本原因。

检查您正在使用的框架是否动态生成类 - 这也会消耗 PermGen 空间，但在一定程度上。

如果可以，请每周重新启动您的进程以防止停机

考虑增加 PermGen 空间，但要监控它，因为增加它可能只会延长您的 20 天期限，但不能解决问题。在这个过程持续足够长的时间后，永久代应该保持相当静态。

在 Google 上使用字符串 Coldfusion PermGen 进行搜索，产生了许多报告问题的点击 - 尝试按照这些搜索来集中精力进行调查。