[轉]線上GC故障解決過程記錄

標籤：

 排查了三四個小時，終於解決了這個GC問題，記錄解決過程於此，希望對大家有所協助。本文假定讀者已具備基本的GC常識和JVM調優知識，關於JVM調優工具使用可以查看我在同一分類下的另一篇文章：

    http://my.oschina.net/feichexia/blog/196575

 

背景說明

    發生問題的系統部署在Unix上，發生問題前已經跑了兩周多了。

    其中我用到了Hadoop源碼中的CountingBloomFilter，並將其修改成了安全執行緒的實現（詳情見：AdjustedCountingBloomFilter），主要利用了AtomicLong的CAS樂觀鎖，將long[]替換成了AtomicLong[]。這樣導致系統中有5個巨大的AtomicLong數組（每個數組大概佔50MB），每個數組包含大量AtomicLong對象（所有AtomicLong對象佔據大概1.2G記憶體）。而且這些AtomicLong數組的存活時間都至少為一天。

    服務端已先於手機用戶端上線，用戶端本來計劃本周四上線（寫這篇文章時是周一），所以我還打算在接下來的幾天繼續觀察下系統的健全狀態，開啟的仍然是Debug層級日誌。

    部分JVM參數摘抄如下（JVM參數配置在項目部署的tomcat伺服器的根目錄下的bin目錄下的setenv.sh中，可以通過ps -ef | grep xxx | grep -v grep查看到）：

?

1

-XX:PermSize=256M -XX:MaxPermSize=256M -Xms6000M -Xmx6000M -Xmn1500M -Xss256k -XX:ParallelGCThreads=8 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+DisableExplicitGC -XX:+CMSParallelRemarkEnabled -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:CMSFullGCsBeforeCompaction=5 -XX:+UseCMSCompactAtFullCollection -XX:+CMSScavengeBeforeRemark -XX:+HeapDumpOnOutOfMemoryError -Xloggc:/usr/local/webserver/point/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

 

    可以看到持久代被設定為256M，堆記憶體被設定為6000M（-Xms和--Xmx設為相等避免了“堆震蕩”，能在一定程度減少GC次數，但會增加平均每次GC消耗的時間），年輕代被設定為1500M。

    -XX:+UseConcMarkSweepGC設定老年代使用CMS（Concurrent Mark-Sweep）收集器。 -XX:+UseParNewGC設定新生代使用並行收集器，-XX:ParallelGCThreads參數指定並行收集器背景工作執行緒數，在CPU核心數小於等於8時一般推薦與CPU數目一致，但當CPU核心數大於8時推薦設定為：3 + [(5*CPU_COUNT) / 8]。其他參數略去不提。

 

問題發現與解決過程

    早上測試找到我說線上系統突然掛了，報訪問逾時異常。

    首先我第一反應是系統記憶體溢出或者進程被作業系統殺死了。用ps -ef | grep xxx | grep -v grep命令查看進程還在。然後看tomcat的catlalina.out日誌和系統gc日誌，也未發現有記憶體溢出。

    接下來用jstat -gcutil pid 1000看了下堆中各代的佔用情況和GC情況，發現了一個挺恐怖的現象：Eden區佔用77%多，S0佔用100%，Old和Perm區都有很大空間剩餘。

    懷疑是新生代空間不足，但沒有確鑿證據，只好用jstack擷取線程Dump資訊，不看不知道，一看就發現了一個問題（沒有發現線程死結，這裡應該是“活鎖”問題）：

    從上面第一段可看到有一個Low Memory Detector系統內部線程（JVM啟動的監測和報告低記憶體的守護線程）一直佔著鎖0x00....00，而下面的C2 CompilerThread1、C2 CompilerThread0、Signal Dispatcher和Surrogate Locker線程都在等待這個鎖，導致整個JVM進程都hang住了。

    在網上搜尋一圈，發現大部分都建議調大堆記憶體，於是根據建議打算調大整個堆記憶體大小、調大新生代大小（-Xmn參數）、調大新生代中Survivor區占的比例（-XX:SurvivorRatio參數）。並且由於存在AtomicLong數組大對象，所以設定-XX:PretenureThreshold=10000000，即如果某個對象超過10M（單位為位元組，所以換算後為10M）則直接進入老年代，注意這個參數只在Serial收集器和ParNew收集器中有效。另外希望大量的長生命週期AtomicLong小對象能夠儘快進入老年代，避免老年代的AtomicLong數組對象大量引用新生代的AtomicLong對象，我調小了-XX:MaxTenuringThreshold（這個參數的預設值為15），即現在年輕代中的對象至多能在年輕代中存活8代，如果超過8代還活著，即使那時年輕代記憶體足夠也會被Promote到老年代。有修改或增加的JVM GC參數如下：

?

