通過JVM日誌來進行安全點分析

Java譯站發表於2015-05-25
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 選項後再執行一次，輸出則變成這樣了；

[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檔案中。如何解讀這些日誌並做出響應是一個很大的課題，這已經遠超本文所討論的範圍了，不過未來我仍會更新一到兩篇文章來講下這個，請拭目以待.

相關文章