問題出現(xiàn)：現(xiàn)網(wǎng)CPU飆高，F(xiàn)ull GC告警

CGI 服務(wù)發(fā)布到現(xiàn)網(wǎng)后，現(xiàn)網(wǎng)機(jī)器出現(xiàn)了Full GC告警，同時CPU飆高99%。在優(yōu)先恢復(fù)現(xiàn)網(wǎng)服務(wù)正常后，開始著手定位Full GC的問題。在現(xiàn)場只能夠抓到四個GC線程占用了很高的CPU，無法抓到引發(fā)Full GC的線程。查看了服務(wù)故障期間的錯誤日志，發(fā)現(xiàn)更多的是由于Full GC引起的問題服務(wù)異常日志，無法確定Full GC的根源。為了查找問題的根源，只能從發(fā)布本身入手去查問題，發(fā)現(xiàn)一次bugfix的提交，有可能觸發(fā)一個死循環(huán)邏輯：

for(int i = 1 ;i <= totalPage ;i++) {
            String path = path_prefix + "?cmd=txt_preview&page=" + String.valueOf(i) + "&sign=" + fileSignature;
            url_list.add(path);
}

循環(huán)中的參數(shù)?totalPage?為 long 類型，由一個外部參數(shù)進(jìn)行賦值。當(dāng)外部參數(shù)非常大，超過 int 的最大值時，i遞增到int的最大值后，i++?會發(fā)生翻轉(zhuǎn)，變成一個負(fù)數(shù)，從而使 for 會進(jìn)入死循環(huán)。利用下面這段代碼可以試驗(yàn)：

    public static void main(String[] args) {
        long totalPage = Long.MAX_VALUE;
        for(int i = 0 ;i<totalPage;i++){
            if(i<0){
                System.out.println(i);
            }
        }
    }

通過日志，發(fā)現(xiàn)外部確實(shí)傳遞了一個非常大的參數(shù)：

確認(rèn)了當(dāng)命中邏輯的時候，會進(jìn)入一個死循環(huán)。在循環(huán)中不斷進(jìn)行字符串的拼接與list的Add操作，很快就會耗盡JVM堆內(nèi)存導(dǎo)致Full GC。經(jīng)過測算，實(shí)際上并不需要死循環(huán)，只要是一個比較大的循環(huán)，就能夠引發(fā)Full GC。對totlePage的大小做了限定后，發(fā)布了新版本，沒有再出現(xiàn)Full GC的問題。

現(xiàn)場還原：重現(xiàn)問題，探索定位思路

回顧排查問題的過程并不高效，最開始懷疑過是否是打包有問題或使用的jdk版本不對，花了較多的時間確認(rèn)打包問題。另一方面，發(fā)布帶出的代碼較多，通過重復(fù)review代碼無法很快鎖定問題。為了探索一種更有效的問題定位方法，我將有問題的代碼重新部署到機(jī)器上，手動構(gòu)造請求觸發(fā)bug，探索定位此類問題的通用思路。

如何確定bug可以導(dǎo)致CPU飆升？為何會引發(fā)OOM？

1） 在 Java 服務(wù)上開啟?JMX，在本地使用?VisualVm?來查看 Java 服務(wù)在運(yùn)行過程中的內(nèi)存、GC、線程等信息。VisualVM 是 Sun 的一個 OpenJDK 項(xiàng)目，它是集成了多個 JDK 命令工具的一個可視化工具，它主要用來監(jiān)控 JVM 的運(yùn)行情況，可以用它來查看和瀏覽 Heap Dump、Thread Dump、內(nèi)存對象實(shí)例情況、GC 執(zhí)行情況、CPU 消耗以及類的裝載情況，也可以使用它來創(chuàng)建必要信息的日志。

 

