每天億級(jí)數(shù)據(jù)量的日志清洗系統(tǒng)，從Kafka不停消費(fèi)各種日志數(shù)據(jù)，然后對(duì)日志格式進(jìn)行各種清洗，如對(duì)敏感信息字段（姓名、手機(jī)號(hào)、身份證號(hào)）進(jìn)行脫敏，再把清洗后數(shù)據(jù)給其它系統(tǒng)，如推薦系統(tǒng)、廣告系統(tǒng)、分析系統(tǒng)都會(huì)去使用這些清洗好的數(shù)據(jù)。
OOM 現(xiàn)場
某天我們也是突然收到線上的報(bào)警，發(fā)現(xiàn)日志清洗系統(tǒng)發(fā)生OOM。第一時(shí)間登錄到線上機(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()
似乎同樣的一個(gè)方法（XXClass.process()）反復(fù)出現(xiàn)，最終導(dǎo)致堆內(nèi)存溢出。
再仔細(xì)分析日志，代碼出現(xiàn)大量遞歸操作，正是這大量遞歸，導(dǎo)致堆內(nèi)存溢出。接著自然就是MAT分析內(nèi)存快照。
初步分析內(nèi)存快照
雖然日志能看到哪個(gè)方法導(dǎo)致內(nèi)存溢出，但不知道到底哪個(gè)方法調(diào)用創(chuàng)建的大量對(duì)象。因此還得用MAT分析。
因大量XXClass.process()遞歸執(zhí)行，每個(gè)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ù)組對(duì)象總和其實(shí)也最多1G。
可能這次OOM發(fā)生不一定是代碼寫的爛，可能就是JVM 內(nèi)存參數(shù)不對(duì)，給堆內(nèi)存分配太少。
分析GC日志
要知道堆內(nèi)存是不是設(shè)小了，就得分析JVM運(yùn)行時(shí)的內(nèi)存使用模型。
現(xiàn)在宕機(jī)了，唯一能看到的，就是當(dāng)時(shí)在JVM啟動(dòng)參數(shù)中加入的自動(dòng)記錄的GC日志。
從GC日志中，可見JVM啟動(dòng)時(shí)的完整參數(shù)設(shè)置：
-Xmx1024m
-Xms1024m
-XX:+PrintGCDetails
-XX:+PrintGC()
-XX:+HeapDumpOnOutOfMemoryError
-Xloggc:/opt/logs/gc.log
-XX:HeapDumpPath=/opt/logs/dump
這里主要是把gc日志詳細(xì)記錄在了一個(gè)日志文件，另外指定OOM時(shí)要導(dǎo)出內(nèi)存快照，堆內(nèi)存1G，但這臺(tái)機(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)建新對(duì)象，然后觸發(fā)GC，結(jié)果觸發(fā)時(shí)肯定先觸發(fā)Full GC了。發(fā)現(xiàn)每次Full GC都只回收一點(diǎn)點(diǎn)對(duì)象，堆內(nèi)存幾乎都占滿的。
日志顯示的是每s都會(huì)執(zhí)行一次Full GC，這就絕了。應(yīng)該是在系統(tǒng)運(yùn)行時(shí)，因?yàn)閄XClass.process()不停遞歸創(chuàng)建大量char[]數(shù)組，導(dǎo)致堆內(nèi)存幾乎滿。
然后導(dǎo)致連續(xù)一段時(shí)間，每s觸發(fā)一次Full GC，因?yàn)閮?nèi)存都滿了，特別是Old可能幾乎都滿了，所以可能每s執(zhí)行YGC前，發(fā)現(xiàn)Old可用空間不足，就會(huì)提前觸發(fā)Full GC。
也可能YGC后，存活對(duì)象太多無法放入Survivor，而都要進(jìn)入Old，也放不下了，只能Full GC。但每次full gc只能回收少量對(duì)象，直到最后可能某次full gc回收不掉任何對(duì)象了，然后新的對(duì)象無法放入堆內(nèi)存了，就觸發(fā)OOM了：
明顯就是堆內(nèi)存偏小了，導(dǎo)致頻繁full gc。
分析一下JVM運(yùn)行時(shí)內(nèi)存使用模型
接著jstat分析當(dāng)時(shí)JVM運(yùn)行時(shí)的內(nèi)存模型，當(dāng)時(shí)重啟系統(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后存活對(duì)象太多，Survivor放不下，直接進(jìn)了Old！接著Old都占99%了，直接觸發(fā)一次Full GC，但也僅讓Old從99%到87%，只回收少量對(duì)象。
該過程反復(fù)循環(huán)了幾次，年輕代對(duì)象反復(fù)進(jìn)入老年代，不停觸發(fā)Full GC，但是還回收不了多少對(duì)象，幾次循環(huán)過后，老年代滿了，可能Full GC沒回收多少對(duì)象，新的對(duì)象一大批放不下了，就觸發(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過后存活對(duì)象都落入Survivor區(qū)域了，不會(huì)隨便進(jìn)入老年代，而且因?yàn)槎褍?nèi)存很大，基本上運(yùn)行一段時(shí)間不會(huì)發(fā)生OOM問題了。
優(yōu)化第二步：改寫代碼
讓他不要占用過多內(nèi)存。代碼之所以遞歸，是因?yàn)樵谝粭l日志中，可能出現(xiàn)很多用戶的信息，一條日志也許會(huì)合并包含了十幾個(gè)到幾十個(gè)用戶的信息。
這時(shí)代碼中就是會(huì)遞歸處理日志，每次遞歸都會(huì)產(chǎn)生大量char[]數(shù)組，是切割了日志用來處理的。
這代碼寫的完全沒必要，因?yàn)閷?duì)每一條日志，若發(fā)現(xiàn)包含多個(gè)用戶的信息，就對(duì)這一條日志切割出來進(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)化代碼即可。
