一次線上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查看到）：

-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-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 CompilerThread一、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參數以下：

-Xms9000M -Xmx9000M -Xmn1500M -XX:SurvivorRatio=6 -XX:MaxTenuringThreshold=8 -XX:PretenureSizeThreshold=10000000-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分代基本假設是：

JVM堆中存在的大部分對象都是短生命週期小對象。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

原文連接：https://my.oschina.net/feichexia/blog/277391