偶尔会遇到长时间的垃圾收集延迟，为啥？
Posted
技术标签:
【中文标题】偶尔会遇到长时间的垃圾收集延迟，为啥？【英文标题】：Experiencing occasional long garbage collection delays, why?偶尔会遇到长时间的垃圾收集延迟，为什么？ 【发布时间】：2010-10-09 07:57:30 【问题描述】：我很难处理 Java 垃圾收集问题和解释日志。
我的应用程序要求 GC 的时间不超过 2 秒，最好少于 100 毫秒。
根据之前的一些建议，我正在尝试以下命令行选项：
java -XX:MaxGCPauseMillis=100 -XX:NewRatio=9 -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -server -Xmx9g -Xms9g
应用程序有大量长期存储的对象，这些对象保存在 ConcurrentLinkedHashMap 中。我看到偶尔的长时间停顿，在最坏的情况下长达 10 秒（这是下面 GC 日志的倒数第二个）！
这是我得到的一些输出：
16938.968: [GC 16938.968: [ParNew: 153343K->17022K(153344K), 7.8608580 secs] 6184328K->6122510K(9420160K) icms_dc=7 , 7.8614100 secs] [Times: user=0.63 sys=0.01, real=7.86 secs]
16947.087: [GC 16947.087: [ParNew: 153342K->17022K(153344K), 7.2604030 secs] 6258830K->6198642K(9420160K) icms_dc=7 , 7.2609780 secs] [Times: user=0.44 sys=0.00, real=7.27 secs]
16954.614: [GC 16954.614: [ParNew: 153342K->17024K(153344K), 8.4307620 secs] 6334962K->6274625K(9420160K) icms_dc=7 , 8.4313150 secs] [Times: user=0.62 sys=0.01, real=8.43 secs]
16963.310: [GC 16963.310: [ParNew: 153344K->17023K(153344K), 6.2588760 secs] 6410945K->6350748K(9420160K) icms_dc=7 , 6.2594290 secs] [Times: user=0.48 sys=0.01, real=6.25 secs]
16969.834: [GC 16969.834: [ParNew: 153343K->17022K(153344K), 6.0274280 secs] 6487068K->6425868K(9420160K) icms_dc=7 , 6.0279830 secs] [Times: user=0.50 sys=0.01, real=6.03 secs]
16976.122: [GC 16976.123: [ParNew: 153342K->17022K(153344K), 11.7774620 secs] 6562188K->6503030K(9420160K) icms_dc=7 , 11.7780180 secs] [Times: user=0.43 sys=0.04, real=11.78 secs]
16988.164: [GC 16988.164: [ParNew: 153342K->17024K(153344K), 10.9477920 secs] 6639350K->6579928K(9420160K) icms_dc=7 , 10.9483440 secs] [Times: user=0.37 sys=0.02, real=10.95 secs]
16999.371: [GC 16999.372: [ParNew: 153344K->17023K(153344K), 9.8828360 secs] 6716248K->6655886K(9420160K) icms_dc=7 , 9.8833940 secs] [Times: user=0.42 sys=0.01, real=9.88 secs]
17009.509: [GC 17009.509: [ParNew: 153343K->17023K(153344K), 5.0699960 secs] 6792206K->6727987K(9420160K) icms_dc=7 , 5.0705660 secs] [Times: user=0.55 sys=0.01, real=5.07 secs]
17014.838: [GC 17014.838: [ParNew: 153343K->17023K(153344K), 6.6411750 secs] 6864307K->6790974K(9420160K) icms_dc=7 , 6.6417400 secs] [Times: user=0.37 sys=0.01, real=6.63 secs]
17021.735: [GC 17021.735: [ParNew: 153343K->17024K(153344K), 8.0545970 secs] 6927294K->6856409K(9420160K) icms_dc=7 , 8.0551790 secs] [Times: user=0.34 sys=0.03, real=8.05 secs]
17030.052: [GC 17030.053: [ParNew: 153344K->17023K(153344K), 7.9756730 secs] 6992729K->6922569K(9420160K) icms_dc=7 , 7.9762530 secs] [Times: user=0.34 sys=0.01, real=7.98 secs]
17038.398: [GC 17038.398: [ParNew: 153343K->17022K(153344K), 12.9613300 secs] 7058889K->6990725K(9420160K) icms_dc=7 , 12.9618850 secs] [Times: user=0.39 sys=0.01, real=12.96 secs]
17051.630: [GC 17051.630: [ParNew: 153342K->17022K(153344K), 6.8942910 secs] 7127045K->7059607K(9420160K) icms_dc=7 , 6.8948380 secs] [Times: user=0.56 sys=0.02, real=6.89 secs]
17058.798: [GC 17058.798: [ParNew: 153342K->17024K(153344K), 10.0262190 secs] 7195927K->7126351K(9420160K) icms_dc=7 , 10.0267860 secs] [Times: user=0.37 sys=0.01, real=10.02 secs]
17069.096: [GC 17069.096: [ParNew: 153344K->17023K(153344K), 10.0419500 secs] 7262671K->7195002K(9420160K) icms_dc=7 , 10.0425020 secs] [Times: user=0.40 sys=0.02, real=10.04 secs]
17079.410: [GC 17079.410: [ParNew: 153343K->17022K(153344K), 13.5389040 secs] 7331322K->7264275K(9420160K) icms_dc=7 , 13.5394610 secs] [Times: user=0.30 sys=0.01, real=13.54 secs]
17093.223: [GC 17093.224: [ParNew: 153342K->17023K(153344K), 10.5909450 secs] 7400595K->7330446K(9420160K) icms_dc=7 , 10.5915060 secs] [Times: user=0.33 sys=0.00, real=10.58 secs]
17104.083: [GC 17104.084: [ParNew: 153343K->17024K(153344K), 5.8420210 secs] 7466766K->7392173K(9420160K) icms_dc=7 , 5.8425920 secs] [Times: user=0.57 sys=0.00, real=5.84 secs]
我花了好几个小时翻阅各种描述 Java GC 调优的网页，但没有一个真正让我能够解释上面的日志并提出行动方案。任何基于我提供的日志的具体建议将不胜感激。
更新：根据以下问题：
这台机器有 16G 内存，下面是上面的信息： 内存：总共 15483904k，已使用 15280084k，空闲 203820k，155684k 缓冲区 交换：总计 2031608k，已使用 1347240k，免费 684368k，缓存 3304044k
这是一个不同的运行，但这里是该进程的当前最高输出：
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1016 sanity 17 0 10.2g 6.5g 9464 S 1 44.2 10:24.32 java
更新 2： 一些更详细的日志记录，这看起来导致了 400 毫秒的延迟：
Heap before GC invocations=1331 (full 1):
par new generation total 153344K, used 153343K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
eden space 136320K, 100% used [0x00002aaaae200000, 0x00002aaab6720000, 0x00002aaab6720000)
from space 17024K, 99% used [0x00002aaab77c0000, 0x00002aaab885fff0, 0x00002aaab8860000)
to space 17024K, 0% used [0x00002aaab6720000, 0x00002aaab6720000, 0x00002aaab77c0000)
concurrent mark-sweep generation total 7169664K, used 4258496K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
484.738: [GC 484.738: [ParNew: 153343K->17022K(153344K), 0.3950480 secs] 4411840K->4341689K(7323008K), 0.3954820 secs] [Times: user=0.49 sys=0.07, real=0.40 secs]
Heap after GC invocations=1332 (full 1):
par new generation total 153344K, used 17022K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
eden space 136320K, 0% used [0x00002aaaae200000, 0x00002aaaae200000, 0x00002aaab6720000)
from space 17024K, 99% used [0x00002aaab6720000, 0x00002aaab77bfb68, 0x00002aaab77c0000)
to space 17024K, 0% used [0x00002aaab77c0000, 0x00002aaab77c0000, 0x00002aaab8860000)
concurrent mark-sweep generation total 7169664K, used 4324666K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
【问题讨论】：
你可以使用 -XX:+PrintHeapAtGC 并发布结果吗？这会让你知道每个垃圾回收周期前后每一代的确切大小。 【参考方案1】：我觉得你的注意力可能有点偏了。
花一点时间在分析器中查找您最大的分配热点。如果您的代码中只有少数几个地方发生了大部分分配，请尝试使用对象池，而不是总是构造新对象。
集合类和 StringBuilder 是池化的绝佳候选者。当您将它们返回到池中时，调用 collection.clear() 或 stringbuilder.setLength(0) 方法，以便在下一个调用者想要从池中检索它们时可以使用它们。
调整 GC 的最佳方法是创建更少的对象。消除分配的策略有很多，池化只是其中之一（尽管是我最喜欢的策略之一）。
更新：我写这个答案已经五年了，我对池化的看法已经发生了很大变化。当我在 2009 年写这个答案时，我可以经常使用对象池（即使是像 StringBuilder 这样的简单对象）来加速具有大量分配的紧密内部循环。这些天来，很难找到合并不会使情况变得更糟的情况。除了线程或连接之外，我几乎从不使用池。尽管如此，即使您不经常使用它，它仍然是一个不错的工具。
【讨论】：
对象池实际上被 sun GC 的人所反对。 GC 专门针对这种情况进行了调整。 GC 特别喜欢不变的对象。 我应该更仔细地阅读这个问题，尤其是在他说他的大部分对象都是长寿的地方。但是对于人们在短期对象上遇到 GC 滞后的情况，我坚持我的建议。即使 Sun 不鼓励这样做，我在分析和调优 Java 应用程序方面的十年经验告诉我，池有时可以是一个很好的解决方案，具有多种好处：它不仅可以减少 GC 的负担，还可以显着减少花费在构造函数。 池化主要只对那些比平均构建成本高得多的对象或持有外部或本地资源的对象有益。对于具有现代 JVM 的普通 Java 对象，如今池化的范围从“它不会伤害您”到不优化。【参考方案2】：对我来说，问题是完整的幸存者空间。由于 CMS 不是压缩的，垃圾被直接提升到老一代。对于这么大的堆，这可能非常昂贵。需要增加 Survivor 空间和 MaxTenuringThreshold 以尽可能避免提升。
问候，亚历克斯
【讨论】：
【参考方案3】：我想你有这个UseConcMarkSweepGC and NewRatio bug。由于您的新空间远不及-Jmx=9G 的十分之一。该错误包括一种解决方法（绝对大小为 NewSize）。
另一个可能对您非常重要的标志是CMSInitiatingOccupancyFraction。它在 java6 中设置为 92%，在 java5 中设置为 68%。如果旧空间变大，CMS 线程池将开始工作。如果你有 CPU 可以使用，那么有一个高于初始分数的 live-set 是没有危险的。
如果您在修复内存分页问题后包含 GC 统计信息，那就太好了。
【讨论】：
【参考方案4】：原来问题在于堆被换出到磁盘，延迟是 Java 的 GC 必须等待它被换回。
（大部分）通过将 Linux 的“swappiness”参数设置为 0 来解决。
【讨论】：
您是如何确定这一点的？我怀疑我的一个应用程序可能会遇到同样的问题。【参考方案5】：9 GB JVM ！以前从未见过！我想你的 10 秒。停顿是很正常的。 see this（也许你已经读过了……）
【讨论】：
【参考方案6】：您能否发布/链接到 ConcurrentLinkedHashMap 实现的代码？如果这是我发布的实现，请在项目页面上开一张票，以便我们一起调试。如果没有，了解您的实施细节将有助于确定问题所在。
【讨论】：
【参考方案7】：如果没有实际看到，并且在某些情况下对代码进行分析，可能很难分辨。
您是否为任何对象实现了 finalize()？这将导致巨大的 GC 惩罚。 看到一个可能有 6 Gigs 堆的测试运行也会很有趣，如果你在性能方面得到了不成比例的改进，这表明 GC 正在为内存而颠簸。
【讨论】：
【参考方案8】：从时间上看，GC 似乎并没有一直运行（查看用户时间），所以大部分时间都是在等待。
只是一个疯狂的猜测：它不会交换吗？机器有多少内存？ java进程得到了多少（驻留集大小）？
编辑：为什么要等待：
看看这个（来自你的成绩单）
[Times: user=0.39 sys=0.01, real=12.96 secs]
这意味着（我猜从 GC 开始到结束），12（几乎 13）秒过去了。在这 13 秒中，0.39 秒用于在用户模式下运行，0.01 秒用于在内核模式下运行。如果时间收集方法没有完全缺陷（即数字确实代表 GC 进程/线程的运行时间），这意味着至少要等待 12 秒。
【讨论】：
您能否详细说明为什么它会花费大部分时间等待？ 感谢您的额外解释，但我想问题是：它可能在等待什么？ IO？将数据从交换中拉入 RAM？ 可能。您可以通过检查主要故障计数来判断（top 不提供该信息，但 atop 提供） ...嗯。应该是交换。【参考方案9】：您是否通过分析器运行您的应用程序，以查看您认为在内存方面发生的事情与实际发生的事情有关？
当我研究这个时，我做的一件事是使用 Netbeans 分析器（尽管任何分析器都应该给你这个）是查看实时字节（内存分配），看看那些是否有大量分配的字节和分配的对象是我所期望的，并且来自我期望的地方。
您也可以使用分析器查看调整的效果，在没有任何调整参数的情况下运行应用程序，然后添加调整参数并再次运行它，看看内存发生了什么。
【讨论】：
【参考方案10】：如果您有严格的时间要求，也许您应该查看Java Real-Time System。
RTSJ /Java RTS 提供：
API 集、语义 Java VM 增强和 JVM 到 OS 层的修改使 Java 开发人员能够正确推理和控制 Java 应用程序的时间行为。
【讨论】：
【参考方案11】：一般来说，当您需要如此大的堆时，很难正确调整 GC。
话虽如此，大部分 GC 挂起时间是由在年轻垃圾回收中存活的对象的内存复制引起的。
您的 ConcurrentLinkedHashMap 是否一次性使用所有内存持久对象进行了初始化？还是随着应用程序的继续运行，它会慢慢变大？如果是后者，则可能很难减少 GC 挂起时间，因为有些对象始终存在。如果是前者，你需要将你的永久代的大小调整为持久对象的大小 + 20% 左右，并确保你的年轻代足够大，以跟上在创建过程中创建的瞬态对象。你的申请。
【讨论】：
【参考方案12】：你见过吗？
http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html
还有，看看...
http://java.sun.com/javase/6/docs/technotes/guides/visualvm/index.html
【讨论】：
【参考方案13】：也许 200ms 的性能限制太严格了，您需要自己管理垃圾收集？ 你试过用更大的限制吗？
【讨论】：
以上是关于偶尔会遇到长时间的垃圾收集延迟，为啥？的主要内容，如果未能解决你的问题，请参考以下文章