每天億級數(shù)據(jù)量的日志清洗系統(tǒng)，從Kafka不停消費(fèi)各種日志數(shù)據(jù)，然后對日志格式進(jìn)行各種清洗，如對敏感信息字段（姓名、手機(jī)號、身份證號）進(jìn)行脫敏，再把清洗后數(shù)據(jù)給其它系統(tǒng)，如推薦系統(tǒng)、廣告系統(tǒng)、分析系統(tǒng)都會去使用這些清洗好的數(shù)據(jù)。

OOM 現(xiàn)場

某天我們也是突然收到線上的報(bào)警，發(fā)現(xiàn)日志清洗系統(tǒng)發(fā)生OOM。第一時間登錄到線上機(jī)器，查看日志，經(jīng)典日志

 JAVA.lang.OutOfMemoryError: java heap space

堆內(nèi)存溢出。套路應(yīng)該很熟了。

先看異常日志，定位啥導(dǎo)致的問題，日志里看到了：

 java.lang.OutOfMemoryError: java heap space xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx()

似乎同樣的一個方法（XXClass.process()）反復(fù)出現(xiàn)，最終導(dǎo)致堆內(nèi)存溢出。

再仔細(xì)分析日志，代碼出現(xiàn)大量遞歸操作，正是這大量遞歸，導(dǎo)致堆內(nèi)存溢出。接著自然就是MAT分析內(nèi)存快照。

初步分析內(nèi)存快照

雖然日志能看到哪個方法導(dǎo)致內(nèi)存溢出，但不知道到底哪個方法調(diào)用創(chuàng)建的大量對象。因此還得用MAT分析。

因大量XXClass.process()遞歸執(zhí)行，每個XXClass.process()中都創(chuàng)建了大量char數(shù)組，最后因XXClass.process()又多次遞歸調(diào)用，也就導(dǎo)致大量的char[]數(shù)組耗盡內(nèi)存：

JVM參數(shù)問題？

基本定位出問題了，但先別急直接去代碼檢查問題，因?yàn)榘l(fā)現(xiàn)了比較大問題。

雖然XXClass.process()遞歸調(diào)用多次，但實(shí)際上我們在MAT中發(fā)現(xiàn)遞歸調(diào)用的次數(shù)也不多，最多幾十次。所有遞歸調(diào)用加起來創(chuàng)建的char[]數(shù)組對象總和其實(shí)也最多1G。

可能這次OOM發(fā)生不一定是代碼寫的爛，可能就是JVM 內(nèi)存參數(shù)不對，給堆內(nèi)存分配太少。

分析GC日志

要知道堆內(nèi)存是不是設(shè)小了，就得分析JVM運(yùn)行時的內(nèi)存使用模型。

現(xiàn)在宕機(jī)了，唯一能看到的，就是當(dāng)時在JVM啟動參數(shù)中加入的自動記錄的GC日志。

從GC日志中，可見JVM啟動時的完整參數(shù)設(shè)置：

 -Xmx1024m
 -Xms1024m
 -XX:+PrintGCDetails
 -XX:+PrintGC()
 -XX:+HeapDumpOnOutOfMemoryError
 -Xloggc:/opt/logs/gc.log 
 -XX:HeapDumpPath=/opt/logs/dump

這里主要是把gc日志詳細(xì)記錄在了一個日志文件，另外指定OOM時要導(dǎo)出內(nèi)存快照，堆內(nèi)存1G，但這臺機(jī)器可是4核8G！

記錄下來的gc.log日志：

 [Full GC (Allocation Failure) 866M->654M(1024M)]
 [Full GC (Allocation Failure) 843M->633M(1024M)] 
 [Full GC (Allocation Failure) 855M->621M(1024M)] 
 [Full GC (Allocation Failure) 878M->612M(1024M)]

因Allocation Failure觸發(fā)的Full GC很多，即堆內(nèi)存無法創(chuàng)建新對象，然后觸發(fā)GC，結(jié)果觸發(fā)時肯定先觸發(fā)Full GC了。發(fā)現(xiàn)每次Full GC都只回收一點(diǎn)點(diǎn)對象，堆內(nèi)存幾乎都占滿的。