1	-Xms9000M -Xmx9000M -Xmn1500M -XX:SurvivorRatio=6 -XX:MaxTenuringThreshold=8 -XX:PretenureSizeThreshold=10000000

 

    重啟系統後用jstat -gcutil pid 1000命令發現一個更恐怖的現象，如：Eden區記憶體持續快速增長，Survivor佔用依然很高，大概每兩分鐘就Young GC一次，並且每次Young GC後年老代記憶體佔用都會增加不少，這樣導致可以預測每三四個小時就會發生一次Full GC，這是很不合理的。

    第二列是S1，佔用高達87.45%，第三列是Eden區記憶體佔用變化情況，可以看到增長非常快。

    於是我用jmap -histo:live（注意jmap命令會觸發Full GC，並發訪問量較大的線上環境慎用）查看了下活對象，發現有一些Integer數組和一些Character數組佔用記憶體在持續增長，並且佔了大概好幾百M的記憶體，然後經過Young GC又下降，然後再次快速增長，再Young GC下降，周而復始。 

    至此，我推測可能是大量的Integer數組對象和Character數組對象基本佔滿了Survivor，導致在Eden滿了之後，新產生的Integer數組對象和Character數組對象不足以放入Survivor，然後對象被直接被Promote到了年老代，這種推測部分正確，它解釋了S1佔用那麼高的原因，但不能解釋上面的Eden區記憶體佔用持續上升。

    於是繼續查看了下介面調用日誌，不看不知道，一看嚇一跳：日誌重新整理非常之快（99%是DEBUG日誌）。原來運營和測試在未通知我們服務端的情況下已經於昨天在某個渠道發布了一個Android線上版本（難怪今天就暴露問題了），再看了下使用該系統的使用者已經有6400多個了，徹徹底底被他們坑了一把。這就能解釋為什麼上面有一個Integer數組和Character數組佔用記憶體持續增長了，原因就在於大量的系統介面調用觸發了大量DEBUG日誌重新整理，寫日誌對於線上系統是一個重量級操作，無論是對CPU佔用還是對記憶體佔用，所以高並發線上系統一定要記得調高記錄層級為INFO甚至ERROR。

    於是修改log4j.properties中的記錄層級為INFO，然後用jmap -histo:live pid命令查看活對象，發現Integer數組對象和Character[]數組對象明顯下降，並且佔用記憶體也由前面的幾百M降到幾M。

    之後再用jstat -gcutil pid 1000查看了下GC情況，如下：

    很明顯Survivor佔用沒這麼高了，最重要的Young GC後年老代記憶體佔用不會增加了，此處Eden區增長貌似還是挺快，因為此時使用者數比前面多了很多。至此出現的問題基本搞定，但還有待後續觀察。

 

總結

    總的來說本系統中存在一個違背GC假設的東西，那就是在JVM堆中存在著海量生命週期較長的小對象（AtomicLong對象）。這無疑會給系統埋坑。

    GC分代基本假設是：

?

1	JVM堆中存在的大部分對象都是短生命週期小對象。

 

    這也是為什麼Hotspot JVM的年輕代採用複製演算法的原因。

 

    其他推薦一些非常不錯的GC方面的參考文章（前兩篇都來自《深入理解Java虛擬機器》一書，參考連結大部分是我今天查閱的資料，大家選擇性看就好）：

    JVM記憶體管理：深入Java記憶體地區與OOM http://www.iteye.com/topic/802573

    JVM記憶體管理：深入垃圾收集器與記憶體配置策略 http://www.iteye.com/topic/802638

    Oracle GC Tuning http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html

    Java 6 JVM參數選項大全 http://kenwublog.com/docs/java6-jvm-options-chinese-edition.htm

    Java HotSpot VM Options http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html

    CMS GC實踐總結 http://www.iteye.com/topic/473874

    JVM記憶體的分配及回收 http://blog.csdn.net/eric_sunah/article/details/7893310

    一步一步最佳化JVM系列 http://blog.csdn.net/zhoutao198712/article/category/1194642

    Java線程Dump分析 http://www.linuxidc.com/Linux/2009-01/18171.htm http://jameswxx.iteye.com/blog/1041173

    利用Java Dump進行JVM故障診斷 http://www.ibm.com/developerworks/cn/websphere/library/techarticles/0903_suipf_javadump/

    Detecting Low Memory in Java https://techblug.wordpress.com/2011/07/16/detecting-low-memory-in-java/

    Detecting Low Memory in Java Part 2 http://techblug.wordpress.com/2011/07/21/detecting-low-memory-in-java-part-2/

    http://blog.sina.com.cn/s/blog_56d8ea9001014de3.html

    http://stackoverflow.com/questions/2101518/difference-between-xxuseparallelgc-and-xxuseparnewgc

    http://stackoverflow.com/questions/220388/java-concurrent-and-parallel-gc

    http://j2eedebug.blogspot.com/2008/12/what-to-look-for-in-java-thread-dumps.html

    https://devcenter.heroku.com/articles/java-memory-issues

    http://blog.csdn.net/sun7545526/article/category/1193563

    http://java.dzone.com/articles/how-tame-java-gc-pauses

2樓：優雅先生 發表於 2015-01-07 16:49 回複此評論引用來自“木木三”的評論我想問一個最後一張圖，第6列YGC=4，第8列FGC=9，FGC比YGC次數多，這種現象正常麼其實這個問題還沒有解決，後來又出現了，根本原因在於我改寫的一個CountingBloomFilter中用到了AtomicLong[]，海量的AtomicLong小對象瞬間產生，年輕代放不下直接Promote到老年代導致promotion failed，後來改成AtomicLongArray才解決問題。

[轉]線上GC故障解決過程記錄