title: YGC(ParNew) real time is much more that user+sys times
body: <p>We have a Web Java based application running on JBoss with allowed maximum heap size of about 2.2 GB (Young Generation is 400MB, total machine physical memory is 4 GB). At some point the application stops responding (to clients) for several minutes. After some analysis we found out that the culprit is the Young Generation GC. Here's an excerpt from the verbose GC log:</p>
  
  <pre><code>Heap before GC invocations=3844 (full 7):
   par new generation   total 614336K, used 614272K,  eden space 614272K, 100% used,  from space 64K,   0% used,  to   space 64K,   0% used , concurrent mark-sweep generation total 921600K, used 690936K, concurrent-mark-sweep perm gen total 262144K, used 65905K 2679114.965: [GC 2681684.725: [ParNew: 614272K-&gt;0K(614336K), 0.0132460 secs] 1305208K-&gt;692360K(1535936K), 0.0135020 secs] [Times: user=0.03 sys=0.03, real=2569.62 secs] 
  Heap after GC invocations=3845 (full 7):
   par new generation   total 614336K, used 0K,  eden space 614272K,   0% used,  from space 64K,  to   space 64K,   0% used, concurrent mark-sweep generation total 921600K, used 692360K, concurrent-mark-sweep perm gen total 262144K, used 65905K
  Total time for which application threads were stopped: 2569.7748610 seconds
  </code></pre>
  
  <p>What I don't understand is how is it possible that the real time spent on ParNew GC is about 42 minutes (2569 seconds), while user+sys times are just 0.06 seconds, and pause time for the minor collection is just 0.0132460 seconds. </p>
  
  <p>we guess "virtual memory thrashing" or "high cpu load" may cause this problem, and we test two case:</p>
  
  <ol>
  <li><p>we start several other programe which uses a while loop to use 100% cpu, and the GC log is as follows:
  6052.217: [GC 6052.217: [ParNew: 409288K->0K(409536K), 1.9456320 secs] 480161K->72140K(1638336K), 1.9460370 secs] [Times: user=0.03 sys=0.00, real=1.95 secs] </p></li>
  <li><p>we start several other progarm which take a lot of memory, and now the GC log is as follows: 
  11710.051: [GC 11710.058: [ParNew: 409472K->0K(409536K), 5.9080290 secs] 489119K->81136K(1638336K), 5.9256280 secs]</p></li>
  </ol>
  
  <p>At any of these two case, the time of Young generation GC becomes longer, but pause time for the minor collection is about equal with the realtime, it seem not any one of them cause above long time pause.</p>
  
  <p>But Where does all the other time go?</p>