日志顯示的是每s都會執(zhí)行一次Full GC，這就絕了。應(yīng)該是在系統(tǒng)運(yùn)行時，因?yàn)閄XClass.process()不停遞歸創(chuàng)建大量char[]數(shù)組，導(dǎo)致堆內(nèi)存幾乎滿。

然后導(dǎo)致連續(xù)一段時間，每s觸發(fā)一次Full GC，因?yàn)閮?nèi)存都滿了，特別是Old可能幾乎都滿了，所以可能每s執(zhí)行YGC前，發(fā)現(xiàn)Old可用空間不足，就會提前觸發(fā)Full GC。

也可能YGC后，存活對象太多無法放入Survivor，而都要進(jìn)入Old，也放不下了，只能Full GC。但每次full gc只能回收少量對象，直到最后可能某次full gc回收不掉任何對象了，然后新的對象無法放入堆內(nèi)存了，就觸發(fā)OOM了：

明顯就是堆內(nèi)存偏小了，導(dǎo)致頻繁full gc。

分析一下JVM運(yùn)行時內(nèi)存使用模型

接著jstat分析當(dāng)時JVM運(yùn)行時的內(nèi)存模型，當(dāng)時重啟系統(tǒng)，每s打印一次：

 S0 S1 E O YGC FGC
 
 0 100 57 69 36 0
 
 0 100 57 69 36 0
 
 0 100 65 69 37 0
 
 0 100 0 99 37 0
 
 0 100 0 87 37 1

我就給出部分信息大家就可以看出來問題所在了，剛開始都是Eden在漲，接著YGC從36到37，發(fā)生了一次YGC，Old直接從69%到99%。

why？

YGC后存活對象太多，Survivor放不下，直接進(jìn)了Old！接著Old都占99%了，直接觸發(fā)一次Full GC，但也僅讓Old從99%到87%，只回收少量對象。

該過程反復(fù)循環(huán)了幾次，年輕代對象反復(fù)進(jìn)入老年代，不停觸發(fā)Full GC，但是還回收不了多少對象，幾次循環(huán)過后，老年代滿了，可能Full GC沒回收多少對象，新的對象一大批放不下了，就觸發(fā)OOM了。

優(yōu)化第一步：加大堆內(nèi)存

所以這OOM，不能一口說是代碼問題，從JVM運(yùn)行情況及內(nèi)存大小來看，其實(shí)是內(nèi)存分配不足問題。

第一步，直接在4核8G的機(jī)器上，加大堆內(nèi)存，直接給堆5G。

接著運(yùn)行系統(tǒng)，jstat發(fā)現(xiàn)，每次YGC過后存活對象都落入Survivor區(qū)域了，不會隨便進(jìn)入老年代，而且因?yàn)槎褍?nèi)存很大，基本上運(yùn)行一段時間不會發(fā)生OOM問題了。

優(yōu)化第二步：改寫代碼

讓他不要占用過多內(nèi)存。代碼之所以遞歸，是因?yàn)樵谝粭l日志中，可能出現(xiàn)很多用戶的信息，一條日志也許會合并包含了十幾個到幾十個用戶的信息。

這時代碼中就是會遞歸處理日志，每次遞歸都會產(chǎn)生大量char[]數(shù)組，是切割了日志用來處理的。

這代碼寫的完全沒必要，因?yàn)閷γ恳粭l日志，若發(fā)現(xiàn)包含多個用戶的信息，就對這一條日志切割出來進(jìn)行處理，沒必要遞歸調(diào)用，每次調(diào)用都切割一次日志，生成大量char[]數(shù)組。

該步代碼優(yōu)化后，線上系統(tǒng)的內(nèi)存使用情況降低10倍以上。

總結(jié)

先通過OOM的排查方法去分析，發(fā)現(xiàn)主要是內(nèi)存太小導(dǎo)致的問題然后用gc日志和jstat分析，明顯發(fā)現(xiàn)是內(nèi)存不夠用了，最后加大系統(tǒng)內(nèi)存，并優(yōu)化代碼即可。