性能文章>记一次接口耗时异常排查过程>

记一次接口耗时异常排查过程原创

259329

1现象

某后端系统,处于整个调用链路偏后的位置,对接口性能有着比较严格的要求。因此对外承诺的三个9响应时间为200多毫秒。

然而,从某天开始,一到上午流量高峰,服务耗时就报警,随机的从集群内的某些机器上报了出来,过了流量高峰就好很多。。。

2问题排查

一般的,排查接口耗时,基本都习惯从外部流量,和各内部接口、逻辑块耗时,底层存储耗时等接口层面来观察。如果能在接口层面就找到了瓶颈,是最理想的情况。否则,就要从JVM层面来排查,比如线程运行异常、GC异常等,势必要耗费更多的精力了。

2.1 服务器性能、流量分配等外在因素

虽然这类问题发生的概率比较小,但是看到几十台机器中,只有几台在报,感觉还是有必要排查一下。

  • 服务器差异?云服务器相较物理机,性能还是有很大差距,然而,摘掉报警机器后,报警又出现在了其他机器,那应该不是服务器的问题了。
  • 单机承载的流量不均衡?RPC路由策略默认加权轮询,但是在不设置权重属性的情况下,权重一样就蜕变成普通轮询。而且,看单机QPS,也基本一致,因此,这个原因也排除了。

2.2 是不是有业务重逻辑导致耗时增加

交互框架本身的限制:大型服务调用,基本都采用异步响应式调用方式,相比同步调用可以更好的利用资源。然而,异步响应式调用虽然节省了等待资源,但是也需要分出响应资源进行结果接收和返回,这里如果线程资源设置不合理,很有可能造成响应式阻塞。

Future异步调用

然而,服务响应资源还算充足,没有发现拒绝,排队等异常日志,排除。

业务逻辑本身的耗时:做业务开发的兄弟,应该都有感触,有的业务逻辑那是真的复杂,如果其中还涉及外部调用,那绝对是妥妥的耗时大户。流量小的时候还好,随着流量范围的扩大,影响就会非常凸显了。

好巧,正好有一个业务刚做了运营动作,于是,我们梳理了该业务场景涉及的执行链路,发现某个排序操作非常耗时,赶紧分析优化并上线。

以为发现了事情的真相然而,并无卵用,报警短信第二天又按时上班了~

2.3 是不是代码出了性能bug

既然不是流量问题,那就要从服务本身来看了。

在JVM层面,可能造成服务耗时增加的最大可能,一是异常GC,二是线程资源阻塞或竞争。比较容易的应该是GC问题,因为有现成的日志和监控可循,优先怀疑GC的原因。先来整理一下有哪些方面可能导致GC:

YGC耗时异常场景汇总:

  • GCRoot对象的扫描和标记时间异常
  • 存活对象的copy次数过多导致的耗时
  • 等待各线程到达安全点的时间过长
  • GC日志IO阻塞导致GC总耗时过长
  • 存在swap行为

FGC耗时异常场景汇总

  • 对象过早进入老年代
  • 元空间不足、分配担保等场景
  • 内存泄漏

诸多猜想

从上述罗列的可能性,其实会有很多猜想:

  • 有没有可能是参数设置不合理,在大流量下无法更好的适配服务;
  • FGC是因为老年代没有空闲空间,会不会是年轻代大小设置不合理,导致对象提前晋升;
  • 如果年轻代空间充足,又是什么原因造成老年代占比快速上升,是有泄漏么?

2.4 问题分析

系统JVM监控异常

  • 内存占用达到80%、甚至90或更高,直观感觉有点多了,但是拉长时间看,平时也是70%多,想到业务本身有很多的缓存项,如城市、商圈、地域类目等等,内容占用多也就暂时忽略了。
  • 在接口异常的时间点常伴随FGC的发生。
日常的内存占用

GC日志分析

2022-01-06T11:12:46.035+0800: 52873.818: [Full GC (Allocation Failure)  4511M->4419M(10G), 11.3422935 secs]
   [Eden: 8192.0K(4496.0M)->0.0B(4624.0M) Survivors: 64.0M->0.0B Heap: 4511.4M(10.0G)->4419.4M(10.0G)], [Metaspace: 308300K->308289K(1310720K)]
 [Times: user=14.09 sys=0.00, real=11.34 secs]
2022-01-06T11:12:57.378+0800: 52885.160: [Full GC (Allocation Failure)  4419M->4419M(10G), 11.3581878 secs]
   [Eden: 0.0B(4624.0M)->0.0B(4624.0M) Survivors: 0.0B->0.0B Heap: 4419.4M(10.0G)->4419.4M(10.0G)], [Metaspace: 308289K->308237K(1310720K)]
 [Times: user=14.17 sys=0.00, real=11.36 secs]

看日志,只能看到现象是发生了连续两次FGC,第一次堆有减少,第二次几乎没有什么效果;另外,看时间userreal稍有点问题,按理说,FGC也是多线程并行的,real应该要小不少,但现在没有少很多。

JVM参数分析

当时的VM参数如下:

-XX:+UseG1GC -Xmx10g -Xms10g 
-XX:ParallelGCThreads=16 -XX:ConcGCThreads=8 -XX:GCTimeRatio=39 
-XX:G1HeapRegionSize=8m -XX:MetaspaceSize=512M -XX:MaxMetaspaceSize=1024M 
-XX:MaxGCPauseMillis=40 -XX:G1RSetUpdatingPauseTimePercent=40 
-XX:MaxTenuringThreshold=15 -XX:InitiatingHeapOccupancyPercent=70 -XX:-UseBiasedLocking

