上一篇介绍了性能问题分析的诊断的基本过程,还没看过的可以先看下【性能测试】常见的性能问题分析思路-道与术,精炼总结下来就是,当遇到性能问题的时候,首先分析现场,然后根据现象去查找对应的可能原因,在通过对应的方法和工具去定位问题。
本篇来给出个具体实际工作中的案例,以及会简单说一下一种性能分析工具的使用技巧,加深这方面的认知和学习。
案例分析
背景
对某个项目(内部项目脱敏)进行压测的时候出现了内存泄漏的问题,经过发现问题-分析现象和过程-定位问题,排查出根因是定时任务引发的内存泄漏,因此把整个分析过程分享出来,做个类型性能缺陷的参考,也作为分析过程的一个实际操作案例。
问题现象
计税某接口/finance-xxxxx-center/xxxxx/incomeCalculate接口,压测过程中,通过监控发现,服务器的CPU每隔一段时间有规律波动,内存由60%上涨至85%,更奇怪的是当停止压测后,CPU依旧有规律的尖刺波动,服务器内存占用率一直居高在85%没有回收。
分析过程
从上述CPU占用图上看,一开始的思路是以为MQ消息消费导致的,去阿里云观察MQ消费情况。
从两个方面验证:第一让研发去review代码,是不是有定时任务在执行检查执行频率,第二,我通过打印CPU尖刺时间段线程dump,查看尖刺时CPU占用的线程,定位到引起CPU尖刺的就是定时任务线程和GC回收线程。
到这里之后还有一个点需要分析,那就是服务器的内存为什么会持续上升?上升之后为什么没回收?需要确认内存这个现象是不是导致CPU尖刺的定时任务引起。
首先,去应用服务器上看了GC情况,发现没有尖刺的时候YGC几乎没有,但是当CPU尖刺时间段,就有频繁的YGC,除了单次GC时间730ms不正常,其他的算正常。
所以需要进一步找内存上涨,内存不释放原因。
打印压测停止后存活对象的内存堆dump,通过mat工具分析。
从工具上看有三处疑似内存泄漏,主要关注suspect1,通过GCroot分析。
进一步确认是quartz引起的 对象不释放。
接下来,我们验证猜想,定时任务5分钟执行一次,而且执行完一次可能不只5分钟。
分两步走,第一去看服务器日志,当出现CPU尖刺的时候,观察job跑批的时间,发现单次job启动后,由于数据量大,在5分钟之内无法跑完,日志一直刷,出现任务浪打浪现象
到这里基本可以确定是定时任务造成的,那个数量是太大了,一次性捞出来的数据太多导致5分钟之内执行不完任务,然后5分钟后job又重新启动,形成job日志一直在刷,然后对象的引用无法清除,导致大对象占用内存不能释放。
接下来我们在通过再次压测验证,修改定时任务频率为1个小时,重启服务器,继续压测计税接口,发现CPU没有尖刺出现,内存也没有明显上升,然后把定时任务频率再改回5分钟,发现跑任务的时候,内存又继续上去了,而且一直维持在85%的高位,到此验证完毕。
ARTHAS
本工具是阿里开源的Java诊断工具,很多研发和性能分析同学使用,是一把通过探测系统深度问题的利器。由于本篇不是讲解此工具,安装,使用的就略了,敢兴趣的参考Arthas(阿尔萨斯)吧[参考-1],这里给一些交互截图和在性能测试问题分享一些使用技巧
如了解系统状态信息
如查看Profiler/FlameGraph/火焰图
性能分析案例一些使用方法技巧
先用thread -n 10 找出线程堆栈中程序运行的类与方法
Thread –b 检测是否有线程锁
接着sc -d com.poizon.infr.user.core.service.util.HttpUtil.doHttpPost,查找类
然后 sm -d com.poizon.infr.user.core.service.util.HttpUtil包下的方法
再然后trace com.poizon.infr.user.core.service.util.HttpUtil doHttpPost '#cost > 10'方法耗时
trace com.poizon.infr.user.core.service.controller.UnionLoginController unionLogin '#cost > 50' -n 3
jad --source-only com.poizon.infr.user.core.service.util.HttpUtil.doHttpPost ,反编译出怀疑的源代码进行分析
profiler -e cpu -d 300 --format svg start 火焰图
【注解&参考】
[参考-1] https://arthas.aliyun.com/doc/
原稿分享:禧子
优化编辑:大奇