記錄一次線上OOM情況排查過程

酥糖發表於2018-05-17

現象

某天凌晨，手機突然告警，線上某臺機子記憶體使用率超過90%，當時以為是有定時任務在跑，再加上夜已深了，沒有去排查具體原因。第二天早上有釋出，記憶體降下來了，白天就沒有去調查這個問題。等到傍晚高峰期的時候，又接到記憶體呼叫超過90%的告警，並且持續一段時間後，線上的某臺機子掛了。

現場儲存

當時一臺機子掛掉後，馬上重啟了掛掉的機子，並且把另一臺機子的記憶體資訊dump下來。

jmap -dump:format=b,file=檔名 [pid]

在dump過程中遇到小插曲，無法dump下來。

這種情況是因為非當前執行緒使用者導致，在命令前面加上sudo -u 使用者即可

同時儲存了執行緒資訊

sudo -u jetty jstack pid > /tmp/jstack2018-04-18.txt

問題定位

檢視伺服器系統日誌

cat /var/log/messages

上圖看到 Killed process 7364, UID 502, (java) total-vm:10511252kB, anon-rss:7489308kB java記憶體使用了7G多。ps：上一行的java程式的2627813 和 1872416都是頁數，每頁4K。

可以發現容器記憶體使用因為超過系統記憶體被kill掉了。

使用mat分析具體記憶體洩漏問題。

由於本人對mat工具使用的還不熟練，看到分佈圖後，total一共才103.6MB，以為堆內記憶體沒有問題，便往堆外記憶體溢位方向去考慮。陸陸續續的檢查了程式碼中的ThreadLocal的使用，物件也有及時清理，檢查了線上執行緒的數量，都沒有發現明顯問題。

轉載一篇執行緒過多導致的堆外記憶體溢位文章：執行緒數過多導致堆外記憶體溢位

繼續使用mat分析，使用Leak Suspects功能，發現記憶體中有大量的TrueTypeFont物件

正好想到在該應用中，有使用到字型畫圖，傳送圖片的功能。於是乎查詢一下OOM當時請求情況，發現確實有大量的畫圖的請求，並且發現某個請求中同時畫600多張畫。

問題重現

接著，在公司的測試環境下模擬了下請求，果然記憶體使用率由60多一下子升到了80多。

回頭檢查了一下畫圖的程式碼，發現在處理字型的地方確實有問題。

該方法的邏輯為載入伺服器上的某個字型檔案，使用畫筆畫一張二維碼，然後儲存到伺服器的臨時目錄下。

這裡在載入字型的時候沒做好處理，導致每次過來一個畫的任務就會載入一次字型檔案，記憶體中建立一個字型物件，而我們伺服器上的字型檔案大小約有16M，也就相當於每次畫一幅畫就需要載入16M的記憶體大小。

分析原因

由於當時對mat不熟悉，還在懷疑是不是Font操作了堆外空間導致的。於是乎準備測試一下堆外空間。

排除堆外空間溢位可能性

我們伺服器的配置為8G記憶體，jvm配置為 -Xmx4428m -Xms4428m -Xmn2767m，堆外空間如果不限制的話，會和jvm使用差不多。這時候，我們限定堆外空間大小，比如我們指定堆外空間比如說只有100M -XX:MaxDirectMemorySize=100m 。

如果說Font使用的是堆外空間，那麼堆外空間就會很快到達100M，並且進行Full GC，阻塞所有請求，Stop The World。這時候，只要Full GC清理及時，後面阻塞請求繼續進來，繼續滿100M，繼續Full GC。這樣，記憶體使用率永遠也不會到8G，就不會出現被系統kill掉的情況了。

但是在測試過程中，發現記憶體使用率還是在一路飆升，最終還是被kill了。所以後來只能再次懷疑是堆內記憶體溢位。用同樣的策略，將堆內記憶體設定為1G（100M應用起不來了），發現記憶體沒有繼續往上升，並且檢視了下gc日誌，一直在進行Fulll GC，從這大致可以看出使用的是堆內的記憶體。

由此可以看出，當時高峰期，大量畫圖請求進來，導致大量的大物件載入進記憶體，最終導致jvm記憶體超過了系統記憶體，容器被系統kill掉。