可以看到邏輯被命中的時候，CPU確實(shí)是升到100%的，此時也發(fā)生了Full GC告警。嘗試著多發(fā)了幾次請求，服務(wù)直接就掛掉了。這里有個問題是：不是已經(jīng)Full GC了嗎，為什么還會發(fā)生OOM？實(shí)際上，雖然JVM已經(jīng)開始回收內(nèi)存，但是由于對象被引用，這些內(nèi)存是回收不掉的。從GC日志可以看到回收的情況：

從GC日志中可以看到，新生代的Eden區(qū)域與老年代都已經(jīng)被占滿。如果新生代放不下對象的時候，object會直接被放到老年代中。除了GC日志，也可以使用jstat命令來堆Java堆內(nèi)存的使用情況進(jìn)行統(tǒng)計(jì)展示:

jstat -gcutil 12309 1000 10

1000為統(tǒng)計(jì)的間隔，單位為毫秒，10為統(tǒng)計(jì)的次數(shù)，輸出如下：

從輸出中同樣可以看到E（Eden）區(qū)與O（Old）區(qū)都已經(jīng)被占滿了。其他幾個輸出項(xiàng)的含義如下：

• YGC: 從啟動到采樣時Young Generation GC的次數(shù)
• YGCT: 從啟動到采樣時Young Generation GC所用的時間 (s).
• FGC: 從啟動到采樣時Old Generation GC的次數(shù).
• FGCT: 從啟動到采樣時Old Generation GC所用的時間 (s).
• GCT: 從啟動到采樣時GC所用的總時間 (s).

可以看到JVM一直在嘗試回收老年代，但是一直沒能將內(nèi)存回收回來。

如何獲取占用CPU最高的線程id？

2）可以登上機(jī)器，確認(rèn)下是什么線程使 CPU 飆高。先ps查看 Java 進(jìn)程的 PID：

拿到進(jìn)程 pid 后，可以使用?top?命令，來看是什么線程占用了 CPU。

top -p 12309 -H

-p?用于指定進(jìn)程，-H?用于獲取每個線程的信息，從 top 輸出的內(nèi)容，可以看到有四個線程占用了非常高的 CPU：

到這里可以拿到12313、12312、12311、12314這四個線程id。為了確定這些是什么線程，需要使用?jstack?命令來查看這幾個是什么線程。

高占用CPU的是什么線程？

3)?jstack?是 Java 虛擬機(jī)自帶的一種堆棧跟蹤工具，用于打印出給定的 Java 進(jìn)程 ID 或 core file 或遠(yuǎn)程調(diào)試服務(wù)的 Java 堆棧信息。使用下面命令，將 Java 進(jìn)程的堆棧信息打印到文件中：

jstack -l 12309 > stack.log

在線程堆棧信息中，線程 id 是使用十六進(jìn)制來表示的。將上面四個四個線程 id 轉(zhuǎn)換為16進(jìn)制，分別是0X3019、0X3018、0×3017、0x301A。在 stack.log 中可以找到這幾個線程：

到這里可以確定的是，死循環(huán)引發(fā)了Full GC,四個GC線程一直嘗試著回收內(nèi)存，這四個線程將CPU占滿。

是哪些對象占用了內(nèi)存？

4）Full GC、OOM、CPU 被占滿的問題都得到了解答。那么再次遇到類似的線上問題時，如何確定或者縮小問題范圍，找到導(dǎo)致問題的代碼呢？這時候需要進(jìn)一步觀察的是 Java 堆內(nèi)存的信息，查看是什么對象占用了內(nèi)存�？梢允褂蒙衔奶岬降� VisualVM 來生成 headdump 文件：

也可以在機(jī)器上使用?jmap?命令來生成 head dump 文件。

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

live 這個參數(shù)表示我們需要抓取的是目前在生命周期內(nèi)的內(nèi)存對象，也就是說 GC 收不走的對象，在這種場景下，我們需要的就是這些內(nèi)存的信息。生成了 hprof 文件后，可以拉回到本地，使用 VisualVM 來打開它進(jìn)行分析。打開后可以看到：

