Note that there are some explanatory texts on larger screens.

plurals
  1. PO
    primarykey
    data
    text
    <p>This took some digging to find the smoking gun, but the lessons have been valuable; especially on how to prove and isolate the cause. So I thought it good to document them here.</p> <p>The JVM was indeed waiting to perform a Stop The World event. Alexey Ragozin has a very good blog post about this topic at <a href="http://blog.ragozin.info/2012/10/safepoints-in-hotspot-jvm.html" rel="nofollow">http://blog.ragozin.info/2012/10/safepoints-in-hotspot-jvm.html</a> and this was the post that got me onto the right track. He points out that safe points are on JNI method boundaries and Java method calls. Thus the for loop that I have here has no safe points in it.</p> <p>To understand stop the world events in Java use the following JVM flags: <code>-XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1</code></p> <p>The first prints out the total duration of a stop the world event, and it is not limited to just GC. In my case here that printed out:</p> <pre><code>Total time for which application threads were stopped: 2.5880809 seconds </code></pre> <p>Which proved that I had a problem with threads waiting to reach a safe point. The next two arguments print out why the JVM wanted to wait for a global safe point to be reached.</p> <pre><code> vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 4.144: EnableBiasedLocking [ 10 1 1 ] [ 2678 0 2678 0 0 ] 0 Total time for which application threads were stopped: 2.6788891 seconds </code></pre> <p>So this says that the JVM waited 2678ms while trying to enable Biased Locking. Why is this a stop the world event? Thankfully Martin Thompson has also hit this problem in the past and he has documented it <a href="http://mechanical-sympathy.blogspot.co.uk/2011/11/biased-locking-osr-and-benchmarking-fun.html" rel="nofollow">here</a>. It turns out that the Oracle JVM has quite a lot of thread contention during startup, during that time biased locking has a very high cost so it delays turning the optimisation on for four seconds. So what happened here was that my micro benchmark went over four seconds and then its loop had no safe points in it. So when the JVM tried to turn Biased Locking on it had to wait.</p> <p>Candidate solutions that all worked for me were:</p> <ol> <li>-XX:-UseBiasedLocking (turn biased locking off)</li> <li>-XX:BiasedLockingStartupDelay=0 (enable biased locking immediately)</li> <li>Change the loop to have a safe point within it (eg a method call that does not get optimised out or inlined)</li> </ol>
    singulars
    1. This table or related slice is empty.
    plurals
    1. This table or related slice is empty.
    1. This table or related slice is empty.
    1. This table or related slice is empty.
    1. VO
      singulars
      1. This table or related slice is empty.
    2. VO
      singulars
      1. This table or related slice is empty.
    3. VO
      singulars
      1. This table or related slice is empty.
    1. This table or related slice is empty.
 

Querying!

 
Guidance

SQuiL has stopped working due to an internal error.

If you are curious you may find further information in the browser console, which is accessible through the devtools (F12).

Reload