JVM调优实战—接口成功率下降排查与优化

xu_jiang_hua

已于 2024-12-01 22:41:37 修改

阅读量889

点赞数 10

分类专栏： jvm 性能优化文章标签： jvm

于 2024-12-01 22:38:58 首次发布

本文链接：https://blog.youkuaiyun.com/weixin_47095883/article/details/144176513

版权

性能优化同时被 2 个专栏收录

3 篇文章

订阅专栏

jvm

1 篇文章

订阅专栏

一、告警通知

在某个上午收到接口成功率下降的告警通知，本着生产优先的原则立马分析：
file

二、锁定慢服务

通过告警信息可以看到监控告警来源于网关，于是登录网关查看日志，发现多条与queryProudct接口相关的日志，因此提取一条日志，具体详情如下所示：

file

可以看到网关收到请求到响应请求耗时为3.003秒，网关向微服务发起请求到收到响应为3.002秒，因此基本可以排除是网关积压导致，根据找到的traceId到微服务中找到的日志如下：

file

先介绍一下LogFilter，服务中接口通过dubbo框架向外暴露rest协议，外部通过http向服务发起请求。LogFilter实现Dubbo中Filter接口，通过SPI机制让Dubbo启动时加载LogFilter，通过order将LogFilter设置成首个执行Filter，在里面打印接口请求出入参及耗时。

从LogFilter可以看到服务收到请求、处理请求到响应请求耗时仅为17ms。将dubbo与网关之间的传输耗时纳入考虑（考虑传输的包体大小，假设网络传输耗时为20ms），但整体37ms还是与3.002s相差甚远，时间消耗在哪儿了?

从以上基本可以排除是网关积压导致。

三、问题排查

1、服务接口流量

检查服务中queryProduct及其他高流量接口，并未发现流量有突变。

2、kafka流量

Kafka消费在09:55有个上升突变到10点达到顶峰，持续到11:15开始下降，11:30时基本触底，因此基本可以排除是kafka消息量突变引起。结合接口流量和kafka消息量，基本可以排除是突增流量导致。
file

3、响应包体大小

根据网关日志提取服务最近访问接口量及包体大小（最后一列为包体大小，单位为byte），未发现包体特别大的响应，此处基本锁定接口慢就是微服务引起，与包体大小无关。

4、http线程

file
可以看到11:30时http线程数存在尖刺，有个陡增，怀疑是服务变慢或暂停导致长时间无法响应请求，需要创建新的线程处理新请求，因此需要查看gc监控。

5、gc监控及日志

file
file
file
服务使用jdk版本为1.8，垃圾回收器用的G1，从日志可以看到进行young gc耗时为8.1秒。根据JVM知识可知年轻代回收会暂停服务（STW），因此锁定接口超时是因young gc长时间暂停造成，找到问题后接下来分析为什么会出现长暂停。

四、问题分析

由G1知识可知在进行young gc时，根据三色标记法会将Eden和So区域中的存活对象复制到S1时，如果S1不够，将会由老年代空间进行担保。日志中出现to-space exhausted、Evaciation Failure等关键字可以看出此次回收中，将Eden和So存活对象复制到S1时，S1空间不够，由担保机制会将存活对象转移到老年代时，老年代空间同样不足，因此出现转移失败（Evaciation Failure）。因老年代不足g1将会增加老年代空间，然后将存活对象转移到老年代，对象复制耗时比较长（Object Copy耗时7s）。

gc前：
老年代已使用量：5395-3672-14=1709
最大的老年代：6144-3672-14=2458
老年代剩余使用空间为：2458-1709=749

gc后：
老年代已使用量：4429-0-462=3967
最大的老年代：6144-624-462=5058

gc前后老年代增量：
老年代增量：3967-1709= 2258>749

可以看出就是因老年代空间不足导致担保失败。

五、优化jvm参数

老年代内存担保失败，因此将-XX:InitiatingHeapOccupancyPercent从45%调到40%，尽早启动mixedGc，尽早回收老年代内存（G1年轻代和老年代都是copy对象，因此回收年轻代、老年代成本差不多）；
G1内部有很多自适应机制，自适应动态调整年轻代比例（最小和最大比例默认值如下：-XX:G1NewSizePercent=5 -XX:G1MaxNewSizePercent=60），将年轻代比例大小适当降低，调整为50%。jdk1.8中此参数为实验参数，因此需要打开 -XX:+UnlockExperimentalVMOptions；

优化后的JVM参数为：
-server -Xmx6g -Xms6g -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -Xss256k -XX:+DisableExplicitGC -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseG1GC -XX:MaxGCPauseMills=200 -XX:max-XX:+UseStringDeduplication -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/app/deploy/logs/heapDump.hprof -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M -Xloggc:/app/deploy/logs/gc-log.log -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:InitiatingHeapOccupancyPercent=35 -XX:G1MaxNewSizePercent=50 -XX:+PrintHeapAtGC