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

杜老師說 2022-01-07 08:27:10 阅读数:252

jvm 日志 安全 分析

原文鏈接 作者: Plumbr 譯者:之諸暇

許多事件都可能會導致JVM暫停所有的應用線程。這類暫停又被稱為”stop-the-world”(STW)暫停。觸發STW暫停最常見的原因就是垃圾回收了(github中的一個例子),但不同的JIT活動(例子),偏向鎖擦除(例子),特定的JVMTI操作,以及許多場景也可能會導致應用程序暫停。

應用程序線程可以被安全地停止掉的那個時間點,就叫做安全點。這一術語也通常用來指代SWT暫停。

通常來講GC日志都是打開的。然而,並非所有安全點的信息都能完整地記錄下來。想獲取到完整的日志,可以使用下列的JVM選項:

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

從參數名字來看你可能會覺得是與GC相關的,其實不然——打開這些選項能够記錄下所有的安全點,而不止是GC暫停的。如果你用上述的選項來運行下這個例子(github源碼

你會在標准輸出中看到如下信息:

Application time: 0.3440086 secondsTotal time for which application threads were stopped: 0.0620105 secondsApplication time: 0.2100691 secondsTotal 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 secondsTotal 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文件中。如何解讀這些日志並做出響應是一個很大的課題,這已經遠超本文所討論的範圍了,不過未來我仍會更新一到兩篇文章來講下這個,請拭目以待.

英文原文鏈接

本文同時發錶在我的個人博客:Java譯站

原創文章,轉載請注明: 轉載自並發編程網 – ifeve.com本文鏈接地址: 通過JVM日志來進行安全點分析

FavoriteLoading添加本文到我的收藏
版权声明:本文为[杜老師說]所创,转载请带上原文链接,感谢。 https://gsmany.com/2022/01/202201070827101429.html