世界杯前的一次线上JVM调优经历

最新推荐文章于 2024-08-19 19:51:22 发布

枫林啊

最新推荐文章于 2024-08-19 19:51:22 发布

阅读量225

点赞数 3

文章标签： jvm java 开发语言

本文链接：https://blog.csdn.net/weixin_43575663/article/details/127913154

版权

发现服务异常现象

最近查看日志，发现部分微服务出现大量接口出现响应时间大于2秒的情况在这里插入图片描述选取其中一个请求，查看链路中各服务的耗时，发现耗时还是在服务自身，并不是远程调用

在这里插入图片描述
再通过监控查看jvm的信息。发现服务使用的cms收集器，但是频繁的在进行FullGC.并且会存在上一次垃圾回收还没执行完，然后FullGC又被触发，导致并发标记清理失败的情况,也就是concurrent mode failure，导致STW并使用serial Old垃圾收集器。
在这里插入图片描述

CMS垃圾收集器及Parallel Old工作流程

在这里插入图片描述

初步分接口响应慢的原因一：

从老年代的使用比例上看，很多60%-80%左右就进行了full GC,由于CMS垃圾收集器由于浮动垃圾预留了8%的空间，但是可用率应该能达到92%，这说明是触发了老年代空间担保机制导致Full GC.

在这里插入图片描述
再查看年轻代增长速度，发现平均仅仅15秒左右就可以把年轻代装满，高峰期时甚至1秒就将年轻代装满！根据对象动态年龄判断原则，也会导致的对象频繁进入老年代的问题

在这里插入图片描述
查看survivor区使用情况，发现survivor区使用率较低

响应慢的原因二：

由于serial old收集器是单线程，并且在gc时，会完全STW,所有用户线程被阻塞，GC时，会有大量用户请求响应时间较长。

问题进一步排查

大概了解了原因，再到容器中使用arthas查看jvm的使用情况：
1.使用jps命令，查看到服务的pid为1
2.打开arthas，使用dashboard命令查看整个进程的运行情况，线程、内存、GC、运行环境信息
在这里插入图片描述
可以看到jvm的内存模型大概是这样的

根据参数可以看到，年轻代设置的也比较大。这个跟本服务的特色也很符合。
所以再看一下GC日志使用命令jstat -gc pid 1000 60(查看进程id的GC日志，每1000毫秒打印一次，共打印60次)，查看对象增长情况，在年轻代空间充足的情况下依然进行了fullGC,这很有可能是大对象直接进入老年代了
在这里插入图片描述

导出快照分析

使用命令jmap -dump:format=b,file=fileName.hprof pid
导出分析内存快照，使用MAT工具分析，内存占用主要是2个原因
在这里插入图片描述

当时第一反应是找服务中定义的类对象，发现是本地缓存对象，占据了堆空间的39%。根据配置的内容来看，缓存时间30分钟，根据本次快照计算得出这两个缓存对象共占用约550M左右的空间，这部分对象会长时间占用survivor区以及老年代空间
在这里插入图片描述
再查看代码：

于是尝试了调整缓存过期时间，以及年轻代survivor空间比例，但是依然没有效果。于是在查看线程中其他对象情况，结果一看吓一跳，仅一个bytes和char[]对象就占用了654M的内存！

在这里插入图片描述
这应该就是频繁进入老年代的大对象了！于是根据堆栈信息找到代码。

该代码是引用的一个公共包，主要是上报本地缓存占用内存大小的指标。本地调试打断点看到该代码将本地所有缓存的内容拼接成了一个字符串，再转为byte[]。
问题分析：
1.该代码主要是本地缓存大小指标上报，若本地缓存内容较多时，cache.asMap()会拼接成一个巨大的StringBuilder对象，占用很大jvm年轻代内存空间。并且拼接耗时较长，一次年轻代GC可能无法回收，survivor空间也放不下，所以该对象会被直接放入老年代。
2.StringBuilder对象转为String对象和byte[]对象时，属于大对象，这两个对象也会直接放入老年代。这样也导致每次放入老年代的对象空间较大，老年代空间担保机制就很容易触发导致FullGC。
3.该指标上报频率大概10s一次，这也会频繁的导致Minor GC以及full GC。