從一次線上故障思考 Java 問題定位思路
問題出現：現網CPU飆高，Full GC告警
CGI 服務釋出到現網後，現網機器出現了Full GC告警，同時CPU飆高99%。在優先恢復現網服務正常後，開始著手定位Full GC的問題。在現場只能夠抓到四個GC執行緒佔用了很高的CPU，無法抓到引發Full GC的執行緒。查看了服務故障期間的錯誤日誌，發現更多的是由於Full GC引起的問題服務異常日誌，無法確定Full GC的根源。為了查詢問題的根源，只能從釋出本身入手去查問題，發現一次bugfix的提交，有可能觸發一個死迴圈邏輯：
for(inti =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 會進入死迴圈。利用下面這段程式碼可以試驗：
publicstaticvoidmain(String[] args){
longtotalPage = Long.MAX_VALUE;
for(inti =0;i
if(i<0){
System.out.println(i);
}
}
}
通過日誌，發現外部確實傳遞了一個非常大的引數：
確認了當命中邏輯的時候，會進入一個死迴圈。在迴圈中不斷進行字串的拼接與list的Add操作，很快就會耗盡JVM堆記憶體導致Full GC。經過測算，實際上並不需要死迴圈，只要是一個比較大的迴圈，就能夠引發Full GC。對totlePage的大小做了限定後，釋出了新版本，沒有再出現Full GC的問題。
現場還原：重現問題，探索定位思路
回顧排查問題的過程並不高效，最開始懷疑過是否是打包有問題或使用的jdk版本不對，花了較多的時間確認打包問題。另一方面，釋出帶出的程式碼較多，通過重複review程式碼無法很快鎖定問題。為了探索一種更有效的問題定位方法，我將有問題的程式碼重新部署
如何確定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-gcutil12309100010
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-p12309 -H
-p 用於指定程序，-H 用於獲取每個執行緒的資訊，從 top 輸出的內容，可以看到有四個執行緒佔用了非常高的 CPU：
到這裡可以拿到12313、12312、12311、12314這四個執行緒id。為了確定這些是什麼執行緒，需要使用 jstack 命令來檢視這幾個是什麼執行緒。
高佔用CPU的是什麼執行緒？
3) jstack 是 Java 虛擬機器自帶的一種堆疊跟蹤工具，用於打印出給定的 Java 程序 ID 或 core file 或遠端除錯服務的 Java 堆疊資訊。使用下面命令，將 Java 程序的堆疊資訊列印到檔案中：
jstack -l12309>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.hprof12309
live 這個引數表示我們需要抓取的是目前在生命週期內的記憶體物件，也就是說 GC 收不走的物件，在這種場景下，我們需要的就是這些記憶體的資訊。生成了 hprof 檔案後，可以拉回到本地，使用 VisualVM 來開啟它進行分析。開啟後可以看到：
從資訊中可以看到，字串 char[] 在佔了記憶體的73%，因此可以確定的是記憶體洩漏與字串有關。通常生成的 headdump 檔案會很大，也可以使用下面的命令，來檢視佔用記憶體最多的型別：
jmap -histo12309> heap.log
輸出內容如下：
能否對堆內物件進行查詢？
5） 到這裡突然有個想法，如果能夠分析出相似度高的字串，那麼有比較大的可能是這些字串存在洩漏，從而可以縮小問題程式碼的範圍。確實是有這麼一種工具來對堆內的物件進行分析，也就是OQL（Object Query Language）,在VisualVM中可以對headdump檔案執行物件查詢，下面是一個示例，查詢包含內容最多的List：
selectmap(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:GCoverheadlimitexceeded
這種情況發生的原因是, 程式基本上耗盡了所有的可用記憶體, GC 也清理不了。JVM 執行垃圾收集的時間比例太大, 有效的運算量太小。預設情況下, 如果GC花費的時間超過 98%, 並且 GC 回收的記憶體少於 2%, JVM 就會丟擲這個錯誤。從這裡也可以看到 GC 執行緒一直在嘗試回收記憶體，但是回收效果實在太差，也就是第二點提到的。
4）當時在線上環境出現問題時，看到很多 log4 j的錯誤日誌資訊，是什麼原因？猜測大概是寫日誌的 I/O 操作要經過記憶體，而記憶體已經被使用光，無法進行寫操作所導致。這些問題都可以進一步研究。
對於一般的 OOM 問題，通過這幾個方面的思考，大致可以鎖定問題所在，或是縮小問題可能發生的範圍。例如對某些特定型別的記憶體洩漏來說，到這一步已經可以分析出是什麼型別導致記憶體洩漏。而對本案例來說，根據排查結果可以優先考慮的是字串的洩露，程式碼 review 中檢視是否有操作字串的地方，而不會將問題的優先順序鎖定在打包問題上。
擴充套件閱讀
Spring4+Spring MVC+MyBatis整合思路
來源：https://www.cnblogs.com/QG-whz/p/9647614.html
微信公眾號：javafirst
掃碼關注免費獲取更多資源
