一次驚險的Java 內(nèi)存泄漏排查日志......

| 背景

前些日子小組內(nèi)安排值班，輪流看顧我們的服務(wù)，主要做一些報警郵件處理、Bug 排查、運營 issue 處理的事。工作日還好，無論干什么都要上班的，若是輪到周末，那這一天算是毀了。

不知道是公司網(wǎng)絡(luò)廣了就這樣還是網(wǎng)絡(luò)運維組不給力，網(wǎng)絡(luò)總有問題，不是這邊交換機(jī)脫網(wǎng)了就是那邊路由器壞了，還偶發(fā)地各種超時，而我們靈敏地服務(wù)探測服務(wù)總能準(zhǔn)確地抓住偶現(xiàn)的小問題，給美好的工作加點料。好幾次值班組的小伙伴們一起吐槽，商量著怎么避過服務(wù)保活機(jī)制，偷偷停了探測服務(wù)而不讓人發(fā)現(xiàn)（雖然也并不敢）。

前些天我就在周末處理了一次探測服務(wù)的鍋。

| 問題

網(wǎng)絡(luò)問題？

晚上七點多開始，我就開始不停地收到報警郵件，郵件顯示探測的幾個接口有超時情況。多數(shù)執(zhí)行棧都在：

java.io.BufferedReader.readLine(BufferedReader.java:371)
java.io.BufferedReader.readLine(BufferReader.java:389)
java_io_BufferedReader$readLine.call(Unknown?Source)
com.domain.detect.http.HttpClient.getResponse(HttpClient.groovy:122)
com.domain.detect.http.HttpClient.this$2$getResponse(HttpClient.groovy)

這個線程棧的報錯我見得多了，我們設(shè)置的 HTTP DNS 超時是 1s， connect 超時是 2s， read 超時是 3s，這種報錯都是探測服務(wù)正常發(fā)送了 HTTP 請求，服務(wù)器也在收到請求正常處理后正常響應(yīng)了，但數(shù)據(jù)包在網(wǎng)絡(luò)層層轉(zhuǎn)發(fā)中丟失了，所以請求線程的執(zhí)行棧會停留在獲取接口響應(yīng)的地方。這種情況的典型特征就是能在服務(wù)器上查找到對應(yīng)的日志記錄。而且日志會顯示服務(wù)器響應(yīng)完全正常。與它相對的還有線程棧停留在 Socket connect 處的，這是在建連時就失敗了，服務(wù)端完全無感知。

我注意到其中一個接口報錯更頻繁一些，這個接口需要上傳一個 4M 的文件到服務(wù)器，然后經(jīng)過一連串的業(yè)務(wù)邏輯處理，再返回 2M 的文本數(shù)據(jù)，而其他的接口則是簡單的業(yè)務(wù)邏輯，我猜測可能是需要上傳下載的數(shù)據(jù)太多，所以超時導(dǎo)致丟包的概率也更大吧。

根據(jù)這個猜想，群登上服務(wù)器，使用請求的 request_id 在近期服務(wù)日志中搜索一下，果不其然，就是網(wǎng)絡(luò)丟包問題導(dǎo)致的接口超時了。

當(dāng)然這樣 leader 是不會滿意的，這個結(jié)論還得有人接鍋才行。于是趕緊聯(lián)系運維和網(wǎng)絡(luò)組，向他們確認(rèn)一下當(dāng)時的網(wǎng)絡(luò)狀態(tài)。網(wǎng)絡(luò)組同學(xué)回復(fù)說是我們探測服務(wù)所在機(jī)房的交換機(jī)老舊，存在未知的轉(zhuǎn)發(fā)瓶頸，正在優(yōu)化，這讓我更放心了，于是在部門群里簡單交待一下，算是完成任務(wù)。

| 問題爆發(fā)

本以為這次值班就起這么一個小波浪，結(jié)果在晚上八點多，各種接口的報警郵件蜂擁而至，打得準(zhǔn)備收拾東西過周日單休的我措手不及。

這次幾乎所有的接口都在超時，而我們那個大量網(wǎng)絡(luò) I/O 的接口則是每次探測必超時，難道是整個機(jī)房故障了么。

我再次通過服務(wù)器和監(jiān)控看到各個接口的指標(biāo)都很正常，自己測試了下接口也完全 OK，既然不影響線上服務(wù)，我準(zhǔn)備先通過探測服務(wù)的接口把探測任務(wù)停掉再慢慢排查。

結(jié)果給暫停探測任務(wù)的接口發(fā)請求好久也沒有響應(yīng)，這時候我才知道沒這么簡單。

|?解決

內(nèi)存泄漏

于是趕快登錄探測服務(wù)器，首先是?top free df?三連，結(jié)果還真發(fā)現(xiàn)了些異常。

我們的探測進(jìn)程 CPU 占用率特別高，達(dá)到了 900%。

