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释放资源等问题。