(乾貨篇) JVM stop the world

1、遇到的問題

Total time for which application threads were stop 超級長時間，這行日誌表明什麼，以及爲何時間會這麼長 ?

2、日誌的含義

Total time for which application threads were stopp 2.81 seconds，Stopping threads took ：2.6 seconds

當GC發生時，每一個線程只有進入了SafePoint纔算是真正掛起，也就是真正的停頓，這個日誌的含義是整個GC過程當中STW的時間，配置了 -XX:+PrintGCApplicationStoppedTime 這個參數纔會打印這個信息。

重點： 第一個 2.81 seconds 是JVM啓動後的秒數，第二個 2.6 seconds 是 JVM發起STW的開始到結束的時間。特別地，若是是GC引起的STW，這條內容會緊挨着出如今GC log的下面。

3、安全點是什麼

1. 從線程的角度，安全點是代碼執行中的一些特殊位置，當線程執行到這些特殊的位置，若是此時在GC，那麼在這個地方線程會暫停，直到GC結束。
2. GC的時候要掛起全部活動的線程，所以線程掛起，會選擇在到達安全點的時候掛起。
3. 安全點這個特殊的位置保存了線程上下文的所有信息。說白了，在進入安全點的時候打印日誌信息能看出線程此刻都在幹嗎。

有關安全點的詳細說明，請移步：

JVM源碼分析之安全點safepoint

[Java JVM] Hotspot GC研究- GC安全點 (Safepoint&Stop The World)

4、什麼是STW(stop the world)

等待全部用戶線程進入安全點後並阻塞，作一些全局性操做的行爲。

5、何時會STW？（換句話說何時會觸發進入安全點？）

• Garbage collection pauses（垃圾回收）

• JIT相關，好比Code deoptimization, Flushing code cache

• Class redefinition (e.g. javaagent，AOP代碼植入的產生的instrumentation)

• Biased lock revocation 取消偏向鎖

• Various debug operation (e.g. thread dump or deadlock check) dump 線程

6、STW的說明

配置 -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 參數，虛擬機會打印以下日誌文件:

-XX:+PrintSafepointStatistics 打印安全點統計信息，

-XX:PrintSafepointStatisticsCount=n 設置打印安全點統計信息的次數；

6.1 日誌分析：

1. vmop： 引起STW的緣由，以及觸發時間，本例中是GC。該項常見的輸出有：RevokeBias、BulkRevokeBias、Deoptimize、G1IncCollectionPause。

   數字306936.812是虛擬機啓動後運行的秒數。GC log能夠根據該項內容定位Total time for which application threads…引起的詳細信息。

2. total ： STW發生時，JVM存在的線程數目。

3. initially_running ： STW發生時，仍在運行的線程數，這項是Spin階段的 時間來源

4. wait_to_block ： STW須要阻塞的線程數目，這項是block階段的時間來源

5. sync = spin + block + 其餘。

6.2 由日誌能夠看出，safepoint的執行分爲四個階段：

1. Spin階段。由於jvm在決定進入全局safepoint的時候，有的線程在安全點上，而有的線程不在安全點上，這個階段是等待未在安全點上的用戶線程進入安全點。
2. Block階段。即便進入safepoint，用戶線程這時候仍然是running狀態，保證用戶不在繼續執行，須要將用戶線程阻塞。
3. Cleanup。這個階段是JVM作的一些內部的清理工做。
4. VM Operation. JVM 執行的一些全局性工做，例如 GC, 代碼反優化。

6.3 vmop 輸出說明

RevokeBias、BulkRevokeBias、偏向鎖取消狀況。

Deoptimize、

G1IncCollectionPause GC GC 執行狀況。

6.3 優化說明

分析 -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 產生的日誌信息基本上STW的緣由都是RevokeBias或者BulkRevokeBias。這個是撤銷偏向鎖操做，雖然每次暫停的 時間很短，可是特別頻繁出現也會很耗時。

一些高併發的系統中，禁掉JVM偏向鎖優化，能夠提高系統的吞吐量。禁用偏向鎖的參數爲: -XX:-UseBiasedLocking

7、引發長時間STW緣由

• GC
• RevokeBias 撤銷偏向鎖操做也會消耗很長時間。在高併發系統中，建議禁用偏向鎖。
• 百分之九十的狀況都是以上2個緣由。

8、現場

線上配置 -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 參數，虛擬機打印以下日誌文件:

果真是撤銷偏向鎖搞得鬼，增長 -XX:-UseBiasedLocking 後，問題獲得解決.