問題現象
vrs后臺系統從某一時間點，根據已查結果，追溯到幾個月前上線的PGC審核功能引起。
近期大概一周左右運營使用時會反饋系統訪問越來越來慢，最終系統崩潰，無法訪問。因為之前媒資每周都會有功能上線，把這個問題覆蓋掉了，未能很快暴露出來。
實際上，通過Zabbix觀察監控cpu、swap占用都是比較高的。
1031問題分析之CPU 100%
10-31日出現過一次問題，服務器上執行top命令按鍵1觀察始終有一個cpu占用總100%，懷疑可能是因后臺服務請求過多CPU繁忙導致訪問慢。
將后臺服務切到備機，通過堆棧分析具體那段代碼引起的CPU占用100%問題。
問題定位過程：
1）jps -m 非常方便直接定位所有的Java進程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，輸出到jvm日志中，resin服務器默認輸出到jvm-default.log日志中】
3）查找占用CPU資源最高的進程id，使用top -H -p pid 查看進程pid的所有的線程，默認是按照%CPU高~低排序。
或者直接使用top查看， shift+H顯示所有的線程，默認按照%CPU高~低排序。
找到占用CPU利用率最高的pid，一般CPU利用率達到90%以上，將pid轉換為16進制，方法有很多種，我使用linux自帶python命令：hex(pid)，很方便。
4）根據轉換的16進制去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）在備機切換到線上機器前，通過jmap打印出JVM堆內存信息
jmap -dump:live,format=b,file=heap1031.bin <pid>
1212問題分析之內存泄漏
12-11日晚VRS系統又一次服務Down掉，但是當時收到反饋后并沒有及時切到備機，未能及時保留問題現場，緊急重啟后暫時恢復服務，此時距離上一次上線間隔為9D。
通過Zabbix監控來看swap內存這些天每天都在升高，最大值占用了接近4G，可服務器總內存不過才6G，初步定位肯定是Java應用內存泄漏導致。
第二天一塊討論這塊問題如何排查，內存泄漏一般通過jstack輸出的棧很難定位到問題，只能對JVM堆內存信息做分析。
這次問題也聯想到上次故障處理后，實際并沒有找到問題根本原因，想到了1031日存留過JVM堆信息heap1031.bin，然后下載到本地通過MAT(Eclipse插件)進行內存分析。也可以通過其他工具如jhat，但不如MAT直觀。
問題定位過程：
進入Eclipse：Memory analysis
選擇File—》Open Head Dump…打開heap1031.bin
會彈出一個對話框，選擇Leak Suspects Report 【自動檢測存疑的泄漏點，會報告出那些存活的對象以及這些對象沒有被gc的原因】
MAT會自動分析出內存大致情況，直方圖顯示內存占用以及Problem Suspect
通過以上會看到1635個JPEGImageReader實例沒有被釋放，可能這個是導致內存泄漏的根源，也說明跟系統裁圖功能有關，縮小了問題定位范圍。
沒有釋放資源懷疑可能是IO流沒有正常關閉導致，因JVM堆棧轉存只看到底層代碼，具體還要進一步分析程序源代碼。
下一步，點擊Details
再點擊下面的Class Name，查看Inspector【顯示了當前顯示類或對象的詳細信息】
通過Inspector能知道使用了javax.imageio.ImageReader接口，我們處理圖片的任務都在ImageResize.java類中，然后對這塊代碼進行分析排查。
最初懷疑自動截圖這塊的影響，單獨對自動截圖功能做批量測試，循環截圖100，1000次dump內存看基本都沒有太大變化。
代碼排查：
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入手查看代碼，發現調用了dispose方法，但是只在try中做了調用，finally中并沒有調用dispose方法。懷疑如果if條件不成立或者有異常發生，則不會調用dispose方法。
查看下dispose方法的含義，如果不再使用這個ImageReader對象時，必須調用這個方法釋放資源；否則，可能導致資源(內存)無限的被占用。
/** * 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() { } |
|---|
找到這個原因時很興奮，所以我們將try中的reader.dispose()代碼注釋掉，直接做截圖測試，100，1000，然后打印JVM堆棧轉存用MAT分析，印證了上面的分析結果。
然后修復這個Java類+log（不符合預期的log打印），部署上線了。
因為已知道了JPEGImageReader實例未被釋放，故可通過命令jmap -histo:live <pid> | grep ImageReader 【jmap -histo:live <pid> 分析具體的對象數目和占用內存大小】
在線上來查看JPEGImageReader instances數量變化，大概觀察1個小時左右，發現JPEGImageReader instances>5了，而且也沒有不符合條件的log輸出，正常應該釋放掉的，難道還是有內存泄漏？
然后，繼續分析代碼，根據ImageReader搜索了下整個代碼庫，發現有個PgcAuditServiceImpl.java PGC審核里也有引用的代碼。
Iterator<ImageReader> it = ImageIO.getImageReadersByFormatName(ext);
reader = it.next();
… //這里沒有調用dispose() |
|---|
這塊僅使用了ImageReader獲取width和height，之后并沒有調用dispose方法，盡快修復重新上線。
持續觀察一段時間，jmap查看類及對象情況：
[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，內部靜態類CallBackLock和State，所以有2個instances
[Lcom.sun.imageio.plugins.jpeg.JPEGImageReader$CallBackLock$State; 1個Class對象
持續觀察幾天性能指標平穩，服務器cpu、swap、load對于內存泄漏前占用都非常少了。
經過以上分析，實際本次故障罪魁禍首是在PGC審核截圖引起。香港vrs因運營沒有使用到PGC審核功能所以也不會觸發內存泄漏問題。