JAVA應用CPU佔用100%|內存泄漏分析總結

問題現象

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審覈功能因此也不會觸發內存泄漏問題。

 

服務器性能指標先後變化狀況：

內存泄漏時內存使用狀況：

解決後內存使用狀況：

內存泄漏時CPU使用狀況：

解決後CPU使用狀況：

 

內存泄漏時Load性能：

解決後Load性能：

 

總結

1）Java應用中的CPU 100%、內存泄漏兩種排錯方式以及具體命令，工具使用上面都已作了說明，可作參考。

2）關注新的監控系統falcon將這些重要服務器性能指標加上監控，超過閾值告警。

3）系統功能上線後，有意識的對服務器性能指標巡邏或許能提早發現異常並提前解決。

4）更多詳細MAT使用，網上大量文章可參閱。

5）建議使用Apache Commons Imaging替代Java自身的裁圖功能，能夠避免顯示調用dispose釋放資源等問題。