這星期被線上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也沒有變化),恢復到了最初的水平.
看來問題不在這里.
看似沒有關聯的問題
周常部署的時候出現一個問題導致CPU飆升,跟了下發現一個處理圖片的接口被頻繁調用並且在處理較大尺寸的圖片,看似和這個堆外內存引起的問題沒有關聯就沒怎么在意.
第二天同事修復了這個問題,遷移走了這個接口到另一個服務.
tcmalloc的heap profiling無法使用,一開啟libunwind就segment fault退出,換成jemalloc后開啟.
還在想是不是常見的那個zip溢出的問題,但是搜索了代碼庫沒有發現忘記關閉的情況,等着看下增長和dump驗證下.
觀察了一會兒,突然發現內存不再增長了.
(藍線是之前一直留着的機器,中間降低是進行了重啟)
非常平穩地度過了一天.
那坨profiling也失去了意義... ...
這就感覺非常尷尬了...
繼續追蹤
更尷尬的是另一個服務炸了... ...
繼續跟進,先把jemalloc配置過去,等下一次增長看下dump.
update 2018/09/25
繼續觀察了一段時間... 發現在內存在突然增大的時候這個部分增加比較多
java2d相關,代碼里確實有圖片處理.
但放着不管(之前都重啟了或者被OOM killer干掉了..)接下去會被回收掉...
update 2018/09/27
之后做了一個實驗,讀取圖片(jpeg),的確是會申請很多native內存.
在爆棧提了個問題:
https://stackoverflow.com/questions/52519253/why-the-code-using-image-io-mallocs-so-much-memory
多線程同時讀取內存會升高明顯.
大體確定是業務原因,讀取處理圖片是同步進行,會導致堆外內存占用升高.
fix應該是用任務隊列的方式去修改業務實現.
再看看之后會不會有問題.
隨着時間的推移遇見了各種各樣的問題.
這次排查除了對之前積累的知識的運用,更多像是一次對搜索引擎熟練度的提升 😦 .
但過程還是很不錯的,也看到了一些自己以前沒有接觸過的知識.
深深感受到自己知識的匱乏,就像深淵(??)一樣,逐漸深入才會發現不一樣的風景.
生活中還是要多(xie)些bug才會更精彩的啊... ...
參考資料:
http://lovestblog.cn/blog/2015/05/12/direct-buffer/
https://yq.aliyun.com/articles/227924
https://github.com/jeffgriffith/native-jvm-leaks
glibc issue原問題:
https://serverfault.com/questions/341579/what-consumes-memory-in-java-process?newreg=394e0ea40e55493d8149010909011719
關於NMT的internal 包含了直接內存 不包含DirectMemory:
https://stackoverflow.com/questions/47309859/what-is-contained-in-code-internal-sections-of-jcmd