歡迎光臨
每天分享高質量文章

從一次線上故障思考 Java 問題定位思路

(點擊上方公眾號,可快速關註)


來源:melonstreet ,

www.cnblogs.com/QG-whz/p/9647614.html

問題出現:現網CPU飆高,Full GC告警

CGI 服務發佈到現網後,現網機器出現了Full GC告警,同時CPU飆高99%。在優先恢復現網服務正常後,開始著手定位Full GC的問題。在現場只能夠抓到四個GC執行緒占用了很高的CPU,無法抓到引發Full GC的執行緒。查看了服務故障期間的錯誤日誌,發現更多的是由於Full GC引起的問題服務異常日誌,無法確定Full GC的根源。為了查找問題的根源,只能從發佈本身入手去查問題,發現一次bugfix的提交,有可能觸發一個死迴圈邏輯:

for(int i = 1 ;i <= totalPage ;i++) {

            String path = path_prefix + “?cmd=txt_preview&page;=” + String.valueOf(i) + “&sign;=” + fileSignature;

            url_list.add(path);

}

迴圈中的引數 totalPage 為 long 型別,由一個外部引數進行賦值。當外部引數非常大,超過 int 的最大值時,i遞增到int的最大值後,i++ 會發生翻轉,變成一個負數,從而使 for 會進入死迴圈。利用下麵這段代碼可以試驗:

public static void main(String[] args) {

    long totalPage = Long.MAX_VALUE;

    for(int i = 0 ;i

        if(i<0){

            System.out.println(i);

        }

    }

}

通過日誌,發現外部確實傳遞了一個非常大的引數:

確認了當命中邏輯的時候,會進入一個死迴圈。在迴圈中不斷進行字串的拼接與list的Add操作,很快就會耗盡JVM堆記憶體導致Full GC。經過測算,實際上並不需要死迴圈,只要是一個比較大的迴圈,就能夠引發Full GC。對totlePage的大小做了限定後,發佈了新版本,沒有再出現Full GC的問題。

現場還原:重現問題,探索定位思路

回顧排查問題的過程並不高效,最開始懷疑過是否是打包有問題或使用的jdk版本不對,花了較多的時間確認打包問題。另一方面,發佈帶出的代碼較多,通過重覆review代碼無法很快鎖定問題。為了探索一種更有效的問題定位方法,我將有問題的代碼重新部署到機器上,手動構造請求觸發bug,探索定位此類問題的通用思路。

如何確定bug可以導致CPU飆升?為何會引發OOM?

1) 在 Java 服務上開啟 JMX,在本地使用 VisualVm 來查看 Java 服務在運行過程中的記憶體、GC、執行緒等信息。VisualVM 是 Sun 的一個 OpenJDK 專案,它是集成了多個 JDK 命令工具的一個可視化工具,它主要用來監控 JVM 的運行情況,可以用它來查看和瀏覽 Heap Dump、Thread Dump、記憶體物件實體情況、GC 執行情況、CPU 消耗以及類的裝載情況,也可以使用它來創建必要信息的日誌。

可以看到邏輯被命中的時候,CPU確實是升到100%的,此時也發生了Full GC告警。嘗試著多發了幾次請求,服務直接就掛掉了。這裡有個問題是:不是已經Full GC了嗎,為什麼還會發生OOM?實際上,雖然JVM已經開始回收記憶體,但是由於物件被取用,這些記憶體是回收不掉的。從GC日誌可以看到回收的情況:

從GC日誌中可以看到,新生代的Eden區域與老年代都已經被占滿。如果新生代放不下物件的時候,object會直接被放到老年代中。除了GC日誌,也可以使用jstat命令來堆Java堆記憶體的使用情況進行統計展示:

jstat -gcutil 12309 1000 10

1000為統計的間隔,單位為毫秒,10為統計的次數,輸出如下:

從輸出中同樣可以看到E(Eden)區與O(Old)區都已經被占滿了。其他幾個輸出項的含義如下:

  • YGC: 從啟動到採樣時Young Generation GC的次數

  • YGCT: 從啟動到採樣時Young Generation GC所用的時間 (s).

  • FGC: 從啟動到採樣時Old Generation GC的次數.

  • FGCT: 從啟動到採樣時Old Generation GC所用的時間 (s).

  • GCT: 從啟動到採樣時GC所用的總時間 (s).

可以看到JVM一直在嘗試回收老年代,但是一直沒能將記憶體回收回來。

如何獲取占用CPU最高的執行緒id?

2)可以登上機器,確認下是什麼執行緒使 CPU 飆高。先ps查看 Java 行程的 PID:

拿到行程 pid 後,可以使用 top 命令,來看是什麼執行緒占用了 CPU。

top -p 12309 -H

-p 用於指定行程,-H 用於獲取每個執行緒的信息,從 top 輸出的內容,可以看到有四個執行緒占用了非常高的 CPU:

到這裡可以拿到12313、12312、12311、12314這四個執行緒id。為了確定這些是什麼執行緒,需要使用 jstack 命令來查看這幾個是什麼執行緒。

