- 打開開發環境服務器(我的服務器應用是單獨部署的,幾乎沒有人訪問),偶然間看到命令窗口報異常,java.lang.OutOfMemoryError:heap space,還包括一大堆的其他錯誤——后面發現其他錯誤都是內存溢出引起的
- 用jconsole和jvisualvm嘗試打開服務器,行不通——堆內存溢出,工具無法直連
- 重啟服務器,開啟jsonsole和jvisualvm監控服務器
- 我喜歡用jconsole查看應用占用的內存變化以及線程的變化,從上午11:00記錄到現在已是7:40(晚上繼續監控,我想復現內存溢出錯誤)
- 變化情況:
- 線程從90多個變成現在有600多個,差不多一分鍾增加一個線程。而且絕大多數線程處於waiting、time-waited、runnable狀態,最多的線程是名字包含nioEventLoopGroup、Thread的兩組線程【線程堆棧信息】
- minor gc(也就是針對eden空間的gc)原來是差不多20秒執行一次,到現在已經是差不多10秒執行一次【高頻】
- 永久代到現在已經爆滿,故當前的minor gc一次,就會發生full gc一次,這時候問題就比較嚴重了。原來要1個多小時執行一次full gc,現在只要10秒鍾!
- 注意:Copy上的gc,也就是minor gc,在老年代空間滿了之后會停止執行; MarkSweepCompact上的gc,在開始每次執行耗時較長的,但是到了后面永久代滿了后單次耗時很短(94次總耗時1分鍾,到了147次總耗時還是1分鍾,此處也可能是因為時間不精確,等到明天早上來看吧……196次的時候2分鍾了)
- 問題描述:
- 這么看來,如果應用運行的時間越久,后期full gc就會越頻繁,服務器就會越卡,更不用說大量用戶訪問了,這是很嚴重的問題!
- 第二天早上一看,jconsole已失去對應用的連接,
- 堆棧上:老年代、survivor區、Enden空間均已爆滿
- 內存變化上看:堆內存使用量在凌晨1:37達到260M左右的峰值
- 已用、已提交、最大值均為253,440 KB,GC時間中copy收集器上的gc仍然停留在2319次,耗時31.109秒,MarkSweepCompact收集器上發生了3974次,耗時53分鍾
- 線程數量則達到989的峰值,活動線程達到982,守護線程73個,啟動線程總數25272個
- 1:35:20的時候出現斷崖
- cmd命令窗口Exception in thread "RMI TCP Connection(idle)" java.lang.OutOfMemoryError:Java heap space
- 通過jconsole的“線程”頁左下角的線程列表,觀察后續大量線程的堆棧信息,發現之前看到的兩組線程都指向了一個依賴的jar包;
- 找出該jar包在代碼中的影響位置,發現只有三處(暫且記為A、B、C),且注銷這些代碼不影響應用啟動,這就好辦了
- 先驗證是不是此jar包引起,我把三處都注銷了,運行應用,用jconsole監控十多分鍾,發現線程不再增長,可以確定就是這個jar包在作祟了
- 分別注銷A、B、C三處代碼,運行應用,然后通過jconsole監視變化,最終確定是C處代碼導致的線程增長
- 驗證堆內存的使用暴漲是否與線程增長有關
- 注銷C處代碼,在開發環境主機和我本地機器上運行代碼,使用jconsole連接進行監控一個晚上
- 第二天早上驚喜地發現,老年代沒有爆滿,線程也只增加了個位數
- jvm配置
- 老年代爆滿只是小驚喜,更大的驚喜是:同一個應用,在我本機上跑出來的結果和開發環境主機上跑出來的結果差異較大。
- 垃圾收集器:因為我是Eclipse oxygen啟動,使用的G1收集器,而開發環境主機用的默認垃圾收集器(開發環境主機JDK版本只比我本地JDK低一個小版本)
- 垃圾收集活動:通過jconsole的"內存"頁,我本機的minor GC只有短27次!Full GC只在啟動的時候觸發過3次!minor gc的頻率在1個半小時到2個小時的樣子執行1次,遠不是20秒一次!但是開發環境主機上minor gc有1432次!而且因為應用在早上九點有一個任務調度而觸發了一次full gc。
- 堆內存變化:我本機上的堆內存變化在100M和600M之間的樣子,survivor空間長期爆滿,但是老年代的占用很低,eden空間變化也很慢(所以minor gc的頻率很低);開發環境主機上,堆內存變化在60M~120M之間,多半穩定在100M左右,survivor空間占用較低,永久代空間占用25%(12個小時占用25%,可知應用大概運行2天會有一次full gc),eden空間變化也較慢,但是比我本機的明顯要快