13

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

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

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

通过查看堆栈跟踪并将 ProcessExplorer 中的 ThreadID 与堆栈转储中的相关联，我知道它们在 GC 中。每个 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 秒=0.3584434 秒=0 时间。 0.36秒] 2013-03-19T22：14：55.078 + 1100：128864.099：[GC [PSYOUNGGEN：4722063K-> 498009K（4783104K）9327990K-> 5103936K（15705792K），0.3766889秒，0.3766889秒] [次数：user = 5.37 sys = 0.00 , real=0.38 秒] 2013-03-19T22:17:46.749+1100: 1289035.760: [GC [PSYoungGen: 4654489K->517299K(4673792K)] 9260416K->5123227K(155930580K), 0.s [时间 1:40580K), 0. sys=0.00, real=0.41 secs] 2013-03-19T22:21:08.762+1100: 1289237.763: [GC [PSYoungGen: 4673779K->522660K(4738880K)] 9279707K->5143831K(156605516K s) [043831K->5143831K(156605516K s) 0.Time用户=5.97 系统=0.00，实际=0.40 秒] 2013-03-19T22:23:42.683+1100:1289391.675:[GC [PSYoungGen:4582628K->530998K(4590976K)] 9203799K->5186242K(15513664K), 0.4317352 秒] [时间: 用户=6.24 系统=0.00, 实际=0.43 秒] 2013-03-19T22:26:11.096+1100: [GCPSYoungGen5.90: 128 4590966K->518331K(4724096K)] 9246210K->5206959K(15646784K)，0.3914401 秒] [时间：用户=5.99 系统=0.00，实际=0.39 秒] 2013-03-19T22:257:44.0763:3. [GC] [PSYOUNGGEN：2602730K-> 447527K（4732864K）] 7291358K-> 5208743K（15655552K），0.3725317秒，0.3725317秒] [次数：User = 5.80 Sys = 0.00，Real = 0.37秒] 2013-03-19T22：27：4448 + 1100：1289633.428 ：[全GC（系统）[PSYOUNGGEN：447527K-> 0K（4732864K）] [PARORDGEN：4761215K-> 4628296K - > 4628296K（15655552K）[PSPermgen：352378K-> 352287K（352832K），4.2955639秒] [时间：用户 = 57.70 系统 = 0.06，实际 = 4.30 秒] 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: [12GC861599] 4054116K->109175K(4092352K)] 8682413K->4737472K(15015040K), 0.1347919 秒] [时间: 用户=1.03 系统=0.00, 实际=0.13 秒] 2013-03-19T22:306: [32.9016+] [PSYoungGen: 4092343K->147318K(4712320K)] 8720640K->4775615K(15635008K), 0.1593523 secs] [Times: user=1.58 sys=0.00, real=0.16 secs] 24092343K->147318K(4712320K)] 8720640K->4775615K(15635008K)，0.1593523 秒] [时间：用户=1.58 系统=0.00，实际=0.16 秒] 24092343K->147318K(4712320K)] 8720640K->4775615K(15635008K)，0.1593523 秒] [时间：用户=1.58 系统=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 秒] [时间: 用户=0.16 系统= 0.01 秒] 2013-03-22T10:03:47.631+1100: 1504185.912: [完整 GC [PSYoungGen: 0K->0K(5452736K)] [ParOldGen: 4413907K->4412613K(10922688K)] 44133901->44133K017664426 PSPermGen: 358399K->358278K(358400K)], 5.4435442 秒] [时间: 用户=73.74 系统=0.14, 真实=5.44 秒] 2013-03-22T10:03:53.145+1100: 1504191.26926: [GCK-PSYoungGen: >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: [Full 1.456: 15041: PSYoungGen: 7734K->0K(5449088K)] [ParOldGen: 4414379K->4415189K(10922688K)] 4422114K->4415189K(16371776K) [PSPermGen: 358399K->358371K(358400K).,6033684 秒] [时间：用户=36.33 系统=0.00，实际=2.60 秒] 2013-03-22T10:03:55.788+1100: 1504194.069: [GC [PSYoungGen: 94969K->826K(5451328K)] 4410101K58K->446101K58K->4 16374016K），0.0133588 秒] [时间：用户 = 0.16 系统 = 0.00，实际 = 0.01 秒] 2013-03-22T10：03：55.802+1100：1504194.082：[完整 GC [PSYoungGen：826K->0K（5451328K）] ParOldGen: 4415189K->4415348K(10922688K)] 4416015K->4415348K(16374016K) [PSPermGen: 358399K->358389K(358400K)], 2.7156884 secs] [Times: user=38.171 sys=0002,=2.71 系统4415189K->4415348K(10922688K)] 4416015K->4415348K(16374016K) [PSPermGen: 358399K->358389K(358400K)], 2.7156884 secs] [Times: user=38.11 sys=0.0.0.04415189K->4415348K(10922688K)] 4416015K->4415348K(16374016K) [PSPermGen: 358399K->358389K(358400K)], 2.7156884 secs] [Times: user=38.11 sys=0.0.0.0

4

1 回答 1

5

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

此外，正如提到的评论之一 -假设问题出在老年代的容量上，使用 CMS 集合（并发标记和扫描）可以减少您的Stop the World 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 和 Young 代，您会发现它们都没有达到最大值，OldGen 正在消耗 10GB 中的 4GB - 所以这不是原因。

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

  1. 检查您的代码以确保您没有滥用String'sintern()方法 - 如果您无缘无故地在代码中使用它过于广泛，这可能是您的根本原因。
  2. 检查您正在使用的框架是否动态生成类 - 这也会消耗 PermGen 空间，但在一定程度上。
  3. 如果可以，请每周重新启动您的流程以防止这种停机时间
  4. 考虑增加永久代空间，但要监控它，因为增加它可能只会延长你的 20 天期限，但不能解决问题。在该过程已经存在足够长的时间之后，PermGen 应该保持相当静态。
  5. 使用字符串Coldfusion PermGen在 Google 上运行搜索会产生许多报告问题的结果 - 尝试关注这些结果以专注于您的调查。
于 2013-03-22T19:27:49.063 回答