GC 暂停 5 秒，但标记、扫描和压缩不到 1 秒答案

【问题标题】：GC pauses of 5 seconds but mark, sweep and compact take less than 1 secondGC 暂停 5 秒，但标记、扫描和压缩不到 1 秒
【发布时间】：2016-01-21 17:58:24
【问题描述】：

我有一个使用 gencon GC 策略运行具有 8 GB 堆的 JVM 进程的 AIX 服务器。今天我有 5 秒的暂停时间，这令人担忧。我查看了 GC 日志中的事件，但无法弄清楚所有这些时间都花在了哪里。

<con event="collection" id="1" timestamp="Oct 22 13:34:10 2015" intervalms="0.000">   <time exclusiveaccessms="0.195" />   <nursery freebytes="871692288" totalbytes="966367232" percent="90" />   <tenured freebytes="375809024" totalbytes="7516192768" percent="4" >
    <soa freebytes="0" totalbytes="7140383744" percent="0" />
    <loa freebytes="375809024" totalbytes="375809024" percent="100" />   </tenured>   <stats tracetarget="2430736896">
    <traced total="2804446392" mutators="2591437504" helpers="213008888" percent="115" />
    <cards cleaned="1874" kickoff="102056216" />   </stats>   <con event="remembered set scan">
    <stats objectsfound="17649" traced="110458224" timetakenms="129.797" />   </con>   <con event="final card cleaning">
    <stats cardscleaned="334" traced="9118008" durationms="7.732" />   </con>   <gc type="global" id="1" totalid="929" intervalms="0.000">
    <classloadersunloaded count="162267" timetakenms="4957.805" />
    <refs_cleared soft="1942" threshold="32" weak="164659" phantom="0" />
    <finalization objectsqueued="120" />
    ***<timesms mark="258.390" sweep="33.125" compact="0.000" total="5267.373" />***
    <nursery freebytes="904360200" totalbytes="966367232" percent="93" />
    <tenured freebytes="3848182720" totalbytes="7516192768" percent="51" >
      <soa freebytes="3472373696" totalbytes="7140383744" percent="48" />
      <loa freebytes="375809024" totalbytes="375809024" percent="100" />
    </tenured>   </gc>   <nursery freebytes="904360200" totalbytes="966367232" percent="93" />   <tenured freebytes="3848182720" totalbytes="7516192768" percent="51" >
    <soa freebytes="3472373696" totalbytes="7140383744" percent="48" />
    <loa freebytes="375809024" totalbytes="375809024" percent="100" />   </tenured>   <time totalms="5406.538" /> </con>

如何找到完整 GC 的哪个活动部分占用了大部分暂停时间？

谢谢

【问题讨论】：

标签： java garbage-collection jvm aix

【解决方案1】：

您没有附加任何示例 GC 日志，但根据您的描述，您正在运行 CMS 收集器。长时间的停顿通常是由完整的 GC 引起的，这种情况有时会发生在这个收集器上——它主要是并发的。我建议在有问题的时候上传一些示例 GC 日志，并查看这篇名为“Understanding CMS GC Logs”的文章。

【讨论】：

好吧，gc 在设计上很慢（cf en.wikipedia.org/wiki/Glossary_of_graph_theory#Walks），但不时手动调用它（System.gc）可能是个好主意，而不是让它从它开始自己的意志。 [此评论属于原始问题-我的错，对不起]
我不确定调用 System.gc() 是否会产生您想要的效果，因为不能保证调用垃圾收集器。这基本上是对 JVM 的建议。其次，JVM 会在程序的整个生命周期内调用垃圾收集器时进行优化，不断尝试找到干扰最小的最佳位置。在这方面真的很难比 JVM 更好。第三，CMS 收集器非常快。您拥有的图表参考仅指 GC 所做的停止世界暂停，并且 CMS 尝试在到达该点之前使用多个并发阶段来最小化这种暂停。
上传其他 GC 日志只会显示大量的 scavenge GC。我看到 5s 暂停的一个 GC 事件显示在我的原始问题中。其他 GC 事件与它无关。如果我说这句话有误，请告诉我。这将有助于我了解周围的 GC 事件（之前或之后）对整个 GC 持续时间有任何影响。
好吧，调用 System.gc 可能什么都不做，但也可能释放内存（我有过这种情况的经验），所以调用它没有风险。而且，如果它这么聪明，这个话题就不存在了；）
Zsigmond，公平地反驳我关于 JVM 聪明的观点。 :-) 我之前在调用它的时候也记不住了，但你真的不能指望它。通过 JVM args 调整收集器时，我的经验更加积极。

【解决方案2】：

扫描类加载器所花费的时间不计入总和：

<classloadersunloaded count="162267" timetakenms="4957.805" />

您在内存中有 162267 个类加载器，扫描时间为 4957.805 毫秒。这似乎是已知问题，解决方法和修复在这里：http://www-01.ibm.com/support/docview.wss?uid=swg1IZ76742

【讨论】：

这是否意味着我的应用程序将在整个 4.9 秒内停止？我的假设是这意味着我有 258.390（标记）+ 33.125（扫描）+ 4957（卸载类加载器）= 5267ms，其中服务器不会响应任何请求。对吗？
没错。卸载类加载器是全局 GC 循环的一部分。它不会在标记/扫描/紧凑下报告，因为那些裁判你的应用程序的数据堆和类加载器是你的可执行代码。本文可能有助于理解这些类加载器的来源：ibm.com/developerworks/library/j-nativememory-aix，请参阅“类和类加载器”部分
这是我的赏金问题和我的以下问题的答案。你完全配得上你的赏金积分。享受:) -Xgc:classUnloadingKickoffThreshold 参数对我没有帮助，因为我使用的是 IBM Java 5，但您评论中的文章指出我有一个 java 参数，即 -Xshareclasses:none。我假设禁用类数据共享意味着应用程序将开始使用重复的类加载器，并且它是增加 ClassloadersLoaded 数量的来源。我认为我应该删除它是否正确？