通過JVM日志來進行安全點分析
許多事件都可能會導致JVM暫停所有的應用線程。這類暫停又被稱為"stop-the-world"（STW）暫停。觸發STW暫停最常見的原因就是垃圾回收了（github中的一個例子），但不同的JIT活動(例子)，偏向鎖擦除（例子），特定的JVMTI操作，以及許多場景也可能會導致應用程序暫停。
應用程序線程可以被安全地停止掉的那個時間點，就叫做安全點。這一術語也通常用來指代SWT暫停。
通常來講GC日志都是打開的。然而，并非所有安全點的信息都能完整地記錄下來。想獲取到完整的日志，可以使用下列的JVM選項：
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime
從參數名字來看你可能會覺得是與GC相關的，其實不然——打開這些選項能夠記錄下所有的安全點，而不止是GC暫停的。如果你用上述的選項來運行下這個例子（github源碼）
你會在標準輸出中看到如下信息：
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日志相比來說）——從中你可以得知應用程序在前344毫秒中是在處理實際工作的，然后將所有線程暫停了62毫秒，緊接著又工作了210ms，然后又暫停了89ms。
你還可以將這些選項與GC的選項結合起來使用，比如將上面這個程序加上-XX:+PrintGCDetails 選項后再運行一次，輸出則變成這樣了；
[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
綜上可知，應用線程被強制暫停了57ms來進行垃圾回收。其中又有8ms是用來等待所有的應用線程都到達安全點。如果我們用同樣的選項運行另一個例子(Github源碼)的話，輸出又變成這樣的了：
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
光從這些信息我們無從得知是什么導致的暫停，因為看不出有任何的垃圾回收的活動。如果你想更詳細地了解安全點的信息的話，可以使用這組JVM參數：
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1
啟用這些參數使得JVM會將一些額外的信息記錄到標準輸出中，大概類似這樣：
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
關于安全點的信息是按照如下的順序進行顯示的：
- JVM啟動之后所經歷的毫秒數（上例中是5.141）
- 觸發這次暫停的操作名（RevokeBias）。 如果你看見"no vm operation"，就說明這是一個"保證安全點"。JVM默認每秒會觸發一次安全點來處理那些非緊急的排隊的操作。GuaranteedSafepointInterval選項可以用來調整這一行為（設置為0的話就會禁用該功能）
- 停在安全點的線程的數量（13）
- 在安全點開始時仍在運行的線程的數量（0）
- 虛擬機操作開始執行前仍處于阻塞狀態的線程的數量（2）
- 到達安全點時的各個階段以及執行操作所花的時間（0） </ul>
因此我們可以看出，使用了偏向鎖會導致大量的STW暫停，盡管它們只花了幾十毫秒。在如今這個大量使用并發的年代，禁用它們也不是什么罕見的事情。
不管怎樣，多打印些日志總會減少一些麻煩事的。你可以使用如下的JVM參數：
-XX:+LogVMOutput -XX:LogFile=vm.log
所有的虛擬機日志都會輸出到vm.log文件中。如何解讀這些日志并做出響應是一個很大的課題，這已經遠超本文所討論的范圍了，不過未來我仍會更新一到兩篇文章來講下這個，請拭目以待.
來自：http://it.deepinmind.com/jvm/2015/05/25/logging-stop-the-world-pauses-in-jvm.html