線上某應用的FULLGC分析
這2天，排除線上某應用啟動記憶體變化頻繁的問題時，額外發現了一個fullgc的問題，分享給大家。
過程如下：抽了臺線上機器，想看下這段時間機器的gc情況，發現裡面有好幾個FullGc的日誌：
T23:23:02.009+0800: 21860.015: [Full GC 21860.015: [CMS: 2361237K->1111804K(4718592K), 4.9917540 secs] 2532961K->1111804K(5190464K), [CMS Perm : 17397K->17240K(131072K)], 4.9918770 secs] [Times: user=4.96
|
JVM引數設定如下：
-XX:+UseCMSInitiatingOccupancyOnly
-XX:CMSInitiatingOccupancyFraction=60
|
引數的意思是：在舊區到60％的時候，會觸發一次cmsgc，應該出現如下日誌：
T20:10:37.803+0800: 3246087.559: [CMS-concurrent-mark-start] T20:10:38.463+0800: 3246088.220: [CMS-concurrent-mark: 0.661/0.661 secs] [Times: user=3.17 sys=0.56, real |
而現在日誌裡面都是old區到2.3G（50%）的時候，就會觸發一次FullGc，而且gc日誌裡面沒有一次正常的cmsgc，現在是什麼原因在半路截胡了？
開始懷疑JVM引數是否設定生效，通過jinfo進行檢視：
jinfo -flag UseCMSInitiatingOccupancyOnly 20195 jinfo -flag CMSInitiatingOccupancyFraction 20195 |
一切正常。
出現Fullgc，當時我想可能的原因有以下幾個情況：
- cmsgc失敗導致（GC日誌中沒有相關cmsgc失敗的日誌）
- JMAP -histo：現場（人為執行肯定不是）
- 大物件分配時，空間不夠導致（當時還剩下50%記憶體，並且如果大物件分配，gc日誌裡面是會有如下WARN的）
- 記憶體碎片導致？（由於系統會經常分配一些大陣列，這個會加劇碎片化）
第四點是最可能的原因了。於是，接下來怎麼驗證是否是它導致的呢？加上PrintGCReason，先打印出fullgc的原因,
命令如下：
/java/bin/jinfo -flag +PrintGCReason
|
第二天，檢視日誌，如下：
GC Cause: Heap Inspection Initiated GC T16:16:01.880+0800: 687439.886: [Full GC 687439.886: [CMS: 2362138K->1180717K(4718592K), 5.6573690 secs] 2700275K->1180717K(5190464K), [C MS Perm : 17531K->17488K(131072K)], 5.6574950 secs] [Times: user=5.59 sys=0.06, real=5.65 secs]
|
GC原因：堆檢查啟動GC，FullGc的原因是這個，看不明白，諮詢過後，說這個很可能是因為JAMP -hist繼：活導致的FullGc。
那如果是這樣，就有可能是有指令碼或者定時任務，也可能是什麼其他東西，去執行了這個命令，反正據我瞭解的cs沒有做這事。接下來就是找這個“凶手”了，這事情沒做過，沒啥頭緒，看程序也看不出什麼，想grep所有指令碼，懶癌又發作了，還是先去群裡諮詢下有啥簡單又省力的辦法吧，一下搞定：
[ ~]$ crontab -l */1 * * * * /home/bin/config-monitor.sh >> /home/logs/config-monitor.log 2>&1 [logs]$ cat /home/bin/config-monitor.sh |grep "jmap" jmaplog="/home/jmap.log"; if (count == 3) { / run jmap print "run jmap command : /java/bin/jmap -histo:live "pid" |head -n 20"; system("/java/bin/jmap -histo:live "pid" |head -n 20")>jmaplog; print "#######Server has recovered after running jmap######";
|
有個定時任務跑一個叫config-monitor.sh的指令碼，裡面做的事情，基本就是監視記憶體各個區的比例，超過一定比例，就通過jamp -histo：現場觸發下fullgc，防止溢位===》這個定時任務是cs以前遺留下來的，一直沒發現，後續就是評估是否去掉這個定時任務，整個過程告一段落。
總結：
1，問題可能出現的原因，要儘快動手去驗證，不要只停留在思考的層面;
2，出現fullgc的時候，可以通過加上PrintGCReason，檢視具體GC原因。