故障藐视
接到通知说线上图表的导出功能异常,导出功能是做成服务单独运行的,上面还有定时人任务在跑,上服务器看了下运行日志,日志内功还在更新定时任务的运行日志,只是更新的特别慢,这并不是第一次出现这种情况,重启服务可以解决,但是同样的问题不定时的又会重新出现,这可忍不了。使用top命令查看服务器情况,这个服务所属的进程占用cpu达到了400%多!
通过PID号找到对应的进程名及所在目录,看看出问题的是哪个服务进程
最简单的方法是直接进入pid目录查看,输入命令cd /proc/30219
,可以很直观的看到服务启动目录,如下图
初步结果判定
上图可以看到PID为30279的进程占用CPU非常高,这时候我首先就要看看这个进程JVM的gc情况
jstat -gc 30279 5000
下面是对上图中各列的解释
S0C:年轻代中第一个survivor(幸存区)的容量 (字节)
S1C:年轻代中第二个survivor(幸存区)的容量 (字节)
S0U:年轻代中第一个survivor(幸存区)目前已使用空间 (字节)
S1U:年轻代中第二个survivor(幸存区)目前已使用空间 (字节)
EC:年轻代中Eden(伊甸园)的容量 (字节)
EU:年轻代中Eden(伊甸园)目前已使用空间 (字节)
OC:Old代的容量 (字节)
OU:Old代目前已使用空间 (字节)
PC:Perm(持久代)的容量 (字节)
PU:Perm(持久代)目前已使用空间 (字节)
YGC:从应用程序启动到采样时年轻代中gc次数
YGCT:从应用程序启动到采样时年轻代中gc所用时间(s)
FGC:从应用程序启动到采样时old代(full gc)gc次数
FGCT:从应用程序启动到采样时old代(full gc)gc所用时间(s)
GCT:从应用程序启动到采样时gc用的总时间(s)
可以看到老年代的空间十分正常,可是持久代(红框1)的容量已经沾满了,并且不再扩容,想必是已经达到了最大容量,红框2处显示Full GC的次数已经达到了两万多次,并且还在不断增长,但是并没有起到什么作用。
到这里问题就确定了,导致这次服务卡慢的原因是持久代(Perm)溢出导致gc持续运行,持久代的最大空间83968k换算下来也只有82m,解决办法是在启动服务时增大持久代的空间
-XX:PermSize=250m -XX:MaxPermSize=512m
进一步原因探究
上面已经确定了是永久代溢出导致的问题,但是这只是结果,到现在还不知道造成永久代内存溢出的具体原因,如果完全是因为永久代设置过小,承受不了程序日常运行所需开销,那增大永久代空间就可以解决问题,可如果是程序代码本身存在漏洞,那光加大内存也是治标不治本。
根据问题进程id定位问题线程
命令:top -Hp 30279
红框部分的线程全是问题线程,先记录下这些线程的PID,挨个将其转换为16进制
命令:printf "%x\n" 30290 30282 30283 30284 30285 30286 30287 30288 30289
打印问题进程堆栈信息
为方便查看,将堆栈信息答应到文件,每隔5秒打印一份
命令:jstack 30279 > jstack.dump
分析堆栈信息
随便打开一个一个jstack.dump文件,在其中查找刚才转化的十六进制线程id,查找内容如下
印证了开始的判断,全是GC线程。
然后向上翻找,查找与项目有关的代码,分析五个堆栈文件,找到如下堆栈信息
这段代码是系统系统的一个报表导出功能,业务十分复杂,关联资源很多,于是到这里判断是这个导出所需内存资源过大,同时系统永久代内存又过小,多用户同时导出报表就可能撑爆持久代。
到这里,本次线上问题排查就算结束了,并不是程序代码的问题,是项目永久代空间设置过小,不能满足项目所有功能的长时间运行。
额外分享
这里也再记录一次早前项目卡死问题的堆栈问题信息记录,如下
定位到的项目代码如下:
没看错,就是代码在try catch 捕获异常输出的时候采用了e.printStackTrance()进行输出,e.printStackTrance()会将异常堆栈信息存到字符串内存空间中,堆栈信息一旦过长,就很可能导致内存溢出。一般只在测试阶段才使用该方法打印到控制台,上线后就应该使用log对象将错误信息输出到日志文件里去。
在这里分享一篇文章,解释为什么e.printStackTrance()会导致程序锁死:https://blog.csdn.net/hy_coming/article/details/88523988
总结
关注系统运行时的资源需求,分配合适的资源。
避免在上线的项目中出现e.printStackTrance()这样的代码,这可能是刚入门学习时养成的习惯,但是不好的习惯得改!同时在使用其他可能会产生大量字符串的方法时,都得特别注意。