问题现象
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审核功能所以也不会触发内存泄漏问题。