不同的事件可能導(dǎo)致JVM暫停所有應(yīng)用程序線程。 這種暫停稱為世界停止（STW）暫停。 觸發(fā)STW暫停的最常見原因是垃圾回收（ 例如github中的示例 ），但是不同的JIT操作（ 示例 ），偏向鎖吊銷（ 示例 ），某些JVMTI操作以及更多其他 操作也需要停止應(yīng)用程序。

可以安全停止應(yīng)用程序線程的點稱為“意外點”。 該術(shù)語也經(jīng)常用于指代所有STW暫停。

啟用GC日志或多或少是常見的。 但是，這不會捕獲所有安全點上的信息。 要獲得全部信息，請使用以下JVM選項：

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

如果您想知道顯式引用GC的命名，請不要驚慌-啟用這些選項會記錄所有安全點，而不僅僅是垃圾收集暫停。 如果您運(yùn)行下面的示例（ github中的源代碼），并帶有上面指定的標(biāo)志

public class FullGc {private static final Collection<Object> leak = new ArrayList<>();private static volatile Object sink;public static void main(String[] args) {while (true) {try {leak.add(new byte[1024 * 1024]);sink = new byte[1024 * 1024];} catch (OutOfMemoryError e) {leak.clear();}}} }

您應(yīng)該在標(biāo)準(zhǔn)輸出中看到類似于以下內(nèi)容的條目：

Application time: 0.3440086 seconds Total time for which application threads were stopped: 0.0620105 seconds Application time: 0.2100691 seconds Total time for which application threads were stopped: 0.0890223 seconds

讀取起來很容易（尤其是與GC日志進(jìn)行比較）–從上面您可以看到應(yīng)用程序在前344毫秒內(nèi)成功完成了有用的工作，將所有線程暫停了62毫秒，接著是210毫秒的有用工作和另外89毫秒的暫停。

您可以將這些標(biāo)志與GC標(biāo)志結(jié)合使用，例如，當(dāng)再次運(yùn)行同一程序并添加-XX：+ PrintGCDetails時 ，輸出將類似于以下內(nèi)容：

[Full GC (Ergonomics) [PSYoungGen: 1375253K->0K(1387008K)] [ParOldGen: 2796146K->2049K(1784832K)] 4171400K->2049K(3171840K), [Metaspace: 3134K->3134K(1056768K)], 0.0571841 secs] [Times: user=0.02 sys=0.04, real=0.06 secs] Total time for which application threads were stopped: 0.0572646 seconds, Stopping threads took: 0.0000088 seconds

基于以上內(nèi)容，我們看到應(yīng)用程序線程被迫停止57毫秒以進(jìn)行垃圾回收。 等待所有應(yīng)用程序線程到達(dá)安全點所花的時間為8微秒。 但是，如果我們再舉一個示例（ github中的源代碼 ）并使用相同的選項運(yùn)行它，我們可能會看到以下輸出：

Total time for which application threads were stopped: 0.0001273 seconds, Stopping threads took: 0.0000196 seconds Total time for which application threads were stopped: 0.0000648 seconds, Stopping threads took: 0.0000174 seconds

由此，我們實際上無法推斷出導(dǎo)致暫停的原因，因為沒有垃圾收集活動。 如果您想更詳細(xì)地了解其他安全點，這里有幾個JVM參數(shù)供您選擇：

-XX:+PrintSafepointStatistics ?-XX:PrintSafepointStatisticsCount=1

啟用它們會使JVM將其他信息記錄到標(biāo)準(zhǔn)輸出中，類似于以下內(nèi)容：

5.141: RevokeBias ??????????????????????[ ?????13 ?????????0 ?????????????2 ???] ?????[ ????0 ????0 ????0 ????0 ????0 ???] ?0 ? Total time for which application threads were stopped: 0.0000782 seconds, Stopping threads took: 0.0000269 seconds

根據(jù)以下順序顯示有關(guān)安全點的信息：

• 自JVM啟動以來的時間戳（以毫秒為單位）（上例中為5.141）
• 觸發(fā)暫停的操作的名稱（ RevokeBias ）。
  • 如果看到“無虛擬機(jī)操作”，則意味著這是所謂的“保證安全點”。
• 在安全點停止的線程數(shù)（13）
• 在安全點開始時運(yùn)行的線程數(shù)（0）
• vm操作開始執(zhí)行時被阻塞的線程數(shù)（2）
• 到達(dá)安全點和執(zhí)行操作的各個階段的時間（全零）

因此，現(xiàn)在我們看到，使用偏向鎖可能會導(dǎo)致許多STW暫停發(fā)生，即使它們僅花費數(shù)十微秒的時間。 在大規(guī)模并行的日子里立即禁用它們并不罕見。

總而言之，通過隨時記錄這些數(shù)據(jù)，您確實可以為自己省去一些麻煩。 為此，請指定以下JVM選項：

-XX:+LogVMOutput -XX:LogFile=vm.log

并且所有JVM的輸出都將存儲到vm.log文件中。 但是，基于這些日志進(jìn)行解釋和執(zhí)行是一個非常廣泛的話題，不在本文的討論范圍之內(nèi)，但是將來我可能會寫一兩篇有關(guān)它的文章，因此，如有興趣，請隨時關(guān)注–通過我們的Twitter訂閱或通過RSS feed 。

如果您想立即內(nèi)容，請閱讀Nitsan Wakart的精彩博客文章 ：當(dāng)然還有OpenJDK源代碼 。

翻譯自: https://www.javacodegeeks.com/2015/04/logging-stop-the-world-pauses-in-jvm.html

總結(jié)

以上是生活随笔為你收集整理的在JVM中记录世界停顿的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。