天天看點

java bufferedreader讀大檔案會記憶體溢出嗎_分享一次 Java 記憶體洩漏的排查

  • 由來
  • 問題
  • 解決
  • 排查
  • 小結
  • 《Netty 實作原理與源碼解析 —— 精品合集》
  • 《Spring 實作原理與源碼解析 —— 精品合集》
  • 《MyBatis 實作原理與源碼解析 —— 精品合集》
  • 《Spring MVC 實作原理與源碼解析 —— 精品合集》
  • 《Spring Boot 實作原理與源碼解析 —— 精品合集》
  • 《資料庫實體設計合集》
  • 《Java 面試題 —— 精品合集》
  • 《Java 學習指南 —— 精品合集》

由來

前些日子小組内安排值班,輪流看顧我們的服務,主要做一些報警郵件處理、Bug 排查、營運 issue 處理的事。工作日還好,無論幹什麼都要上班的,若是輪到周末,那這一天算是毀了。

不知道是公司網絡廣了就這樣還是網絡運維組不給力,網絡總有問題,不是這邊交換機脫網了就是那邊路由器壞了,還偶發地各種逾時,而我們靈敏地服務探測服務總能準确地抓住偶現的小問題,給美好的工作加點料。好幾次值班組的小夥伴們一起吐槽,商量着怎麼避過服務保活機制,偷偷停了探測服務而不讓人發現(雖然也并不敢)。

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

問題

網絡問題?

晚上七點多開始,我就開始不停地收到報警郵件,郵件顯示探測的幾個接口有逾時情況。 多數執行棧都在:

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)
           

這個線程棧的報錯我見得多了,我們設定的 HTTP DNS 逾時是 1s, connect 逾時是 2s, read 逾時是 3s,這種報錯都是探測服務正常發送了 HTTP 請求,伺服器也在收到請求正常處理後正常響應了,但資料包在網絡層層轉發中丢失了,是以請求線程的執行棧會停留在擷取接口響應的地方。這種情況的典型特征就是能在伺服器上查找到對應的日志記錄。而且日志會顯示伺服器響應完全正常。 與它相對的還有線程棧停留在 Socket connect 處的,這是在建連時就失敗了,服務端完全無感覺。

我注意到其中一個接口報錯更頻繁一些,這個接口需要上傳一個 4M 的檔案到伺服器,然後經過一連串的業務邏輯處理,再傳回 2M 的文本資料,而其他的接口則是簡單的業務邏輯,我猜測可能是需要上傳下載下傳的資料太多,是以逾時導緻丢包的機率也更大吧。

根據這個猜想,群登上伺服器,使用請求的 request_id 在近期服務日志中搜尋一下,果不其然,就是網絡丢包問題導緻的接口逾時了。

當然這樣 leader 是不會滿意的,這個結論還得有人接鍋才行。于是趕緊聯系運維和網絡組,向他們确認一下當時的網絡狀态。網絡組同學回複說是我們探測服務所在機房的交換機老舊,存在未知的轉發瓶頸,正在優化,這讓我更放心了,于是在部門群裡簡單交待一下,算是完成任務。

問題爆發

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

這次幾乎所有的接口都在逾時,而我們那個大量網絡 I/O 的接口則是每次探測必逾時,難道是整個機房故障了麼。

我再次通過伺服器和監控看到各個接口的名額都很正常,自己測試了下接口也完全 OK,既然不影響線上服務,我準備先通過探測服務的接口把探測任務停掉再慢慢排查。

結果給暫停探測任務的接口發請求好久也沒有響應,這時候我才知道沒這麼簡單。

解決

記憶體洩漏

于是趕快登陸探測伺服器,首先是

top free df

三連,結果還真發現了些異常。

java bufferedreader讀大檔案會記憶體溢出嗎_分享一次 Java 記憶體洩漏的排查

我們的探測程序 CPU 占用率特别高,達到了 900%。

我們的 Java 程序,并不做大量 CPU 運算,正常情況下,CPU 應該在 100~200% 之間,出現這種 CPU 飙升的情況,要麼走到了死循環,要麼就是在做大量的 GC。

使用

jstat -gc pid [interval]

指令檢視了 java 程序的 GC 狀态,果然,FULL GC 達到了每秒一次。

java bufferedreader讀大檔案會記憶體溢出嗎_分享一次 Java 記憶體洩漏的排查

這麼多的 FULL GC,應該是記憶體洩漏沒跑了,于是 使用

jstack pid > jstack.log

儲存了線程棧的現場,使用

jmap -dump:format=b,file=heap.log pid

儲存了堆現場,然後重新開機了探測服務,報警郵件終于停止了。

jstat

jstat 是一個非常強大的 JVM 監控工具,一般用法是:

jstat [-options] pid interval

它支援的檢視項有:

  • -class 檢視類加載資訊
  • -compile 編譯統計資訊
  • -gc 垃圾回收資訊
  • -gcXXX 各區域 GC 的詳細資訊 如 -gcold

使用它,對定位 JVM 的記憶體問題很有幫助。

排查

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

分析棧

棧的分析很簡單,看一下線程數是不是過多,多數棧都在幹嘛。

> 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)
           

線程狀态好像也無異常,接下來分析堆檔案。

下載下傳堆 dump 檔案。

堆檔案都是一些二進制資料,在指令行檢視非常麻煩,Java 為我們提供的工具都是可視化的,Linux 伺服器上又沒法檢視,那麼首先要把檔案下載下傳到本地。

由于我們設定的堆記憶體為 4G,是以 dump 出來的堆檔案也很大,下載下傳它确實非常費事,不過我們可以先對它進行一次壓縮。

gzip

是個功能很強大的壓縮指令,特别是我們可以設定

-1 ~ -9

來指定它的壓縮級别,資料越大壓縮比率越大,耗時也就越長,推薦使用 -6~7, -9 實在是太慢了,且收益不大,有這個壓縮的時間,多出來的檔案也下載下傳好了。

使用 MAT 分析 jvm heap

MAT 是分析 Java 堆記憶體的利器,使用它打開我們的堆檔案(将檔案字尾改為

.hprof

), 它會提示我們要分析的種類,對于這次分析,果斷選擇

memory leak suspect

java bufferedreader讀大檔案會記憶體溢出嗎_分享一次 Java 記憶體洩漏的排查

從上面的餅圖中可以看出,絕大多數堆記憶體都被同一個記憶體占用了,再檢視堆記憶體詳情,向上層追溯,很快就發現了罪魁禍首。

java bufferedreader讀大檔案會記憶體溢出嗎_分享一次 Java 記憶體洩漏的排查

分析代碼

找到記憶體洩漏的對象了,在項目裡全局搜尋對象名,它是一個 Bean 對象,然後定位到它的一個類型為 Map 的屬性。

這個 Map 根據類型用 ArrayList 存儲了每次探測接口響應的結果,每次探測完都塞到 ArrayList 裡去分析,由于 Bean 對象不會被回收,這個屬性又沒有清除邏輯,是以在服務十來天沒有上線重新開機的情況下,這個 Map 越來越大,直至将記憶體占滿。

記憶體滿了之後,無法再給 HTTP 響應結果配置設定記憶體了,是以一直卡在 readLine 那。而我們那個大量 I/O 的接口報警次數特别多,估計跟響應太大需要更多記憶體有關。

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

小結

其實還是要檢討一下自己的,一開始報警郵件裡還有這樣的線程棧:

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)
           

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

來源:http://t.cn/EIYkz7W

繼續閱讀