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

問題出現：現網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<totalPage;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：

到這裏能夠拿到1231三、123十二、123十一、12314這四個線程id。爲了肯定這些是什麼線程，須要使用jstack命令來查看這幾個是什麼線程。

高佔用CPU的是什麼線程？

3) jstack是java虛擬機自帶的一種堆棧跟蹤工具，用於打印出給定的java進程ID或core file或遠程調試服務的Java堆棧信息。使用下面命令，將java進程的堆棧信息打印到文件中：

jstack -l 12309 > stack.log

在線程堆棧信息中，線程id是使用十六進制來表示的。將上面四個四個線程id轉換爲16進制，分別是0X301九、0X301八、0x301七、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）當時在線上環境出現問題時，看到不少log4j的錯誤日誌信息，是什麼緣由？猜想大概是寫日誌的I/O操做要通過內存，而內存已經被使用光，沒法進行寫操做所致使。這些問題均可以進一步研究。

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

(完)