JVM抖動如何由沒有對象分配的for循環引起？

Question

我一直在微觀基準測試下面的代碼，我注意到一些有趣的事情，我希望有人可以更多地瞭解。它導致了它看起來像for循環可以繼續快速運行，同時阻止JVM中的其他線程。如果那是真的，那麼我想明白爲什麼，如果不是真的，那麼對我可能缺少的東西的任何瞭解將不勝感激。

爲了構建這種情況，讓我引導您瞭解我正在運行的基準和結果。

該代碼非常簡單，遍歷數組中的每個元素，總結其內容。重複「targetCount」次數。

public class UncontendedByteArrayReadBM extends Benchmark { 

private int arraySize; 
private byte[] array; 

public UncontendedByteArrayReadBM(int arraySize) { 
    super("array reads"); 

    this.arraySize = arraySize; 
} 

@Override 
public void setUp() { 
    super.setUp(); 

    array = new byte[arraySize]; 
} 

@Override 
public void tearDown() { 
    array = null; 
} 

@Override 
public BenchmarkResult invoke(int targetCount) { 
    long sum = 0; 
    for (int i=0; i<targetCount; i++) { 
     for (int j=0; j<arraySize; j++) { 
      sum += array[j]; 
     } 
    } 

    return new BenchmarkResult(((long)targetCount)*arraySize, "uncontended byte array reads", sum); 
} 

} 

在我的4核 - 2Ghz英特爾Sandy Bridged/i7筆記本電腦上，在OSX上運行Java 6（Oracle JVM）。此代碼重複運行到

2.626852686364034無競爭字節數組讀取/ NS [totalTestRun = 3806.837ms]

（I已剔除用於加熱JVM的重複運行）

此結果似乎是合理我。

這裏有趣的是當我開始測量JVM抖動。要做到這一點，我開始一個睡眠1ms的後臺守護程序線程，然後計算出超過1ms的睡眠時間。我改變了報告，爲每次重複測試打印出最大抖動。

2.6109858273078306無競爭字節數組讀取/ NS [maxJitter = 0.411ms totalTestRun = 3829.971ms]

若要在開始實際的測試運行餘監視抖動沒有之前獲得「正常」的抖動爲我的環境，一個想法正在進行的工作和以下讀數是典型的（全部以毫秒爲單位）。因此0.411ms的抖動是正常的，並沒有那麼有趣。

getMaxJitterMillis() = 0.599 
getMaxJitterMillis() = 0.37 
getMaxJitterMillis() = 0.352 

我已經在這個問題的末尾包含了如何測量抖動的代碼。

有趣的一部分。但是，是的它確實在「JVM預熱」期間發生的，因此不是「正常」，但我想更詳細地瞭解如下：

2.4519521584902644 uncontended byte array reads/ns [maxJitter=2561.222ms totalTestRun=4078.383ms] 

注意抖動超過2.5秒。通常我會把它放到GC。但是，在測試運行之前，我確實觸發了一個System.gc（），而-XX：+ PrintGCDetails此時不顯示GC。事實上，在任何測試運行期間沒有GC，因爲在總結預先分配的字節的測試中沒有發生對象分配。每次我運行新的測試時都會發生這種情況，因此我並不認爲它是隨機發生的其他進程的干擾。

我的好奇心飆升，因爲當我注意到雖然抖動非常高，但總運行時間以及每納秒的數組元素讀取數量實際上保持不變。所以這裏是一個線程在4核心機器上嚴重滯後的情況，而工作線程本身沒有滯後，並且沒有GC正在進行。

調查進一步我看着什麼熱點編譯器操作的方式，發現通過-XX以下：+ PrintCompilation：

2632 2%  com.mosaic.benchmark.datastructures.array.UncontendedByteArrayReadBM::invoke @ 14 (65 bytes) 
6709 2%  made not entrant com.mosaic.benchmark.datastructures.array.UncontendedByteArrayReadBM::invoke @ -2 (65 bytes) 

被打印出這兩條線之間的滯後爲約2.5秒。正確的時候，包含big for循環的方法已將其優化後的代碼標記爲不再進入。

