通過 JVM 日誌來進行安全點分析
百度搜索：小強測試品牌
轉發+點贊=支持
交流群：522720170
許多事件都可能會導致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）
因此我們可以看出，使用了偏向鎖會導致大量的STW暫停，盡管它們只花了幾十毫秒。在如今這個大量使用並發的年代，禁用它們也不是什麽罕見的事情。
不管怎樣，多打印些日誌總會減少一些麻煩事的。你可以使用如下的JVM參數：
-XX:+LogVMOutput -XX:LogFile=vm.log
所有的虛擬機日誌都會輸出到vm.log文件中。
轉發+點贊=支持
微信二維碼 QQ群二維碼
通過 JVM 日誌來進行安全點分析