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

阿新 • • 發佈：2018-11-02

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大神的指導。