記一次尷尬的Java應用記憶體洩露排查

qq_42606051發表於2018-09-22

這星期被線上JVM記憶體佔用不斷增大的問題所困擾,自己提出了一些假設,然後去實施驗證都一一失敗了,有一些經驗和教訓在這裡分享下.
之所以是尷尬,是最後因為修復了另一個看似不相關的問題導致記憶體不再上升,但這之間的關係還未明瞭,還需要繼續追蹤.
這裡講述一下這次排查的過程.

直接記憶體的錯誤判斷

伺服器的JVM配置為Xmx3g,使用G1,沒有設定Xms考慮自然收縮和fgc之後的空間回攏.
沒有發生過fgc,且堆記憶體的增長正常,排除掉堆記憶體的問題.
使用NMT檢視各個區域的記憶體正常,committed記憶體不足4G,但實際情況記憶體佔用不斷增大,甚至出現了OOM killer殺掉java程式.

Total: reserved=5037MB, committed=3926MB
-                 Java Heap (reserved=3072MB, committed=3072MB)
                            (mmap: reserved=3072MB, committed=3072MB)

-                     Class (reserved=1196MB, committed=192MB)
                            (classes #29793)
                            (malloc=6MB #86203)
                            (mmap: reserved=1190MB, committed=186MB)

-                    Thread (reserved=186MB, committed=186MB)
                            (thread #184)
                            (stack: reserved=184MB, committed=184MB)
                            (malloc=1MB #922)
                            (arena=1MB #366)

-                      Code (reserved=273MB, committed=171MB)
                            (malloc=29MB #39947)
                            (mmap: reserved=244MB, committed=142MB)

-                        GC (reserved=176MB, committed=176MB)
                            (malloc=30MB #114115)
                            (mmap: reserved=146MB, committed=146MB)

-                  Compiler (reserved=1MB, committed=1MB)

-                  Internal (reserved=88MB, committed=88MB)
                            (malloc=88MB #83467)

-                    Symbol (reserved=31MB, committed=31MB)
                            (malloc=27MB #312661)
                            (arena=4MB #1)

-    Native Memory Tracking (reserved=10MB, committed=10MB)
                            (tracking overhead=10MB)

-                   Unknown (reserved=6MB, committed=0MB)
                            (mmap: reserved=6MB, committed=0MB)

記憶體增長情況(中間下降是進行fgc或重啟服務)

最開始考慮是直接記憶體的問題,觀察GC行為發現沒有發生過一次fgc,想當然覺得應該是直接記憶體無法回收,並且在手動執行gc之後記憶體佔用的確是下降的.
於是調整了一波JVM引數,將堆大小設定為2500M,並配置MaxDirectMemory用來觸發fgc.
但最後發現記憶體依舊增長,且還是沒有fgc.
再觀察了下heap(jmap -heap)的情況,發現手工觸發fgc後,heap釋放的大小和記憶體下降幾乎一致.
在使用JMX檢視了direct pool(java.nio.BufferPool)後驚奇地發現..直接記憶體並沒有多少使用(我們底層用了netty,下意識認為出了問題):

圖中所示最大隻用了4M左右.

最後設定了Xms之後發現fgc已經沒有作用,記憶體的使用量不會再下降,排除掉了這個因素.
這個錯誤的判斷最主要的原因還是先入為主,沒有收集支撐的直接證據.

stack中的間隙

接下去只能使用pmap(pamp -X pid)看下具體的記憶體資訊.

發現了一些有趣的東西,大量的64M塊.
直覺告訴我,快找出問題了.
搜尋了下發現類似的問題:

解決方法也很直接換一個分配記憶體的庫.
可選的也只有tcmalloc和jemalloc.

選擇了前者,配置之後效果出眾.
已經沒有上圖中那麼多的64M塊了.
並且啟動後的記憶體使用是掉了下來,但是好景不長.

(藍線是使用了tcmalloc,紅線是對比方)
剛開始的確藍線記憶體使用好一點(紅線在20:00的時候重啟記憶體降低了).
但隨後還是增長了,比較迷的一點是在8點後記憶體陡降(但JVM沒有重啟,PID也沒有變化),恢復到了最初的水平.

看來問題不在這裡.

看似沒有關聯的問題

周常部署的時候出現一個問題,導致heap OOM,我跟了下發現了一段程式碼記憶體溢位,但看似和這個堆外記憶體引起的問題沒有關聯就沒怎麼在意.

第二天同事修復了這個問題,遷移走了這個介面到另一個服務.
tcmalloc的heap profiling無法使用,一開啟libunwind就segment fault退出,換成jemalloc後開啟.
還在想是不是常見的那個zip溢位的問題,但是搜尋了程式碼庫沒有發現忘記關閉的情況,等著看下增長和dump驗證下.
觀察了一會兒,突然發現記憶體不再增長了.

(藍線是之前一直留著的機器,中間降低是進行了重啟)
非常平穩地度過了一天.