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

背景說明

    發生問題的系統部署在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

    可以看到持久代被設定為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引數如下：

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

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

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