我的理解是，Hotspot在後臺線程上運行，當它準備好交換新代碼時，它會等待已經運行的代碼達到安全點，然後交換。在每個循環體的末尾有一個大的for循環的情況下（可能已經展開了一些循環體）。我不希望有2.5秒的延遲，除非這個換出必須在JVM上執行停止世界事件。它是否在去優化以前的編譯代碼時做到這一點？

所以我對JVM內部專家的第一個問題是，我在這裏的正確軌道上？延遲2.5s是否可以歸因於將該方法標記爲「未進入」。如果是這樣，爲什麼它會對其他線程產生如此極端的影響？如果這不可能是原因，那麼關於還有哪些其他調查方面的想法會很棒。

（爲了完整性，這裏是我使用的測量抖動的代碼）

private static class MeasureJitter extends Thread { 
    private AtomicLong maxJitterWitnessedNS = new AtomicLong(0); 

    public MeasureJitter() { 
     setDaemon(true); 
    } 

    public void reset() { 
     maxJitterWitnessedNS.set(0); 
    } 

    public double getMaxJitterMillis() { 
     return maxJitterWitnessedNS.get()/1000000.0; 
    } 

    public void printMaxJitterMillis() { 
     System.out.println("getMaxJitterMillis() = " + getMaxJitterMillis()); 
    } 

    @Override 
    public void run() { 
     super.run(); 

     long preSleepNS = System.nanoTime(); 
     while(true) { 
      try { 
       Thread.sleep(1); 
      } catch (InterruptedException e) { 
       e.printStackTrace(); 
      } 

      long wakeupNS = System.nanoTime(); 
      long jitterNS = Math.max(0, wakeupNS - (preSleepNS+1000000)); 

      long max = Math.max(maxJitterWitnessedNS.get(), jitterNS); 
      maxJitterWitnessedNS.lazySet(max); 

      preSleepNS = wakeupNS; 
     } 
    } 
} 

Answer 1

這花了一些時間去尋找吸菸槍，但這些經驗教訓很有價值;特別是如何證明和隔離原因。所以我認爲在這裏記錄他們是件好事。

JVM確實在等待執行Stop The World事件。 Alexey Ragozin在http://blog.ragozin.info/2012/10/safepoints-in-hotspot-jvm.html有一篇關於此主題的非常好的博客文章，這篇文章讓我走上了正確的軌道。他指出，安全點在JNI方法邊界和Java方法調用上。因此我在這裏的for循環沒有安全的地方。

要了解停止在Java世界的事件使用以下JVM標誌：-XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

第一個打印出一個阻止世界事件的總持續時間，並且它不僅限於GC。在這裏我的情況下打印出來：

Total time for which application threads were stopped: 2.5880809 seconds 

這證明我有一個問題，線程在等待到達安全點。接下來的兩個參數顯示了爲什麼JVM想要等待全局安全點。

  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 

因此，這表示JVM在嘗試啓用偏置鎖定時等待了2678ms。爲什麼這是阻止世界事件？值得慶幸的是，馬丁湯普森在過去也遇到了這個問題，並且他記錄了它here。事實證明，Oracle JVM在啓動過程中有很多線程爭用，在此期間，偏向鎖定的成本非常高，因此它延遲優化四秒鐘。所以這裏發生的事情是我的微型基準測試超過了四秒鐘，然後它的循環沒有安全點。所以，當JVM試圖轉向Biased Locking時，必須等待。

候選方案，所有的工作對我來說是：

1. -XX：-UseBiasedLocking（轉偏向鎖關閉）
2. -XX：BiasedLockingStartupDelay = 0（使能立即偏向鎖）
3. 更改循環內有一個安全的點（例如，一個方法調用沒有得到優化或內聯）

Answer 2

有抖動的原因很多

• 睡眠是在毫秒的水平非常不可靠。
• 上下文切換
• 中斷
• 高速緩存未命中，由於運行

即使你忙等待，綁定線程，以便向CPU已經分離的其他程序，例如使用isocpus，並移動所有可以關閉該CPU的中斷，仍然可以看到少量的抖動。你所能做的就是減少它。

順便說一句：jHiccup完全是你在做什麼來衡量你的系統的抖動。