問題出現(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告警睛琳，同時(shí)CPU飆高99%盒蟆。在優(yōu)先恢復(fù)現(xiàn)網(wǎng)服務(wù)正常后，開始著手定位Full GC的問題师骗。在現(xiàn)場(chǎng)只能夠抓到四個(gè)GC線程占用了很高的CPU茁影，無法抓到引發(fā)Full GC的線程。查看了服務(wù)故障期間的錯(cuò)誤日志丧凤，發(fā)現(xiàn)更多的是由于Full GC引起的問題服務(wù)異常日志募闲，無法確定Full GC的根源。為了查找問題的根源愿待，只能從發(fā)布本身入手去查問題浩螺，發(fā)現(xiàn)一次bugfix的提交靴患，有可能觸發(fā)一個(gè)死循環(huán)邏輯：
for(inti =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 類型，由一個(gè)外部參數(shù)進(jìn)行賦值要出。當(dāng)外部參數(shù)非常大鸳君，超過 int 的最大值時(shí)，i遞增到int的最大值后患蹂，i++ 會(huì)發(fā)生翻轉(zhuǎn)或颊，變成一個(gè)負(fù)數(shù)，從而使 for 會(huì)進(jìn)入死循環(huán)传于。利用下面這段代碼可以試驗(yàn)：
publicstaticvoidmain(String[] args){
longtotalPage = Long.MAX_VALUE;
for(inti =0;i
if(i<0){
System.out.println(i);
}
}
}
通過日志囱挑，發(fā)現(xiàn)外部確實(shí)傳遞了一個(gè)非常大的參數(shù)：
確認(rèn)了當(dāng)命中邏輯的時(shí)候，會(huì)進(jìn)入一個(gè)死循環(huán)沼溜。在循環(huán)中不斷進(jìn)行字符串的拼接與list的Add操作平挑，很快就會(huì)耗盡JVM堆內(nèi)存導(dǎo)致Full GC。經(jīng)過測(cè)算系草，實(shí)際上并不需要死循環(huán)通熄，只要是一個(gè)比較大的循環(huán)，就能夠引發(fā)Full GC找都。對(duì)totlePage的大小做了限定后唇辨，發(fā)布了新版本，沒有再出現(xiàn)Full GC的問題能耻。
現(xiàn)場(chǎng)還原：重現(xiàn)問題赏枚，探索定位思路
回顧排查問題的過程并不高效，最開始懷疑過是否是打包有問題或使用的jdk版本不對(duì)嚎京，花了較多的時(shí)間確認(rèn)打包問題嗡贺。另一方面，發(fā)布帶出的代碼較多鞍帝，通過重復(fù)review代碼無法很快鎖定問題诫睬。為了探索一種更有效的問題定位方法，我將有問題的代碼重新部署到機(jī)器上帕涌，手動(dòng)構(gòu)造請(qǐng)求觸發(fā)bug摄凡，探索定位此類問題的通用思路。
如何確定bug可以導(dǎo)致CPU飆升蚓曼？為何會(huì)引發(fā)OOM亲澡？
1） 在 Java 服務(wù)上開啟 JMX，在本地使用 VisualVm 來查看 Java 服務(wù)在運(yùn)行過程中的內(nèi)存纫版、GC床绪、線程等信息。VisualVM 是 Sun 的一個(gè) OpenJDK 項(xiàng)目，它是集成了多個(gè) JDK 命令工具的一個(gè)可視化工具癞己，它主要用來監(jiān)控 JVM 的運(yùn)行情況膀斋，可以用它來查看和瀏覽 Heap Dump、Thread Dump痹雅、內(nèi)存對(duì)象實(shí)例情況仰担、GC 執(zhí)行情況、CPU 消耗以及類的裝載情況绩社，也可以使用它來創(chuàng)建必要信息的日志摔蓝。
可以看到邏輯被命中的時(shí)候，CPU確實(shí)是升到100%的愉耙，此時(shí)也發(fā)生了Full GC告警贮尉。嘗試著多發(fā)了幾次請(qǐng)求，服務(wù)直接就掛掉了劲阎。這里有個(gè)問題是：不是已經(jīng)Full GC了嗎绘盟，為什么還會(huì)發(fā)生OOM鸠真？實(shí)際上悯仙，雖然JVM已經(jīng)開始回收內(nèi)存，但是由于對(duì)象被引用吠卷，這些內(nèi)存是回收不掉的锡垄。從GC日志可以看到回收的情況：
從GC日志中可以看到，新生代的Eden區(qū)域與老年代都已經(jīng)被占滿祭隔。如果新生代放不下對(duì)象的時(shí)候货岭，object會(huì)直接被放到老年代中。除了GC日志疾渴，也可以使用jstat命令來堆Java堆內(nèi)存的使用情況進(jìn)行統(tǒng)計(jì)展示:
jstat-gcutil12309100010
1000為統(tǒng)計(jì)的間隔千贯，單位為毫秒，10為統(tǒng)計(jì)的次數(shù)搞坝，輸出如下：
從輸出中同樣可以看到E（Eden）區(qū)與O（Old）區(qū)都已經(jīng)被占滿了搔谴。其他幾個(gè)輸出項(xiàng)的含義如下：
YGC: 從啟動(dòng)到采樣時(shí)Young Generation GC的次數(shù)
YGCT: 從啟動(dòng)到采樣時(shí)Young Generation GC所用的時(shí)間 (s).
FGC: 從啟動(dòng)到采樣時(shí)Old Generation GC的次數(shù).
FGCT: 從啟動(dòng)到采樣時(shí)Old Generation GC所用的時(shí)間 (s).
GCT: 從啟動(dòng)到采樣時(shí)GC所用的總時(shí)間 (s).
可以看到JVM一直在嘗試回收老年代姊扔，但是一直沒能將內(nèi)存回收回來绑榴。
如何獲取占用CPU最高的線程id忘嫉？
2）可以登上機(jī)器映挂，確認(rèn)下是什么線程使 CPU 飆高绵载。先ps查看 Java 進(jìn)程的 PID：
拿到進(jìn)程 pid 后宦言，可以使用 top 命令蔽氨，來看是什么線程占用了 CPU玉雾。
top-p12309 -H
-p 用于指定進(jìn)程融师，-H 用于獲取每個(gè)線程的信息右钾，從 top 輸出的內(nèi)容，可以看到有四個(gè)線程占用了非常高的 CPU：
到這里可以拿到12313、12312舀射、12311灭将、12314這四個(gè)線程id。為了確定這些是什么線程后控，需要使用 jstack 命令來查看這幾個(gè)是什么線程庙曙。
高占用CPU的是什么線程？
3) jstack 是 Java 虛擬機(jī)自帶的一種堆棧跟蹤工具浩淘，用于打印出給定的 Java 進(jìn)程 ID 或 core file 或遠(yuǎn)程調(diào)試服務(wù)的 Java 堆棧信息捌朴。使用下面命令，將 Java 進(jìn)程的堆棧信息打印到文件中：
jstack -l12309>stack.log
在線程堆棧信息中张抄，線程 id 是使用十六進(jìn)制來表示的砂蔽。將上面四個(gè)四個(gè)線程 id 轉(zhuǎn)換為16進(jìn)制，分別是0X3019署惯、0X3018左驾、0×3017、0x301A极谊。在 stack.log 中可以找到這幾個(gè)線程：
到這里可以確定的是诡右，死循環(huán)引發(fā)了Full GC,四個(gè)GC線程一直嘗試著回收內(nèi)存，這四個(gè)線程將CPU占滿轻猖。
是哪些對(duì)象占用了內(nèi)存帆吻？
4）Full GC、OOM咙边、CPU 被占滿的問題都得到了解答猜煮。那么再次遇到類似的線上問題時(shí)，如何確定或者縮小問題范圍败许，找到導(dǎo)致問題的代碼呢王带？這時(shí)候需要進(jìn)一步觀察的是 Java 堆內(nèi)存的信息，查看是什么對(duì)象占用了內(nèi)存市殷°底可以使用上文提到的 VisualVM 來生成 headdump 文件：
也可以在機(jī)器上使用 jmap 命令來生成 head dump 文件。
jmap -dump:live,format=b,file=headInfo.hprof12309
live 這個(gè)參數(shù)表示我們需要抓取的是目前在生命周期內(nèi)的內(nèi)存對(duì)象被丧，也就是說 GC 收不走的對(duì)象盟戏，在這種場(chǎng)景下，我們需要的就是這些內(nèi)存的信息甥桂。生成了 hprof 文件后柿究，可以拉回到本地，使用 VisualVM 來打開它進(jìn)行分析黄选。打開后可以看到：
從信息中可以看到蝇摸，字符串 char[] 在占了內(nèi)存的73%婶肩，因此可以確定的是內(nèi)存泄漏與字符串有關(guān)。通常生成的 headdump 文件會(huì)很大貌夕，也可以使用下面的命令律歼，來查看占用內(nèi)存最多的類型：
jmap -histo12309> heap.log
輸出內(nèi)容如下：
能否對(duì)堆內(nèi)對(duì)象進(jìn)行查詢？
5） 到這里突然有個(gè)想法啡专，如果能夠分析出相似度高的字符串险毁，那么有比較大的可能是這些字符串存在泄漏，從而可以縮小問題代碼的范圍们童。確實(shí)是有這么一種工具來對(duì)堆內(nèi)的對(duì)象進(jìn)行分析畔况，也就是OQL（Object Query Language）,在VisualVM中可以對(duì)headdump文件執(zhí)行對(duì)象查詢，下面是一個(gè)示例慧库，查找包含內(nèi)容最多的List：
selectmap(top(heap.objects('java.util.ArrayList'),'rhs.size - lhs.size',5),"toHtml(it)+'='+it.size")
查詢結(jié)果如下：
如何查找到相似度最高的字符串跷跪，還在繼續(xù)學(xué)習(xí)研究中。
一些疑問與總結(jié)
1）為什么無法抓到引發(fā) Full GC 的線程齐板？一個(gè)猜測(cè)是線程拋出 OOM 異常之后就被終止了吵瞻，線程只存活了很短的時(shí)間。
2）為什么對(duì) Eden 區(qū)回收后存活的對(duì)象甘磨，不會(huì)被拷貝到 survivor 區(qū)橡羞？從上面的 GC 日志可以看到，BeforeGC 與 AfterGC宽档，新生代中的兩個(gè)survivor 區(qū)（也就是from\to）一直都是0%尉姨，這里猜想可能是 survivor 區(qū)太小庵朝，沒有足夠的空間存放從 Eden 區(qū)拷貝拷貝過來的對(duì)象吗冤。同時(shí)老年代也沒有足夠的空間（已經(jīng)99%了），因此 JVM 的 GC 基本沒有什么有效的回收操作九府。
3）重現(xiàn)問題時(shí)椎瘟，在日志里發(fā)現(xiàn)了一個(gè) OOM 的錯(cuò)誤信息：
java.lang.OutOfMemoryError:GCoverheadlimitexceeded
這種情況發(fā)生的原因是, 程序基本上耗盡了所有的可用內(nèi)存, GC 也清理不了。JVM 執(zhí)行垃圾收集的時(shí)間比例太大, 有效的運(yùn)算量太小侄旬。默認(rèn)情況下, 如果GC花費(fèi)的時(shí)間超過 98%, 并且 GC 回收的內(nèi)存少于 2%, JVM 就會(huì)拋出這個(gè)錯(cuò)誤肺蔚。從這里也可以看到 GC 線程一直在嘗試回收內(nèi)存，但是回收效果實(shí)在太差儡羔，也就是第二點(diǎn)提到的宣羊。
4）當(dāng)時(shí)在線上環(huán)境出現(xiàn)問題時(shí)，看到很多 log4 j的錯(cuò)誤日志信息汰蜘，是什么原因仇冯？猜測(cè)大概是寫日志的?I/O 操作要經(jīng)過內(nèi)存，而內(nèi)存已經(jīng)被使用光族操，無法進(jìn)行寫操作所導(dǎo)致苛坚。這些問題都可以進(jìn)一步研究。
對(duì)于一般的 OOM 問題，通過這幾個(gè)方面的思考泼舱，大致可以鎖定問題所在等缀，或是縮小問題可能發(fā)生的范圍。例如對(duì)某些特定類型的內(nèi)存泄漏來說娇昙，到這一步已經(jīng)可以分析出是什么類型導(dǎo)致內(nèi)存泄漏尺迂。而對(duì)本案例來說，根據(jù)排查結(jié)果可以優(yōu)先考慮的是字符串的泄露冒掌，代碼 review 中查看是否有操作字符串的地方枪狂，而不會(huì)將問題的優(yōu)先級(jí)鎖定在打包問題上。
擴(kuò)展閱讀
Spring4+Spring MVC+MyBatis整合思路
來源：https://www.cnblogs.com/QG-whz/p/9647614.html