我們的 Java 進(jìn)程，并不做大量 CPU 運算，正常情況下，CPU 應(yīng)該在 100~200% 之間，出現(xiàn)這種 CPU 飆升的情況，要么走到了死循環(huán)，要么就是在做大量的 GC。

使用?jstat -gc pid [interval]?命令查看了 java 進(jìn)程的 GC 狀態(tài)，果然，F(xiàn)ULL GC 達(dá)到了每秒一次。

這么多的 FULL GC，應(yīng)該是內(nèi)存泄漏沒跑了，于是 使用?jstack pid > jstack.log?保存了線程棧的現(xiàn)場，使用?jmap -dump:format=b,file=heap.log pid?保存了堆現(xiàn)場，然后重啟了探測服務(wù)，報警郵件終于停止了。

jstat

jstat 是一個非常強(qiáng)大的 JVM 監(jiān)控工具，一般用法是：jstat [-options] pid interval

它支持的查看項有：

• -class 查看類加載信息
• -compile 編譯統(tǒng)計信息
• -gc 垃圾回收信息
• -gcXXX 各區(qū)域 GC 的詳細(xì)信息 如 -gcold

使用它，對定位 JVM 的內(nèi)存問題很有幫助。

| 排查

問題雖然解決了，但為了防止它再次發(fā)生，還是要把根源揪出來。

分析棧

棧的分析很簡單，看一下線程數(shù)是不是過多，多數(shù)棧都在干嘛。

>?grep?'java.lang.Thread.State'?jstack.log??|?wc?-l
>?464

才四百多線程，并無異常。

>?grep?-A?1?'java.lang.Thread.State'?jstack.log??|?grep?-v?'java.lang.Thread.State'?|?sort?|?uniq?-c?|sort?-n

?????10??at?java.lang.Class.forName0(Native?Method)
?????10??at?java.lang.Object.wait(Native?Method)
?????16??at?java.lang.ClassLoader.loadClass(ClassLoader.java:404)
?????44??at?sun.nio.ch.EPollArrayWrapper.epollWait(Native?Method)
????344??at?sun.misc.Unsafe.park(Native?Method)

線程狀態(tài)好像也無異常，接下來分析堆文件。

下載堆 dump 文件

堆文件都是一些二進(jìn)制數(shù)據(jù)，在命令行查看非常麻煩，Java 為我們提供的工具都是可視化的，Linux 服務(wù)器上又沒法查看，那么首先要把文件下載到本地。

由于我們設(shè)置的堆內(nèi)存為 4G，所以 dump 出來的堆文件也很大，下載它確實非常費事，不過我們可以先對它進(jìn)行一次壓縮。

gzip?是個功能很強(qiáng)大的壓縮命令，特別是我們可以設(shè)置?-1 ~ -9?來指定它的壓縮級別，數(shù)據(jù)越大壓縮比率越大，耗時也就越長，推薦使用 -6~7， -9 實在是太慢了，且收益不大，有這個壓縮的時間，多出來的文件也下載好了。

使用 MAT 分析 jvm heap

MAT 是分析 Java 堆內(nèi)存的利器，使用它打開我們的堆文件（將文件后綴改為?.hprof）, 它會提示我們要分析的種類，對于這次分析，果斷選擇?memory leak suspect。

分析代碼

找到內(nèi)存泄漏的對象了，在項目里全局搜索對象名，它是一個 Bean 對象，然后定位到它的一個類型為 Map 的屬性。

這個 Map 根據(jù)類型用 ArrayList 存儲了每次探測接口響應(yīng)的結(jié)果，每次探測完都塞到 ArrayList 里去分析，由于 Bean 對象不會被回收，這個屬性又沒有清除邏輯，所以在服務(wù)十來天沒有上線重啟的情況下，這個 Map 越來越大，直至將內(nèi)存占滿。

內(nèi)存滿了之后，無法再給 HTTP 響應(yīng)結(jié)果分配內(nèi)存了，所以一直卡在 readLine 那。而我們那個大量 I/O 的接口報警次數(shù)特別多，估計跟響應(yīng)太大需要更多內(nèi)存有關(guān)。

給代碼 owner 提了 PR，問題圓滿解決。

| 小結(jié)

其實還是要反省一下自己的，一開始報警郵件里還有這樣的線程棧：

groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:166)
groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132)
groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:186)
groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132)
groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:186)

看到這種報錯線程棧卻沒有細(xì)想，要知道 TCP 是能保證消息完整性的，況且消息沒有接收完也不會把值賦給變量，這種很明顯的是內(nèi)部錯誤，如果留意后細(xì)查是能提前查出問題所在的，查問題真是差了哪一環(huán)都不行啊。

來源：https://zhenbianshu.github.io/2018/12/troubleshooting_java_memory_leak.html