16核16G的机器规格,设置了10G的堆大小,16个并行GC线程,8个并发线程,GC耗时占比2.5%,期望最大停顿时间40ms,禁用偏向锁。单看参数本身,可以发现一些问题:

  • 几个时间占比参数都要比默认值要大一些,主要是出于内存较大需要充分回收和更新缓存的同时要保证整体服务响应时间的考虑,比如 GCTimeRatioG1RSetUpdatingPauseTimePercent 。从合理性和历史运行数据来看,问题不大。
  • 并行线程数设置的有点大了,按JVM的官方建议,如果CPU<=8 ,则设置为cpu数,否则设置为 8+((16-8)*5)/8 。这里和上面的FGC时间 real时间么有小很多的现象大概率是对上了。
  • 没有设置年轻代的大小。那会不会是年轻代太小了,导致对象快速晋升呢

尝试调整参数

啥也别说了,反正报了好几天了,先调调参数看下,于是:

-XX:+UseG1GC -Xmx10g -Xms10g -Xmn6g
-XX:ParallelGCThreads=10 

如上,主要增加了年轻代大小设置,减小了并行线程数。为的是让Young区尽量大,存放更多代的存活对象。然而,表现更差了,youngGC时间不受控,FGC也没减少,耗时倒是稍微好一点。

为啥呢?主要是因为G1的GC时间预估功能,会动态的调整Young区的大小,而现在Young区固定,导致了GC耗时控制失效。

所以,原因应该不是新生对象的快速晋升导致的了。

其他可能性分析

回看JVM监控,发现老年代有很大一部分根本GC不掉。

老年代内存监控

再看发生问题时的GC日志,发现之前的GC日志查看有所遗漏:

2022-01-06T11:12:46.004+0800: 52873.787: [GC concurrent-root-region-scan-start]
2022-01-06T11:12:46.007+0800: 52873.790: [GC pause (G1 Humongous Allocation) (young)
2022-01-06T11:12:46.017+0800: 52873.799: [GC concurrent-root-region-scan-end, 0.0121935 secs]
2022-01-06T11:12:46.017+0800: 52873.799: [GC concurrent-mark-start], 0.0249766 secs]
   [Root Region Scan Waiting: 9.6 ms]
   [Parallel Time: 13.6 ms, GC Workers: 10]
   ...

看到了G1 Humongous Allocation ,是大对象分配。我们的region块设置的是8M,感觉不小了,但还有大对象。啥对象能占超过8M的内存呢?

查看内存占用大的对象

这个Object是什么鬼,如果是基本数据类型占这么多我觉得还能理解,但Object不太正常哇。杀手锏,来dump一下吧。

结果,悲剧了,10G的内存,发生异常时最多占比有90多,本地MAT根本打不开,就算修改了MAT的最大最小内存也不行,要不是扫描的数据只有几百M,要么是直接卡死。

没办法,只能单独申请了一台超大内存的linux服务器,安装MAT进行处理,然后再将结果文件导出到本地用浏览器分析。

Dump文件分析

Are you joking me ? 谁能帮数下,这是多少个对象。

问题很显然了,内存泄漏。剩下的就是找对应的操作这个对象的代码了。

最后原来是因为在代码中设置了静态集合存储业务规则,又因为配置问题,触发了代码隐藏的异常,流量每次命中该规则时,就会将全量名单再次添加一次到集合列表,导致列表一再扩容,直到内存达到阈值。

有同学可能会问,为啥没有OOM呢?嗯,问的好,你猜....

3总结

因为配错了配置,触发了代码的隐藏BUG,造成了大量的配置项被重复多次添加到了静态变量,导致内存分配不足,触发FGC,导致服务耗时;流量大时,命中规则的次数大,导致内存增长快,流量小时,内存增长慢,这也就解释了为啥总是上午高峰期报,不过也给问题排查带来了不便,需要抓住上午的短暂异常时间来保存现场(关乎收入的服务,有问题得马上恢复)。也是因为规则的原因,命中的不那么多,不然可能早就OOM了,那样的话,可能就直接DUMP内存,不会这样来回来去的猜了。

归根结底一句话,出现了突发的系统异常,去找近期的代码改动和配置改动。一般没跑。

另外,关于ParallelGCThreads的那个计算公式,个人猜测,由于G1为大内存场景设计,在GC时,会有诸多关联操作,如更新RS缓存、计算region价值得分、运行时间预估算法等等,8个线程可能正好把这些任务分个差不多,因此,当少于8核时,每个核都要参与,而大于8核时,增加一些辅助线程来参与,但线程过多又有可能造成资源抢占、上下文切换等开销(如果有哪位同学知晓内在原理,还望不吝赐教)。

 


换了设计感满满的新头像,继续原创之路,迎关注我的公众号“Coder的技术之路”,欢迎转发分享,原创技术文章第一时间推送。

分类:标签:
请先登录,查看2条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
JVM源码分析之String.intern()导致的YGC不断变长
概述之所以想写这篇文章,是因为YGC过程对我们来说太过于黑盒,如果对YGC过程不是很熟悉,这类问题基本很难定位,我们就算开了GC日志,也最多能看到类似下面的日志`[GC (Allocation Fai
全面对比5大GC的内存伸缩能力(译)
在软件开发中,很明显,与大型应用程序相比,小而灵活的微服务可以提供更多的优势。而 JDK9 的 Jigsaw 更加有助于分解我们的 Java 应用程序,从而构建更适合云原生的应用程序和微服务。而随着服
译:谁是 JDK8 中最快的 GC
我们都知道 OpenJDK8 有好几个垃圾回收算法,比如 ParallelGC,CMS,还有 G1,那么哪个才是最快的?如果 GC 算法从 Java8 中默认的 ParallelGC 切换到 G1 会
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
9
2