WAS GC 日志分析

WAS GC日志native_stderr.log分析

 

       我们可以通过添加JVM启动参数 -verbose:gc 或者在管理控制台上勾选详细垃圾回收选项来打印更详细的GC日志，缺省日志记录文件是native_stderr.log文件。

不同的GC策略，日志内容会有所不同，以下是optthruput策略时，记录的详细GC日志：

<af type="tenured" id="24" timestamp="Dec 31 14:51:48 2015" intervalms="494944.872">

af（allocation fail）：触发垃圾回收的事件，af为分配失败。如果是sys，则表示应用程序有显示调用System.gc()方法，不建议使用显示gc()方法，可以通过 -Xdisableexplicitgc参数屏蔽显式GC

type="tenured"：GC类型，tenured/长存区的收集，另一种情况nursery/婴儿区收集

id="24"：tenured区GC的次数，这是第24次tenured区的垃圾回收

timestamp="Dec 31 14:51:48 2015"：GC发生的时间戳

intervalms="494944.872"：距离上一次GC的时间

  <minimum requested_bytes="16944" />

  申请的堆大小为16944byte，垃圾收集并分配后，freebytes可能下降超过这个大小。原因是空闲列表可能会被丢弃或线程本地堆(TLH)刷新

  <time exclusiveaccessms="0.059" meanexclusiveaccessms="0.059" threads="0" lastthreadtid="0x0000000017093E00" />

  exclusiveaccessms="0.059"：准备GC前花费的时间0.059ms

  <refs soft="2363" weak="12244" phantom="774" dynamicSoftReferenceThreshold="9" maxSoftReferenceThreshold="32" />

  refs：提供关于java对象引用的信息

  soft="2363"：2363个SoftReference/软引用对象。最先处理软引用对象，如果内存空间足够，就不会回收软引用对象

  weak="12244"：12244个WeakReference/弱引用对象。软引用对象处理完后，处理弱引用对象

  phantom="774"：774个PhantomReference/虚引用对象。弱引用对象处理完后，处理虚引用对象

  dynamicSoftReferenceThreshold="9"：软引用对象在被回收前可以生存的GC周期，此值会动态调整，如果堆空间使用率很高，可能会降低此阈值

  maxSoftReferenceThreshold="32"：软引用对象在被回收前可以生存的最大GC周期，32次

↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓ GC前堆空间使用情况↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓

  <tenured freebytes="10241336" totalbytes="64998400" percent="15" >

  freebytes="10241336"：空闲空间10241336byte

  totalbytes="64998400"：总空间大小为64998400byte

  percent="15"：空闲空间约占总空间大小的15%

<soa freebytes="9781560" totalbytes="64538624" percent="15" />

soa：小对象分配区域；在分配对象时，首先尝试在小对象区域中进行分配。如果找不到足够大小的可用项来满足分配，并且请求的大小等于或大于64KB，那么将再次在loa中尝试分配。如果请求大小小于64KB或者loa中没有足够的连续空间，那么将触发分配故障。如果小对象区域中的可用自由空间量远远大于分配请求大小，但是还无法满足请求，则表明堆中都是碎片。

freebytes="9781560"：空闲空间9781560byte

totalbytes="64538624"：总空间64538624byte

percent="15"：空闲空间约占总空间大小的15%

<loa freebytes="459776" totalbytes="459776" percent="100" />

loa：大对象分配区域；大对象区域是堆中保留给大对象分配的一小片区域。垃圾收集器会根据loa空间的使用情况来进行扩展或收缩

freebytes="9781560"：空闲空间9781560byte

totalbytes="64538624"：总空间64538624byte

percent="15"：空闲空间约占总空间大小的100%，即未使用

  </tenured>

  <pending-finalizers finalizable="592" reference="5" classloader="0" />

  pending-finalizers：表示可终结队列的当前状态

  <gc type="global" id="26" totalid="26" intervalms="494945.222">

  type="global"：global/全局收集，另一种情况为scavenger/清扫

  id="26"：这是第26次发生全局GC

  totalid="26"：GC总共发生了26次

  intervalms="494945.222"：此次GC花费了494945.222ms

    <finalization objectsqueued="592" />

<timesms mark="95.729" sweep="1.073" compact="0.000" total="96.912" />

mark="95.729"：标记花费的时间95.729ms

sweep="1.073"：清扫花费的时间1.073ms

compact="0.000"：压缩花费的时间 0.000ms，未发生压缩

total="96.912"：此次GC共花费了96.912ms

↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓ GC后堆空间使用情况↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓

<tenured freebytes="22360600" totalbytes="64998400" percent="34" >

freebytes="22360600"：空闲空间22360600byte

totalbytes="64998400"：总空间64998400byte

percent="34"：空闲空间约占总空间大小的34%

      <soa freebytes="21966360" totalbytes="64604160" percent="34" />

      soa：小对象分配区域；

      freebytes="21966360"：空闲空间21966360byte

      totalbytes="64604160"：总空间64604160byte

      percent="34"：空闲空间约占总空间大小的34%

      <loa freebytes="394240" totalbytes="394240" percent="100" />

      soa：大对象分配区域；

      freebytes="394240"：空闲空间394240byte

      totalbytes="394240"：总空间394240byte

      percent="100"：空闲空间100%

    </tenured>

  </gc>

↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓满足分配后堆空间使用情况↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓

  <tenured freebytes="22343656" totalbytes="64998400" percent="34" >

    <soa freebytes="21949416" totalbytes="64604160" percent="33" />

    <loa freebytes="394240" totalbytes="394240" percent="100" />

  </tenured>

  <refs soft="2354" weak="12073" phantom="774" dynamicSoftReferenceThreshold="11" maxSoftReferenceThreshold="32" />

  <pending-finalizers finalizable="592" reference="5" classloader="0" />

  <time totalms="97.038" />

</af>