我正在协助一个项目来调整他们的应用程序服务器环境,并且我看到来自IBM JRE的冗长的gc日志中的一些相当混乱的输出,我比Hotspot更不熟悉.在许多情况下,似乎与我在供应商的文档中看到的内容相矛盾.这适用于在IBM的1.7_64 JRE上运行的在Websphere上运行的应用程序.这个特定的运行是使用gencon GC策略,堆大小为4GB.以下是全局GC的详细：gc输出示例,它是众多歧义的来源,我将在下面详细介绍：
<exclusive-start id="8574" timestamp="2015-09-08T22:48:45.819" intervalms="2919.893">
<response-info timems="0.229" idlems="0.069" threads="43" lastid="0000000005FF6800" lastname="WebContainer : 37" />
</exclusive-start>
<sys-start id="8575" timestamp="2015-09-08T22:48:45.820" intervalms="3028473.245" />
<cycle-start id="8576" type="global" contextid="0" timestamp="2015-09-08T22:48:45.820" intervalms="3028473.281" />
<gc-start id="8577" type="global" contextid="8576" timestamp="2015-09-08T22:48:45.820">
<mem-info id="8578" free="462493104" total="4155310080" percent="11">
<mem type="nursery" free="80236904" total="934084608" percent="8" />
<mem type="tenure" free="382256200" total="3221225472" percent="11">
<mem type="soa" free="221195336" total="3060164608" percent="7" />
<mem type="loa" free="161060864" total="161060864" percent="100" />
</mem>
<remembered-set count="16780" />
</mem-info>
</gc-start>
<allocation-stats totalBytes="745771152" >
<allocated-bytes non-tlh="193377184" tlh="552393968" />
<largest-consumer threadName="WebContainer : 49" threadId="000000000659E600" bytes="156075608" />
</allocation-stats>
<gc-op id="8579" type="mark" timems="609.025" contextid="8576" timestamp="2015-09-08T22:48:46.429">
<trace-info objectcount="9486509" scancount="7257956" scanbytes="246533016" />
<finalization candidates="1528" enqueued="411" />
<ownableSynchronizers candidates="32" cleared="0" />
<references type="soft" candidates="63260" cleared="0" enqueued="0" dynamicThreshold="30" maxThreshold="32" />
<references type="weak" candidates="27120" cleared="11" enqueued="0" />
<references type="phantom" candidates="17361" cleared="7885" enqueued="7885" />
<stringconstants candidates="153217" cleared="105" />
</gc-op>
<gc-op id="8580" type="classunload" timems="1.114" contextid="8576" timestamp="2015-09-08T22:48:46.430">
<classunload-info classloadercandidates="4306" classloadersunloaded="26" classesunloaded="26" quiescems="0.000" setupms="0.955" scanms="0.108" postms="0.051" />
</gc-op>
<gc-op id="8581" type="sweep" timems="18.520" contextid="8576" timestamp="2015-09-08T22:48:46.449" />
<gc-op id="8582" type="compact" timems="2209.475" contextid="8576" timestamp="2015-09-08T22:48:48.658">
<compact-info movecount="9482641" movebytes="539414400" reason="compact on aggressive collection" />
</gc-op>
<gc-end id="8583" type="global" contextid="8576" durationms="2839.085" timestamp="2015-09-08T22:48:48.659">
<mem-info id="8584" free="3615704600" total="4155310080" percent="87">
<mem type="nursery" free="834618336" total="934084608" percent="89" />
<mem type="tenure" free="2781086264" total="3221225472" percent="86">
<mem type="soa" free="2620025400" total="3060164608" percent="85" />
<mem type="loa" free="161060864" total="161060864" percent="100" />
</mem>
<pending-finalizers system="367" default="44" reference="7885" classloader="0" />
<remembered-set count="15785" />
</mem-info>
</gc-end>
<cycle-end id="8585" type="global" contextid="8576" timestamp="2015-09-08T22:48:48.659" />
<sys-end id="8586" timestamp="2015-09-08T22:48:48.659" />
<exclusive-end id="8587" timestamp="2015-09-08T22:48:48.659" durationms="2839.704" />
问题包括：
1)GC操作的时间戳(标记为gc-op)似乎是在操作完成时,而不是从启动时开始. IBM doc暗示时间戳是该操作发生的时间(http://www-01.ibm.com/support/knowledgecenter/SSYKE2_7.0.0/com.ibm.java.zos.71.doc/diag/tools/gcpd_verbose_operation.html).但是,在查看操作的时间戳和持续时间(由timems属性标识)时,数字不会相加.但是,如果将时间戳解释为操作完成时,而不是在操作开始时,它们会加起来并且有意义.为了说明,在上面的示例输出中执行了以下操作,这些是它们提供的持续时间和时间戳(我已经舍入了数字)：
operation - duration - timestamp
mark - 609ms - 48:46.429
classunload - 1ms - 48:46.430
sweep - 19ms - 48:46.449
compact - 2209ms - 48:48.658
可以看出,如果将时间戳解释为开始时间,则时间戳没有意义.但是,如果将它们解释为结束时间.例如,classunload时间戳值等于makr时间戳加上classunload持续时间(如果时间戳指示操作何时开始,则不应加上标记持续时间).同样,扫描时间戳等于classunload时间戳加上扫描持续时间.
有人可以确认这是否是预期的行为,还是我只是错误地阅读？
2)另一个问题似乎是日志中的每个操作都是从头到尾的全程操作.我预计清除GC将全部停止,但是,我从IBM看到的所有文档都表明,全球GC的标记阶段至少应该同时完成.但是,这也不是上面GC日志条目中发生的情况.在这个例子中,似乎一切都是作为一个句号完成的,并且标记的任何部分或者扫描都不是同时完成的.每个(较旧的)文档至少部分标记应该同时进行,因为并非全部停止世界暂停(http://www.ibm.com/developerworks/java/library/j-ibmjava2/)
是否有一个设置可以使终身代的全球GC同时成为周期的一部分？我知道这是在IBM JREs optavgpause收集器以及Hotspot并发收集器中完成的,这两者都不是特别新技术,因此不清楚为什么gencon每次必须做的时候总是强制完全停止世界全球收藏.这很重要,因为上面指出的2.8秒暂停将使我们与客户端的SLA发生冲突.
3)在上面的全球气相色谱中,从苗圃的占用数量可以看出,在这次手术中它也被收集(苗圃在GC之前只有8％免费,之后只有89％).但是,我没有看到关于输出中托儿所中发生的GC的相关信息.我希望看到这里记录的scavange操作.有谁知道为什么这个缺失？这是因为在全球GC期间,还通过相同的堆行走(标记 – 扫描 – 紧凑)方法收集托儿所,因为当全局GC发生时,终身空间是什么？
最佳答案 你是对的,因为你看到停止了由独家开始和独家终端覆盖整个周期的世界收藏.我觉得有趣的是,当堆甚至没有完全分配时,你会看到一个全局gc.
我认为你有sys-start和sys-end条目的原因似乎表明你的应用程序(或远程GC)中的某些东西正在触发System.gc(),你应该首先解决这个问题并获得一个新的一套gc日志.
