JVM菜鳥進階高手之路六(JVM每隔一小時執行一次Full GC)


轉載請注明原創出處,謝謝!

上次分析詳細地址在:http://www.cnblogs.com/lirenzuo/p/7531700.html
以為上次問題是rmi的問題就此結束了,但是問題並沒有結束,其實本次問題不是rmi問題導致的,但是rmi也的確可能會有sys.gc fullgc問題。
查看GC統計匯總情況:

jstat -gcutil pid  3s 30 

參考gc,發現大概一小時運行一次FGC,特別奇怪,笨神一看這樣的問題就知道是system gc導致的System.gc()的默認效果是引發一次stop-the-world的full GC,對整個GC堆做收集。用-XX:+DisableExplicitGC參數后,System.gc()的調用就會變成一個空調用,完全不會觸發任何GC。

問題來了 如果直接使用-XX:+DisableExplicitGC就沒有下面的任何事情了,在測試過程中的確使用了該參數,的確不會有full gc了。但是有寫堆外空間的釋放是需要涉及到System.gc的,如果禁用可能見到direct memory的OOM類似的異常,由於各種原因我們的環境沒有禁用。由於沒有禁用,添加參數-XX:+ExplicitGCInvokesConcurrent 該方法可以指定System.gc()采用 CMS 算法,FGC時停機時間會變短,但是CMS GC次數不會變。通過該參數 經過觀察日志效果比Full GC要好些。

看到這里一切都挺完美,后面開始要到高潮了,糾結…………看上篇文章里面有說一直以為是rmi問題,就查找資料想讓時間延遲下執行,

-Dsun.rmi.dgc.client.gcInterval=36000000 
-Dsun.rmi.dgc.server.gcInterval=36000000

單位是毫秒,可適當延長觸發FGC的定時時間間隔。 文中配置為10小時。通過jstack查看JVM線程

   GC Daemon" daemon prio=10 tid=0x00007f91bcccf800 nid=0x37f0 in Object.wait() [0x00007f9182706000]  
   java.lang.Thread.State: TIMED_WAITING (on object monitor)  
    at java.lang.Object.wait(Native Method)  
    - waiting on <0x0000000600021a48> (a sun.misc.GC$LatencyLock)  
    at sun.misc.GC$Daemon.run(GC.java:117)  
    - locked <0x0000000600021a48> (a sun.misc.GC$LatencyLock)  
  
   Locked ownable synchronizers:  
    - None  

笨神告訴我們,如果該線程一旦創建了就會間隔的調用gc了,所以就會存在定時繼續full gc問題。一直通過觀察居然沒有效果,還是會一小時執行一個full gc。通過gc日志可以出出來:而且old區6g才占2.5G就background cms gc了修改為cms的時候,每次System.gc 一次full gc的時候cms gc還會加2的,觸發的是background cms gc如果不是后台就會一次,cms過程如下:里面有一些概念比較重要,並行和並發的定義。gc這個場景下 你可以這么記 並發表示gc線程可以和業務線程同時跑 並行表示gc線程跑的時候業務線程都全不能跑 。

在Java 9 中將 Java 8 默認的 GC 從 Parallel GC 改為 G1,cms不是和ps比速度的,cms是低延時垃圾回收器。

開始糾結了笨神告訴需要通過btrace跟蹤下就很容易定位到問題那里調用了System.gc,根據ak大神提供的地址,之后阿飛給了我關於btrace新的github地址:https://github.com/btraceio/btrace。 以及一些Sample參考:https://github.com/btraceio/btrace/tree/master/samples。 github官網很多參考樣例,基本上能覆蓋常用的需求編寫了查看gc代碼如下:

@OnMethod(clazz = "java.lang.System", method = "gc")    
    public static void onSystemGC() {    
        println("entered System.gc()");    
        jstack();    
} 

在本地調用模擬結果如下:放到環境進行觀察,也獲取到了結果如下:打印到這里 知道是sun.misc.GC調用的,在這里走了很多彎路了,后來我把rmi去掉了,但是還是一小時一次通過日志觀察,后來搜索發現tomcat文章,的確有,開始也沒有注意,以為是這個原因,修改了重試還是不行,后是一波折過程,后來查看jar文件,的確不是一小時了,

后來又看見以為這個包問題,又是一波修改,發現還是一小時執行一次通過日志觀察,此時我已經無語了,不過還好在我的堅持下,還是把問題找到了,由於我把項目去掉跑不會有,那么感覺和項目有關,但是代碼里面的確沒有調用,我懷疑是否是其他jar里面的問題呢?我把所有的jar都查了一遍,的確發現問題了。查看該jar由於包的確有點老了,里面的確是這樣,和上面的tomcat那個bug很像,我下載了一個新版本查看,發現的確優化了。新版本里面變成了10個小時一次了,而且可以通過jvm參數讓其進行關閉,
-Dorg.apache.cxf.JDKBugHacks.gcRequestLatency=true即可。這次的這個一小時問題排除就結束了,還需要修改代碼,后續繼續觀察,在此過程中,ak大神和阿飛都告訴我關於ygc時間問題,的確這個還一直在實驗,希望優化的更好,內容很多一直也在學習,定位問題就是需要大膽的猜之后試之后優化修改記錄。后續會分享關於ygc時間長問題,推薦一款在線分析gc的好工具析,http://gceasy.io。 非常棒,在此再次感謝笨神,阿飛哥,ak大神的指導。


個人公眾號

匠心零度公眾號.jpg


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM