本文目的:利用線上故障的GC日志,來了解G1的GC過程。
最近在hbase集群一台機器的RegionServer突然掛掉了,經觀察日志發現是Young GC時發生了to-space。
這里首先簡單介紹一下G1和to-space。
G1是JAVA最新的一款垃圾回收器,它主要看重的是GC的停頓時間,用戶可以設置一個允許的停頓時間,G1力圖保證每次GC都在這個時間范圍內。
to-space:了解CMS的應該都清楚young GC的過程。簡單的來說,JAVA將內存分為新生代和老生代,young GC只發生在新生代中。
Young GC:新生代的內存可以分為2部分:eden區,survivor區。新object在eden中創建,然后young GC發生時,G1將eden中存活的對象拷貝到survivor中,如果此時存活的對象較多,survivor裝不下時,此時會發生to-space錯誤。
G1垃圾回收的簡單介紹:
之前查了一些資料,都是按照官網的介紹抄下來的,看了之后還是一知半解,這里我以自己當時困惑為出發點來說一下G1的簡單過程:
G1的主要有3中行為:young GC, Mixed GC, 和循環標記(marking cycle)。
G1將內存分為多個region,可以理解就是將內存分為很多塊,目標是盡量將region個數維護在2048個左右,每個region的大小建議在1-32M之間,這個一般是系統自己調整。
這些region有些屬於新生代,有些屬於老生代。可以看一下一個大致的圖解:
首先說一下young GC,young GC會stop the world,也就意味着這個階段,所有的java進程都會掛起。G1的新生代大小是會不斷擴張的,需要新的內存時,就會分配,然后在young GC的時候進行回收,回收時一般會將age比較大的object放入老生代中。
young GC只回收新生代的內存,這時候有人可能會問了,那老生代的啥時候回收呢?這個時候就要說一下循環標記(init-marking)和mixed GC了,一般在內存使用到一定程度之后(InitiatingHeapOccupancyPercent=45默認為45%),此時G1會啟動循環標記.
由於循環標記(init-marking)有很多步驟,很多博客都有介紹,這里就不詳細寫了,大致說一下它的主要作用:就是標記出完全沒有被占用的region和老生代中可以被回收的region。因為內存占用到達了閾值,所以要對老生代進行回收,此時就要挑出來最應該被回收的region。
然后輪到mixed GC了,mixed GC可以看作是young GC的加強版,它不僅按照young GC的方式回收新生代,同時也將循環標記過程中,標記的老生代中的一部分region一並回收(注意這里是一部分,為什么是一部分?應該是G1為了保證響應時間,所以每次只回收一定量的region,而且官網也寫了mixed GC可能會連續執行多次,在多次執行之后,老保證標記的region完全被回收),這樣執行多次mixed GC,來清除無用的object。
下面我們來觀察一個正常的GC日志來了解一下G1,如圖:
這是youngGC的:
可以看到括號里面有(young),代表這是young gc,Eden:3072M->0.0B,survivors:192M--》384M,Heap:22.6G(64.0G)->19.7G(64.0G):代表新生代中的eden區回收到了survivor區中,存活的對象有384M。總共使用的內存由22G變成了19.7G。可以理解為此次回收了2G多的內存。
圖中的heap before gc和heap after gc可以看出回收前有102個young region,回收后有12個young region。可以看到region size32768K(32M),大約算一下,正好可以得出有2G多的差距,正好和上面的heap變化對應上。
下面是marking的日志:
圖中可以看到heap在28G左右的時候發生了marking(marking都是順帶的在youngGC中進行的),跟默認的配比45%也正好對應。日志比正常的youngGC多了一些,多的那些就是官網寫的marking的幾個步驟,具體干了什么可以參看官網。
之后就開始要進行mixed GC了(不過我這邊的服務器觀察的是init marking之后,往往還會有個young GC,然后在執行mixed GC,具體為啥沒搞清楚):
mixed GC:
mixedGC的日志和young GC的日志挺像的,也沒啥說的,就是回收的時候順帶把老生代中的一些region也回收了。
線上問題:
線上的hbase的regionserver突然掛掉了,觀察日志發現是GC時間過長,我們保留了當時的GC日志,下面是故障時間點的截圖:
圖中可以看出,24號18點到25號18點之間,整整一天,這個regionserver是沒有進行任何GC的,然后過了一整天,直接執行了young GC,但是圖中可以看到一些問題:
heap before的young大小是大約4G,但是eden卻顯示回收了36.4G內存,一般情況下這兩個數值應該是匹配的,這里差距很大。
heap:54.2G回收之后還是54.2G,eden雖然空了,但是內存占用卻沒有變,個人猜測:有可能是eden中的對象並沒有回收,而是全部挪入了老生代,導致時間開銷很大,達到了43s。
疑問:而且還有一點非常奇怪的是,回收前和回收后的young region個數是一模一樣的,再加上之前說的eden和young大小不匹配,這里的顯示也是有問題的。
這個young GC之后,后面便開始了init-marking過程。但是此時已經暫停了太長的時間,導致hbase和hadoop的守護進程都認為機器已死,已經停止了服務。
分析上面的問題,得出以下猜測:
可能的原因:長時間沒有GC,而且eden中的數據並沒有回收,而是挪入了老生代,導致了長時間的暫停。
觀察其他業務的日志,正常情況下早就應該進行young GC的,這個集群由於目前沒有上線,訪問量很小,經常流量為0。有可能是因為這個因為導致沒有觸發young GC,
而且看了一些的文檔,寫了java版本1.7.60以上對G1的支持比較好,目前我們的版本是1.7.45。
故:升級java版本,以更兼容G1,而且項目正式上線,流量上來之后會經常觸發GC,保證及時進行回收。日后再進行觀察。
本文希望以一個實際的例子來看懂G1的日志,已方便日后的故障排查。需要一些知識儲備,比如CMS垃圾回收機制,這個網上資料講的很詳細。