title: What causes increase in vmop time during safepoint application thread pause, while performing GC
body: <p>I'm running Java7 (Java HotSpot(TM) 64-Bit Server VM (build 24.76-b04, mixed mode) on a Linux Server 2.6.32-504.el6.x86_64 (RHEL); with few GC switches enabled as shown below.</p>
  
  <p>The problem appears to be a  significant increase in time while pausing application thread (> 3Sec); And based on the safepointstatistics it appear to be related to vmop operations.</p>
  
  <p>I have observed there isn't much overhead due to GC nor any allocation failures, only minor collections take place during program execution. The GC log pasted below contains reference from the GC just before the application thread pausing took longer than 3Sec and the GC showing the actual delay. </p>
  
  <p><em>Questions</em></p>
  
  <ol>
  <li><p>Could this time sink be related to the Server freezing up or not being responsive, this is based on the assumption real time took 3.02 Sec and there has been no indication of any overhead due to GC. ([Times: user=0.02 sys=0.00, real=3.02 secs])</p></li>
  <li><p>Is there any utility available that would monitor a systems responsiveness, or is there any recommended algorithm that could be used to measure the server responsivness</p></li>
  <li><p>What causes increase in vmop time? </p></li>
  <li><p>Does JVM perform any Disk IO while initiating garbage collection; in otherwords, before pausing the application thread at a safepoint, does JVM perform any diskIO; or can a system with high diskIO activity during GC cause the delay in pausing application thread.   </p></li>
  </ol>
  
  <p><em>Server Configurations:</em></p>
  
  <p><em>Please note there are several applications running on this server, this is not a dedicated server for the mentioned application.</em> </p>
  
  <pre><code>model name: Intel(R) Xeon(R) CPU X5365  @ 3.00GHz / 8 Core
  
               total       used       free     shared    buffers     cached
  Mem:      24602892   22515868    2087024        244     165796   10801380
  -/+ buffers/cache:   11548692   13054200'
  </code></pre>
  
  <p><em>GC Options enabled:</em></p>
  
  <pre><code>-XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/opt/swxsmf_fep/working/gk-gc-CMS.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCApplicationStoppedTime\
   -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+PrintGCApplicationConcurrentTime
  </code></pre>
  
  <p><em>Previous GC (showing no issues)</em></p>
  
  <pre><code>2015-04-08T19:05:24.622+0100: 522569.387: Application time: 16.4710580 seconds
  2015-04-08T19:05:24.622+0100: 522569.387: [GC2015-04-08T19:05:24.622+0100: 522569.387: [ParNew: 102798K-&gt;79K(115456K), 0.0018020 secs] 105218K-&gt;2499K(371776K), 0.0019090 secs] [Times: user=0.02 sys=0.00, rea
  l=0.00 secs]
  2015-04-08T19:05:24.624+0100: 522569.389: Total time for which application threads were stopped: 0.0021910 seconds
  </code></pre>
  
  <p><em>GC where real time > 3 Sec</em></p>
  
  <pre><code>vmop [threads: total initially_running wait_to_block]  [time: spin block sync cleanup vmop] page_trap_count
  522588.500: GenCollectForAllocation          [      22          0              0    ]      [     0     0     0     0  3019    ]  0
  
      2015-04-08T19:05:43.747+0100: 522588.512: Application time: 19.1232430 seconds
      2015-04-08T19:05:43.748+0100: 522588.512: [GC2015-04-08T19:05:46.765+0100: 522591.530: [ParNew: 102735K-&gt;77K(115456K), 0.0017640 secs] 105155K-&gt;2497K(371776K), 3.0195450 secs] [Times: user=0.02 sys=0.00, real=3.02 secs]
  2015-04-08T19:05:46.767+0100: 522591.532: Total time for which application threads were stopped: 3.0198060 seconds
  </code></pre>
  
  <p>Any input on this would be very much appreciated, please let me know if you require any futher details. </p>