問題現(xiàn)象
vrs后臺(tái)系統(tǒng)從某一時(shí)間點(diǎn)，根據(jù)已查結(jié)果，追溯到幾個(gè)月前上線的PGC審核功能引起。
近期大概一周左右運(yùn)營(yíng)使用時(shí)會(huì)反饋系統(tǒng)訪問越來越來慢，最終系統(tǒng)崩潰，無法訪問。因?yàn)橹懊劫Y每周都會(huì)有功能上線，把這個(gè)問題覆蓋掉了，未能很快暴露出來。
實(shí)際上，通過Zabbix觀察監(jiān)控cpu、swap占用都是比較高的。
1031問題分析之CPU 100%
10-31日出現(xiàn)過一次問題，服務(wù)器上執(zhí)行top命令按鍵1觀察始終有一個(gè)cpu占用總100%，懷疑可能是因后臺(tái)服務(wù)請(qǐng)求過多CPU繁忙導(dǎo)致訪問慢。
將后臺(tái)服務(wù)切到備機(jī)，通過堆棧分析具體那段代碼引起的CPU占用100%問題。
問題定位過程：
1）jps -m 非常方便直接定位所有的Java進(jìn)程pid
[root@cdn ldw]# jps -m | grep 28081
6687 WatchdogManager start -conf /ldw/conf/resin/resin-mms-webapp-28081.xml --log-directory /ldw/apps/resin/log
6734 Resin --root-directory /ldw/apps/resin/ -conf /ldw/conf/resin/resin-mms-webapp-28081.xml -server default -socketwait 15304 start --log-directory /ldw/apps/resin/log
2）jstack -l pid > jstack1031.log命令打印棧信息，如果因某些原因無法成功打印，
可以使用kill -3 pid，輸出到j(luò)vm日志中，resin服務(wù)器默認(rèn)輸出到j(luò)vm-default.log日志中】
3）查找占用CPU資源最高的進(jìn)程id，使用top -H -p pid 查看進(jìn)程pid的所有的線程，默認(rèn)是按照%CPU高~低排序。
或者直接使用top查看， shift+H顯示所有的線程，默認(rèn)按照%CPU高~低排序。
找到占用CPU利用率最高的pid，一般CPU利用率達(dá)到90%以上，將pid轉(zhuǎn)換為16進(jìn)制，方法有很多種，我使用linux自帶python命令：hex(pid)，很方便。
4）根據(jù)轉(zhuǎn)換的16進(jìn)制去jstack.log日志中查找基本能定位到具體哪行代碼的問題。
"reportThirdException" daemon prio=10 tid=0x00007f8bd450b800 nid=0x12c4 runnable [0x00007f8b906ac000]
java.lang.Thread.State: RUNNABLE
at com.xxx.interfaces.util.NoticeMonitorSysHelper$ThreadStatue$1.run(NoticeMonitorSysHelper.java:167)
at java.lang.Thread.run(Thread.java:722)
5）fix代碼，重新部署上線
觀察cpu迅速降到正常值，swap值也降下來了，第二天觀察cpu、swap并沒有明顯的增加。
6）在備機(jī)切換到線上機(jī)器前，通過jmap打印出JVM堆內(nèi)存信息
jmap -dump:live,format=b,file=heap1031.bin <pid>
1212問題分析之內(nèi)存泄漏
12-11日晚VRS系統(tǒng)又一次服務(wù)Down掉，但是當(dāng)時(shí)收到反饋后并沒有及時(shí)切到備機(jī)，未能及時(shí)保留問題現(xiàn)場(chǎng)，緊急重啟后暫時(shí)恢復(fù)服務(wù)，此時(shí)距離上一次上線間隔為9D。
通過Zabbix監(jiān)控來看swap內(nèi)存這些天每天都在升高，最大值占用了接近4G，可服務(wù)器總內(nèi)存不過才6G，初步定位肯定是Java應(yīng)用內(nèi)存泄漏導(dǎo)致。
第二天一塊討論這塊問題如何排查，內(nèi)存泄漏一般通過jstack輸出的棧很難定位到問題，只能對(duì)JVM堆內(nèi)存信息做分析。
這次問題也聯(lián)想到上次故障處理后，實(shí)際并沒有找到問題根本原因，想到了1031日存留過JVM堆信息heap1031.bin，然后下載到本地通過MAT(Eclipse插件)進(jìn)行內(nèi)存分析。也可以通過其他工具如jhat，但不如MAT直觀。
問題定位過程：
進(jìn)入Eclipse：Memory analysis
選擇File—》Open Head Dump…打開heap1031.bin
會(huì)彈出一個(gè)對(duì)話框，選擇Leak Suspects Report 【自動(dòng)檢測(cè)存疑的泄漏點(diǎn)，會(huì)報(bào)告出那些存活的對(duì)象以及這些對(duì)象沒有被gc的原因】
MAT會(huì)自動(dòng)分析出內(nèi)存大致情況，直方圖顯示內(nèi)存占用以及Problem Suspect
通過以上會(huì)看到1635個(gè)JPEGImageReader實(shí)例沒有被釋放，可能這個(gè)是導(dǎo)致內(nèi)存泄漏的根源，也說明跟系統(tǒng)裁圖功能有關(guān)，縮小了問題定位范圍。
沒有釋放資源懷疑可能是IO流沒有正常關(guān)閉導(dǎo)致，因JVM堆棧轉(zhuǎn)存只看到底層代碼，具體還要進(jìn)一步分析程序源代碼。
下一步，點(diǎn)擊Details
再點(diǎn)擊下面的Class Name，查看Inspector【顯示了當(dāng)前顯示類或?qū)ο蟮脑敿?xì)信息】
通過Inspector能知道使用了javax.imageio.ImageReader接口，我們處理圖片的任務(wù)都在ImageResize.java類中，然后對(duì)這塊代碼進(jìn)行分析排查。
最初懷疑自動(dòng)截圖這塊的影響，單獨(dú)對(duì)自動(dòng)截圖功能做批量測(cè)試，循環(huán)截圖100，1000次dump內(nèi)存看基本都沒有太大變化。
代碼排查：
try{ //ImageReader聲稱能夠解碼指定格式
Iterator<ImageReader> it = ImageIO.getImageReadersByFormatName(ext);
ImageReader reader = it.next();
// 輸入源中的圖像將只按順序讀取
reader.setInput(iis, true);
int srcWidth = reader.getWidth(0); // 源圖寬度
int srcHeight = reader.getHeight(0); // 源圖高度
if (srcWidth >= destWidth && srcHeight >= destHeight) { // 處理圖片... reader.dispose(); } } catch (Exception e) { logger.error("Cut image failed, src_image_file:{}, error:{}, ", srcImageFile, e.getMessage(), e);
} finally { // ... } |
|---|
從ImageReader入手查看代碼，發(fā)現(xiàn)調(diào)用了dispose方法，但是只在try中做了調(diào)用，finally中并沒有調(diào)用dispose方法。懷疑如果if條件不成立或者有異常發(fā)生，則不會(huì)調(diào)用dispose方法。
查看下dispose方法的含義，如果不再使用這個(gè)ImageReader對(duì)象時(shí)，必須調(diào)用這個(gè)方法釋放資源；否則，可能導(dǎo)致資源(內(nèi)存)無限的被占用。
/** * Allows any resources held by this object to be released. The * result of calling any other method (other than * <code>finalize</code>) subsequent to a call to this method * is undefined. * * <p>It is important for applications to call this method when they * know they will no longer be using this <code>ImageReader</code>. * Otherwise, the reader may continue to hold on to resources * indefinitely. * * <p>The default implementation of this method in the superclass does * nothing. Subclass implementations should ensure that all resources, * especially native resources, are released. */ public void dispose() { } |
|---|
找到這個(gè)原因時(shí)很興奮，所以我們將try中的reader.dispose()代碼注釋掉，直接做截圖測(cè)試，100，1000，然后打印JVM堆棧轉(zhuǎn)存用MAT分析，印證了上面的分析結(jié)果。
然后修復(fù)這個(gè)Java類+log（不符合預(yù)期的log打印），部署上線了。
因?yàn)橐阎懒薐PEGImageReader實(shí)例未被釋放，故可通過命令jmap -histo:live <pid> | grep ImageReader 【jmap -histo:live <pid> 分析具體的對(duì)象數(shù)目和占用內(nèi)存大小】
在線上來查看JPEGImageReader instances數(shù)量變化，大概觀察1個(gè)小時(shí)左右，發(fā)現(xiàn)JPEGImageReader instances>5了，而且也沒有不符合條件的log輸出，正常應(yīng)該釋放掉的，難道還是有內(nèi)存泄漏？
然后，繼續(xù)分析代碼，根據(jù)ImageReader搜索了下整個(gè)代碼庫，發(fā)現(xiàn)有個(gè)PgcAuditServiceImpl.java PGC審核里也有引用的代碼。
Iterator<ImageReader> it = ImageIO.getImageReadersByFormatName(ext);
reader = it.next();
… //這里沒有調(diào)用dispose() |
|---|
這塊僅使用了ImageReader獲取width和height，之后并沒有調(diào)用dispose方法，盡快修復(fù)重新上線。
持續(xù)觀察一段時(shí)間，jmap查看類及對(duì)象情況：
[root@cdn ~]# jmap -histo:live 28093 | grep ImageReader
1905: 1 88 com.sun.imageio.plugins.gif.GIFImageReaderSpi
1913: 1 88 com.sun.imageio.plugins.bmp.BMPImageReaderSpi
1917: 1 88 com.sun.imageio.plugins.wbmp.WBMPImageReaderSpi
1922: 1 88 com.sun.imageio.plugins.png.PNGImageReaderSpi
1924: 1 88 com.sun.imageio.plugins.jpeg.JPEGImageReaderSpi
2685: 2 48 com.sun.imageio.plugins.jpeg.JPEGImageReader$CallBackLock$State
3881: 1 24 [Lcom.sun.imageio.plugins.jpeg.JPEGImageReader$CallBackLock$State;
com.sun.imageio.plugins.jpeg.JPEGImageReader$CallBackLock$State，內(nèi)部靜態(tài)類CallBackLock和State，所以有2個(gè)instances
[Lcom.sun.imageio.plugins.jpeg.JPEGImageReader$CallBackLock$State; 1個(gè)Class對(duì)象
持續(xù)觀察幾天性能指標(biāo)平穩(wěn)，服務(wù)器cpu、swap、load對(duì)于內(nèi)存泄漏前占用都非常少了。
經(jīng)過以上分析，實(shí)際本次故障罪魁禍?zhǔn)资窃赑GC審核截圖引起。香港vrs因運(yùn)營(yíng)沒有使用到PGC審核功能所以也不會(huì)觸發(fā)內(nèi)存泄漏問題。