從信息中可以看到，字符串 char[] 在占了內(nèi)存的73%，因此可以確定的是內(nèi)存泄漏與字符串有關(guān)。通常生成的 headdump 文件會很大，也可以使用下面的命令，來查看占用內(nèi)存最多的類型：

jmap -histo 12309 > heap.log

輸出內(nèi)容如下：

能否對堆內(nèi)對象進(jìn)行查詢？

5） 到這里突然有個想法，如果能夠分析出相似度高的字符串，那么有比較大的可能是這些字符串存在泄漏，從而可以縮小問題代碼的范圍。確實(shí)是有這么一種工具來對堆內(nèi)的對象進(jìn)行分析，也就是OQL（Object Query Language）,在VisualVM中可以對headdump文件執(zhí)行對象查詢，下面是一個示例，查找包含內(nèi)容最多的List：

select map(top(heap.objects('java.util.ArrayList'), 'rhs.size - lhs.size', 5),"toHtml(it)+'='+it.size")

查詢結(jié)果如下：

如何查找到相似度最高的字符串，還在繼續(xù)學(xué)習(xí)研究中。

一些疑問與總結(jié)

1）為什么無法抓到引發(fā) Full GC 的線程？一個猜測是線程拋出 OOM 異常之后就被終止了，線程只存活了很短的時間。
2）為什么對 Eden 區(qū)回收后存活的對象，不會被拷貝到 survivor 區(qū)？從上面的 GC 日志可以看到，BeforeGC 與 AfterGC，新生代中的兩個survivor 區(qū)（也就是from\to）一直都是0%，這里猜想可能是 survivor 區(qū)太小，沒有足夠的空間存放從 Eden 區(qū)拷貝拷貝過來的對象。同時老年代也沒有足夠的空間（已經(jīng)99%了），因此 JVM 的 GC 基本沒有什么有效的回收操作。
3）重現(xiàn)問題時，在日志里發(fā)現(xiàn)了一個 OOM 的錯誤信息：

java.lang.OutOfMemoryError: GC overhead limit exceeded

這種情況發(fā)生的原因是, 程序基本上耗盡了所有的可用內(nèi)存, GC 也清理不了。JVM 執(zhí)行垃圾收集的時間比例太大, 有效的運(yùn)算量太小。默認(rèn)情況下, 如果GC花費(fèi)的時間超過 98%, 并且 GC 回收的內(nèi)存少于 2%, JVM 就會拋出這個錯誤。從這里也可以看到 GC 線程一直在嘗試回收內(nèi)存，但是回收效果實(shí)在太差，也就是第二點(diǎn)提到的。
4）當(dāng)時在線上環(huán)境出現(xiàn)問題時，看到很多 log4 j的錯誤日志信息，是什么原因？猜測大概是寫日志的 I/O 操作要經(jīng)過內(nèi)存，而內(nèi)存已經(jīng)被使用光，無法進(jìn)行寫操作所導(dǎo)致。這些問題都可以進(jìn)一步研究。

對于一般的 OOM 問題，通過這幾個方面的思考，大致可以鎖定問題所在，或是縮小問題可能發(fā)生的范圍。例如對某些特定類型的內(nèi)存泄漏來說，到這一步已經(jīng)可以分析出是什么類型導(dǎo)致內(nèi)存泄漏。而對本案例來說，根據(jù)排查結(jié)果可以優(yōu)先考慮的是字符串的泄露，代碼 review 中查看是否有操作字符串的地方，而不會將問題的優(yōu)先級鎖定在打包問題上。

標(biāo)簽： 代碼

版權(quán)申明：本站文章部分自網(wǎng)絡(luò)，如有侵權(quán)，請聯(lián)系：west999com@outlook.com
特別注意：本站所有轉(zhuǎn)載文章言論不代表本站觀點(diǎn)！
本站所提供的圖片等素材，版權(quán)歸原作者所有，如需使用，請與原作者聯(lián)系。