title: GC pauses of 5 seconds but mark, sweep and compact take less than 1 second
body: <p>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.</p>
  
  <pre><code>&lt;con event="collection" id="1" timestamp="Oct 22 13:34:10 2015" intervalms="0.000"&gt;   &lt;time exclusiveaccessms="0.195" /&gt;   &lt;nursery freebytes="871692288" totalbytes="966367232" percent="90" /&gt;   &lt;tenured freebytes="375809024" totalbytes="7516192768" percent="4" &gt;
      &lt;soa freebytes="0" totalbytes="7140383744" percent="0" /&gt;
      &lt;loa freebytes="375809024" totalbytes="375809024" percent="100" /&gt;   &lt;/tenured&gt;   &lt;stats tracetarget="2430736896"&gt;
      &lt;traced total="2804446392" mutators="2591437504" helpers="213008888" percent="115" /&gt;
      &lt;cards cleaned="1874" kickoff="102056216" /&gt;   &lt;/stats&gt;   &lt;con event="remembered set scan"&gt;
      &lt;stats objectsfound="17649" traced="110458224" timetakenms="129.797" /&gt;   &lt;/con&gt;   &lt;con event="final card cleaning"&gt;
      &lt;stats cardscleaned="334" traced="9118008" durationms="7.732" /&gt;   &lt;/con&gt;   &lt;gc type="global" id="1" totalid="929" intervalms="0.000"&gt;
      &lt;classloadersunloaded count="162267" timetakenms="4957.805" /&gt;
      &lt;refs_cleared soft="1942" threshold="32" weak="164659" phantom="0" /&gt;
      &lt;finalization objectsqueued="120" /&gt;
      ***&lt;timesms mark="258.390" sweep="33.125" compact="0.000" total="5267.373" /&gt;***
      &lt;nursery freebytes="904360200" totalbytes="966367232" percent="93" /&gt;
      &lt;tenured freebytes="3848182720" totalbytes="7516192768" percent="51" &gt;
        &lt;soa freebytes="3472373696" totalbytes="7140383744" percent="48" /&gt;
        &lt;loa freebytes="375809024" totalbytes="375809024" percent="100" /&gt;
      &lt;/tenured&gt;   &lt;/gc&gt;   &lt;nursery freebytes="904360200" totalbytes="966367232" percent="93" /&gt;   &lt;tenured freebytes="3848182720" totalbytes="7516192768" percent="51" &gt;
      &lt;soa freebytes="3472373696" totalbytes="7140383744" percent="48" /&gt;
      &lt;loa freebytes="375809024" totalbytes="375809024" percent="100" /&gt;   &lt;/tenured&gt;   &lt;time totalms="5406.538" /&gt; &lt;/con&gt;
  </code></pre>
  
  <p>How can I find which activity part of the full GC is taking the bulk of the pause time?</p>
  
  <p>Thanks</p>