GC暂停5秒钟，但标记，扫描和紧凑时间少于1秒 [英] GC pauses of 5 seconds but mark, sweep and compact take less than 1 second

问题描述

我有一台AIX服务器，使用gencon GC策略运行带有8 GB堆的JVM进程。今天我有5秒的暂停时间。

 < con event我查看了GC日志中的事件，但无法计算出所有时间都花在哪里。 =collectionid =1timestamp =Oct 22 13:34:10 2015intervalms =0.000> < time exclusiveaccessms =0.195/> < nursery freebytes =871692288totalbytes =966367232percent =90/> < tenured freebytes =375809024totalbytes =7516192768percent =4> 
< soa freebytes =0totalbytes =7140383744percent =0/> 
< loa freebytes =375809024totalbytes =375809024percent =100/> < /终身> < stats tracetarget =2430736896> 
< traced total =2804446392mutators =2591437504helpers =213008888percent =115/> 
< cards cleared =1874kickoff =102056216/> < /统计> < con event =记住集合扫描> 
< stats objectsfound =17649traced =110458224timetakenms =129.797/> < / CON> < con event =最终卡片清洁> 
< stats cardscleaned =334traced =9118008durationms =7.732/> < / CON> < gc type =globalid =1totalid =929intervalms =0.000> 
< classloadersunloaded count =162267timetakenms =4957.805/> 
< refs_cleared soft =1942threshold =32weak =164659phantom =0/> 
< finalization objectsqueued =120/> 
 ***< timesms mark =258.390sweep =33.125compact =0.000total =5267.373/> *** 
  < soa freebytes =3472373696totalbytes =7140383744percent =48/> 
< loa freebytes =375809024totalbytes =375809024percent =100/> 
< / tenured> < / GC> < nursery freebytes =904360200totalbytes =966367232percent =93/> < tenured freebytes =3848182720totalbytes =7516192768percent =51> 
< soa freebytes =3472373696totalbytes =7140383744percent =48/> 
< loa freebytes =375809024totalbytes =375809024percent =100/> < /终身> < time totalms =5406.538/> < / CON> 
  

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

谢谢

解决方案

总计：

 < classloadersunloaded count =162267timetakenms =4957.805/> 
  

内存中的162267类加载器需要4957.805ms才能扫描。这似乎是已知的问题，解决方法和修复方法如下： http：// www-01.ibm.com/support/docview.wss?uid=swg1IZ76742

I have an AIX server running a JVM process with 8 GB heap using gencon GC policy. Today I had 5s pause time which is concerning. I looked at the event in the GC log but couldn't figure out where all that time is spent.

<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>

How can I find which activity part of the full GC is taking the bulk of the pause time?

Thanks

解决方案

Time taken for scan of class loaders is not accounted for in total:

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

You have 162267 class loaders in memory taking 4957.805ms to scan. This seems to be known problem, workaround and fix are here: http://www-01.ibm.com/support/docview.wss?uid=swg1IZ76742

这篇关于GC暂停5秒钟，但标记，扫描和紧凑时间少于1秒的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！