通過 JVM 日誌來進行安全點分析
小強python全棧自動化測試培訓班招生中，開課時間為18年3月7號
在17年12月之前報名並繳納全部費用的童鞋優惠100元；
老學員另有更多優惠！
所有報名的同學均贈送《小強軟體測試瘋狂講義》書一本。
另，全面支持支付寶花唄、信用卡支付！解大家燃眉之急
報名微信長按下方二維碼
轉發+點贊=支持
許多事件都可能會導致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群二維碼
※不愛說話？社交無能？或許你可以試試這種說話術
※自動化測試到底是什麼
※別總想著房價了，好好想想35歲以後你還能幹什麼
※在Jmeter中使用Selenium WebDriver完成測試
TAG:小強軟體測試與脫口秀 |