案例2: 某寿险公司核心系统GC开销超限问题分析

文档属性

此文档由东风微鸣编写。
未经许可，不得向个人或机构传阅或复制

修改记录

日期	作者	版本	修改记录
2016/5/9	东风微鸣	V1.0	创建文档
2017/10/30	东风微鸣	V1.1	格式调整

审阅记录

审阅人	职位

分发记录

拷贝No.	姓名	单位
1
2
3

参考文件

参考文件

概述

某寿险公司的核心系统是运行在实体机上的，实体机的性能都挺好，但是系统的性能却不尽如人意。而且之前某寿险公司的核心系统出过几次性能上的问题，但是我们总是找不到根本原因。每次都是重启完了事，也不清楚性能问题究竟对系统造成了什么样的影响。

装上Dynatrace之后，立马就有关于某寿险公司核心系统的性能告警，告警是关于GC对系统性能造成较大影响(即JVM的GC开销超过限制)，我们这才知道问题的严重性，也知道了从何下手。之后我们定位到导致系统问题的根源，一个是加载的一个用来监控应用各项参数的javamelody的jar包，另一个是因为system.gc()频繁地调用fullgc，导致系统“stop the world”时间过长。

分析过程

告警

某寿险公司核心系统安装上Dynatrace之后，立马出现如下的告警邮件：

可以清楚的看到，告警邮件上已经明确的写出了原因，并指出对性能的影响：

原因：进程XXXX_wls_hx_135a@appserver135:0的垃圾回收运行状况不正常。 由于在垃圾回收过程中花费大量执行时间，因此应用程序进程的显著挂起时间会持续一段时间。

影响： 过去的 5 分钟内，该进程用于回收垃圾的时间，总是多于其执行时间 15%。

多于其执行时间 15%！是的，直到看到这个告警，我们才意识到性能问题居然这么严重，GC所花费的时间，在某段时间内已经超过总的执行时间的15%，而且此告警很频繁。具体如下：

可以从上图看出，核心系统的大部分机器都出现了性能问题，并且很频繁，另外有时甚至在长达1、2个小时内，GC时间占用执行时间超过15%！这是很严重的性能问题。而该问题直到我们使用了Dynatrace才首次意识到。

GC问题优化

针对该问题，为了进一步分析，我们使用了Dynatrace自带的仪表图–应用程序进程图表。具体如下：

从这儿可以看出，告警的时候major gc垃圾收集时间较长，而Dynatrace的major gc就是指会导致“stop the world”的GC。

接下来我们分析了对应的GC日志，发现日志中存在大量的system.gc()，并且该每次调用都是执行full gc。关于SystemGC触发full gc的解释，我们查到的原因如下：

如果应用使用到NIO框架、DirectByteBuffer或者MappedByteBuffer等功能时，上述情况产生的内存是堆外内存，SystemGC就需要Full GC来回收

之后查看资料，发现一种具体的改进方法，具体如下：

加入参数-XX:+ExplicitGCInvokesConcurrent ，该参数并不会禁用SystemGC，SystemGC还是会被触发，只是加上该参数后，会使得system gc时执行CMS GC，效率会提高，减少因为Full GC引起的STW时间。

之后我们在其中一台上添加了该参数，添加之后与其他没有添加的做对比，利用dynatrace的自定义仪表板的功能，直接抓取“Suspension Time”(每个时间间隔中GC导致的挂起时间)这一参数做对比画出曲线图。发现加了后GC导致的暂停时间大幅下降！由于比较早，该图找不到了，附上一张使用另一个小工具分析的结论：

可以看到，加了之后GC”stop the world“时间降低了100多秒，full gc次数为0。

确认加上该参数可以改善gc性能后，我们在核心的所有jvm里都添加了改参数。加入后，除了其中一台机器还会告警，其他机器运行正常。而那台告警的机器，我们发现还有其他的问题。

javamelody

其中一台，即使加入了上边提到的参数，gc的性能还是有问题。具体如下图：

可以看到，GC暂停时间，其他jvm都是位于10ms左右的数量级，而另一台则是6000ms左右的数量级！这对应用造成了较大的影响，具体可以通过dynatrace的下图看出：

直接导致应用，具体到客户的某一请求，由于gc ”stop the world”导致响应时间大幅增加，原本100多ms就能完成的请求，直接由于gc导致的挂起多花了7000ms！

这次我们使用dynatrace自带的CPU采样热点分析和内存快照分析工具来进行分析。

• 直接通过dynatrace对该台jvm做heapdump并直接在dynatrace上进行分析，分析结果如下：下图1-4的实例都是由javamelody这个jar包产生的。

• 通过cpu采样分析，结果如下：直接看出是javamelody占用了较多cpu

作为对比，其他jvm中根本没有加载javamelody这个包。

而联系项目组，得到的答复是：

javamelody-JVM监控程序。可以用来分析具体的问题点。该jar包会定时（较频繁）采集应用的相关指定的数据，并且对数据进行打包、压缩、发送。

而javamelody的这些操作是既消耗CPU又消耗jvm内存资源。对系统的行能造成了较大的影响。而在我们的建议下，项目组拿掉了这个jar包。改用Dynatrace的仪表板和报告.

总结

通过dynatrace，我们发现了核心系统的问题，并快速的分析解决了该问题。解决问题之后，核心系统运行起来平稳而高效。从以前每天都要关注，出了问题抓耳挠腮，变成了今天的风淡云清。