主题
IBM JDK GC日志 3
IBM JDK GC日志
使用编辑器打开
使用顺手的编辑器，可以打开此文件。
<exclusive-start id="342" timestamp="2020-03-24T15:50:49.632" intervalms="3597.446">
<response-info timems="0.129" idlems="0.129" threads="0" lastid="00000000097C3A00" lastname="pool-44-thread-122" />
</exclusive-start>
<af-start id="343" totalBytesRequested="24" timestamp="2020-03-24T15:50:49.633" intervalms="3597.551" />
<cycle-start id="344" type="scavenge" contextid="0" timestamp="2020-03-24T15:50:49.633" intervalms="3597.293" />
<gc-start id="345" type="scavenge" contextid="344" timestamp="2020-03-24T15:50:49.633">
<mem-info id="346" free="4097676128" total="6442450944" percent="63">
<mem type="nursery" free="0" total="1610612736" percent="0">
<mem type="allocate" free="0" total="1449525248" percent="0" />
<mem type="survivor" free="0" total="161087488" percent="0" />
</mem>
<mem type="tenure" free="4097676128" total="4831838208" percent="84">
<mem type="soa" free="3856084832" total="4590246912" percent="84" />
<mem type="loa" free="241591296" total="241591296" percent="100" />
</mem>
<remembered-set count="11910" />
</mem-info>
</gc-start>
<allocation-stats totalBytes="1431723304" >
<allocated-bytes non-tlh="1472136" tlh="1430251168" />
<largest-consumer threadName="WebContainer : 32" threadId="0000000009139000" bytes="17775112" />
</allocation-stats>
<gc-op id="347" type="scavenge" timems="4.152" contextid="344" timestamp="2020-03-24T15:50:49.637">
<scavenger-info tenureage="14" tenuremask="4000" tiltratio="89" />
<memory-copied type="nursery" objects="66135" bytes="8672664" bytesdiscarded="483976" />
<finalization candidates="91" enqueued="52" />
<ownableSynchronizers candidates="6" cleared="0" />
<references type="soft" candidates="454" cleared="0" enqueued="0" dynamicThreshold="30" maxThreshold="32" />
<references type="weak" candidates="519" cleared="9" enqueued="8" />
<references type="phantom" candidates="557" cleared="0" enqueued="0" />
</gc-op>
<gc-end id="348" type="scavenge" contextid="344" durationms="4.789" usertimems="21.177" systemtimems="1.924" timestamp="2020-03-24T15:50:49.638" activeThreads="8">
<mem-info id="349" free="5538029248" total="6442450944" percent="85">
<mem type="nursery" free="1440353120" total="1610612736" percent="89">
<mem type="allocate" free="1440353120" total="1449525248" percent="99" />
<mem type="survivor" free="0" total="161087488" percent="0" />
</mem>
<mem type="tenure" free="4097676128" total="4831838208" percent="84">
<mem type="soa" free="3856084832" total="4590246912" percent="84" />
<mem type="loa" free="241591296" total="241591296" percent="100" />
</mem>
<pending-finalizers system="52" default="0" reference="8" classloader="0" />
<remembered-set count="8493" />
</mem-info>
</gc-end>
<cycle-end id="350" type="scavenge" contextid="344" timestamp="2020-03-24T15:50:50.056" />
<allocation-satisfied id="351" threadId="00000000097C3A00" bytesRequested="24" />
<af-end id="352" timestamp="2020-03-24T15:50:50.056" />
<exclusive-end id="353" timestamp="2020-03-24T15:50:50.056" durationms="424.055" />
|
这一段，基本结构和昨日的差不多。还是有细微区别的：
af-start，表明这是一次分配失败触发的GC
cycle-start中的type="scavenge"表明这是一次对堆的清理
由gc-start和gc-end，我们了解到实际上只清理了新生代，持久代没有被清理
特别地，我们阅读gc-start发现新生代的free都已经是0了。而再阅读gc-end，发现新生代的幸存者区，还是满的。这就说明，有相当一部分对象，长期占据了幸存者区。
只有当对象从幸存者区毕业升级到持久代，幸存者区才能慢慢空下来。
本次GC与上次GC的间隔，阅读exclusive-start的intervalms可以得到，还好。但是持续时间，不太理想。这个数据可以通过阅读exclusive-end的durationms得到。0.4s是一个比较长的时间了。
建议
格式相对来说比较简单，可读性较强，建议自己分析一遍。