高占用CPU的是什麼執行緒?

3) jstack 是 Java 虛擬機自帶的一種堆棧跟蹤工具,用於打印出給定的 Java 行程 ID 或 core file 或遠程除錯服務的 Java 堆棧信息。使用下麵命令,將 Java 行程的堆棧信息打印到檔案中:

jstack -l 12309 > stack.log

在執行緒堆棧信息中,執行緒 id 是使用十六進制來表示的。將上面四個四個執行緒 id 轉換為16進制,分別是0X3019、0X3018、0×3017、0x301A。在 stack.log 中可以找到這幾個執行緒:

到這裡可以確定的是,死迴圈引發了Full GC,四個GC執行緒一直嘗試著回收記憶體,這四個執行緒將CPU占滿。

是哪些物件占用了記憶體?

4)Full GC、OOM、CPU 被占滿的問題都得到瞭解答。那麼再次遇到類似的線上問題時,如何確定或者縮小問題範圍,找到導致問題的代碼呢?這時候需要進一步觀察的是 Java 堆記憶體的信息,查看是什麼物件占用了記憶體。可以使用上文提到的 VisualVM 來生成 headdump 檔案:

也可以在機器上使用 jmap 命令來生成 head dump 檔案。

jmap -dump:live,format=b,file=headInfo.hprof 12309

live 這個引數表示我們需要抓取的是目前在生命周期內的記憶體物件,也就是說 GC 收不走的物件,在這種場景下,我們需要的就是這些記憶體的信息。生成了 hprof 檔案後,可以拉回到本地,使用 VisualVM 來打開它進行分析。打開後可以看到:

從信息中可以看到,字串 char[] 在占了記憶體的73%,因此可以確定的是記憶體泄漏與字串有關。通常生成的 headdump 檔案會很大,也可以使用下麵的命令,來查看占用記憶體最多的型別:

jmap -histo 12309 > heap.log

輸出內容如下:

能否對堆內物件進行查詢?

5) 到這裡突然有個想法,如果能夠分析出相似度高的字串,那麼有比較大的可能是這些字串存在泄漏,從而可以縮小問題代碼的範圍。確實是有這麼一種工具來對堆內的物件進行分析,也就是OQL(Object Query Language),在VisualVM中可以對headdump檔案執行物件查詢,下麵是一個示例,查找包含內容最多的List:

select map(top(heap.objects(‘java.util.ArrayList’), ‘rhs.size – lhs.size’, 5),”toHtml(it)+’=’+it.size”)

查詢結果如下:

如何查找到相似度最高的字串,還在繼續學習研究中。

一些疑問與總結

1)為什麼無法抓到引發 Full GC 的執行緒?一個猜測是執行緒丟擲 OOM 異常之後就被終止了,執行緒只存活了很短的時間。

2)為什麼對 Eden 區回收後存活的物件,不會被拷貝到 survivor 區?從上面的 GC 日誌可以看到,BeforeGC 與 AfterGC,新生代中的兩個survivor 區(也就是from\to)一直都是0%,這裡猜想可能是 survivor 區太小,沒有足夠的空間存放從 Eden 區拷貝拷貝過來的物件。同時老年代也沒有足夠的空間(已經99%了),因此 JVM 的 GC 基本沒有什麼有效的回收操作。

3)重現問題時,在日誌里發現了一個 OOM 的錯誤信息:

java.lang.OutOfMemoryError: GC overhead limit exceeded

這種情況發生的原因是, 程式基本上耗盡了所有的可用記憶體, GC 也清理不了。JVM 執行垃圾收集的時間比例太大, 有效的運算量太小。預設情況下, 如果GC花費的時間超過 98%, 並且 GC 回收的記憶體少於 2%, JVM 就會丟擲這個錯誤。從這裡也可以看到 GC 執行緒一直在嘗試回收記憶體,但是回收效果實在太差,也就是第二點提到的。

4)當時在線上環境出現問題時,看到很多 log4 j的錯誤日誌信息,是什麼原因?猜測大概是寫日誌的 I/O 操作要經過記憶體,而記憶體已經被使用光,無法進行寫操作所導致。這些問題都可以進一步研究。

對於一般的 OOM 問題,通過這幾個方面的思考,大致可以鎖定問題所在,或是縮小問題可能發生的範圍。例如對某些特定型別的記憶體泄漏來說,到這一步已經可以分析出是什麼型別導致記憶體泄漏。而對本案例來說,根據排查結果可以優先考慮的是字串的泄露,代碼 review 中查看是否有操作字串的地方,而不會將問題的優先級鎖定在打包問題上。

【關於投稿】


如果大家有原創好文投稿,請直接給公號發送留言。


① 留言格式:
【投稿】+《 文章標題》+ 文章鏈接

② 示例:
【投稿】《不要自稱是程式員,我十多年的 IT 職場總結》:http://blog.jobbole.com/94148/

③ 最後請附上您的個人簡介哈~



看完本文有收穫?請轉發分享給更多人

關註「ImportNew」,提升Java技能

赞(0)

分享創造快樂