记一次微服务耗时毛刺排查

待我称王封你为后i 2023-02-15 05:01 156阅读 0赞

点击蓝字关注这个神奇的公众号～

![format_png][]

![format_png 1][]

前段时间的某天，注意到一个服务的平均耗时出现了如下图的毛刺现象。

![format_png 2][]

注意到毛刺出现极其规律，每30分钟出现一个毛刺。考虑到这种规律性，并结合服务的流量较小（20 QPS）推测，可能是某个定时请求的接口进行了耗时操作，由于流量较小放大了平均耗时，继而出现了毛刺。但排查主调调用的接口，并没有发现定时的调用，从而否定了这种可能性。

排除服务外部的原因导致的毛刺，那么只剩下服务内部的原因了。该服务为JAVA应用，考虑到服务GC会导致应用暂停，使外部请求耗时异常增长；但是，并不能解释如此规律的毛刺。抱着“死马当活马医”的想法，使用如下命令

jstat -gc pid 3000

查看了服务的GC情况，结果有了意外发现：产生毛刺时发生了多次GC，GC情况如下图：

![format_png 3][]

分析数据，得知产生一个毛刺时Young GC进行了237-231=6次，Full GC进行了303-294=9次，Full GC的时间664-641=23秒，可知，正是由于GC停顿了20多秒，从而使得平均耗时显著提高。得益于良好的运维，服务启动时加入了如下参数：

-XX:+UseConcMarkSweepGC -Xloggc:jvm.log -verbosegc -XX:+PrintGCDetails
        -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps

![format_png 4][]

注意到GC时发生了两次失败：`Promotion Failed`和`Concurrent mode Failuer`，分别是进程停顿6.8s和5s。截图中省去了部分日志，实际之后还发生了两次`Concurrent mode Failuer`从而使进程暂停20多秒。

那为什么连GC都如此有规律的每30分钟进行呢？再次排查代码，发现了如下类似的代码：

public static void refresh() {
            ConcurrentHashMap<String, Integer> newCache = DBUtil.getCache();
            cache = newCache;
            log.info("refresh cache, size:" + newCache.size());
        }

该服务是一个缓存服务，将数据库中的数据读取到内存，然后提供接口查询。由于数据库中的数据会更新，所以需要固定时间（每30分钟）从数据库重新读取数据，刷新缓存。查询数据库中的数据，发现已经有接近500万行的数据。当加载这部分数据到内存时，内存需求暴涨，JVM进行了多次耗时的GC，导致进程暂停，从而使得请求耗时出现毛刺。

找到了问题出现的原因，开始着手进行优化。由于主要是GC问题，故尝试不修改业务代码，直接修改JVM参数的方式进行优化。在优化之前，需要弄明白`Promotion Failed`和`Concurrent mode Failuer`的原因。

晋升失败`Promotion Failed`的原因主要有：

*  Survivor区空间不足，Survivor中的对象还不足以晋升到老年代，从年轻代晋升到Survivor的对象大于了Survivor剩余的空间。
 *  从年轻代直接晋升到老年代的对象大于老年代剩余的空间。

由于本例中的对象是突然暴涨的，所以可确定原因为后者，所以需要增大老年代的空间。

并发模式失败`Concurrent mode Failuer`的原因是：CMS GC回收对象的速度赶不上用户申请对象的速度。当发生并发模式失败后，CMS GC会退回到Serial Old GC使用串行回收，从而使得CMS GC不能发挥作用。解决该问题的方法有：

*  尽早进行CMS GC即调低`-XX:CMSInitiatingOccupancyFraction`参数，默认为68
 *  增大老年代空间

由此，将JVM参数由之前的：

-Xmx2048m -Xms2048m -XX:NewSize=768m -XX:MaxNewSize=768m

调整为：

-Xmx3072m -Xms3072m -XX:NewSize=1536m -XX:MaxNewSize=1536m

增大新生代的初衷是为了直接容纳下服务刷新时的临时对象，不需要晋升到老年代。观察原来的老年代大约需要700M所以没有进行大的扩容。修改后的效果如下：

![format_png 5][]

高峰耗时减少一半，但依然存在毛刺。查看GC日志，依然存在一次`concurrent mode failure`。  
继续调整参数，增大老年代：

-Xmx4096m -Xms4096m -XX:NewSize=1024m -XX:MaxNewSize=1024m

整个堆内存从2G扩容到4G，老年代从1.25G扩容到3G，内存已经较为充足。调整后，耗时大幅降低，也没有出现`concurrent mode failure`，但依然没有消除毛刺现象，效果图如下：

![format_png 6][]

再次查看GC日志，发现耗时主要集中在年轻代回收：

![format_png 7][]

尝试使用`UseParallelOldGC`加快年轻代回收，但是年老代耗时过长。不能同时使用`Parallel Scavenge`回收年轻代，`CMS`回收年老代真是大坑。最后更换为`G1 GC`大大减少了Full GC，毛刺抖动得到大大缓解，效果如下：

![format_png 8][]

历

[漫谈从零访问量到每秒千万访问量的架构设计][Link 1]

史

[谷歌开源内部代码评审规范][Link 2]

文

[UML (统一建模语言) 各种图总结][UML _]

章

[真实项目案例实战—【状态设计模式】使用场景][Link 3]

![format_png 9][]

欢迎分享转发，有帮助的话点个“在看”

![format_png 10][]

![format_png 11][]点我查看原文

[format_png]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2dpZi9jWmtJOE0wbmJDbDRLQ0ZoVEdIaWNZcFBxVUFvNTRzaWNzdkMwSkdlNHlPZTdBODB0VjA1N2NnWW5sVGlhb3NVWW9uZ2JWcUJCOGJZa25WYlRZNVl5Ykd2QS82NDA?x-oss-process=image/format,png
[format_png 1]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2pwZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTGF0Yk5GdG9NTE5PSldXTHY2Y1Q4UkZpYnRoSWo0WTN5b29EUmhXZ054SW9Xa3lUako4RHlMelEvNjQw?x-oss-process=image/format,png
[format_png 2]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTEJVcHh4clVhVzVITTR4Q01yMU1VdzFWMlo3V3ZTR2pvVFBpY3ZiSk1VQUpGV040VFVJczhnb0EvNjQw?x-oss-process=image/format,png
[format_png 3]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTFAzU2E2QVF1dWEyTXVsN1FsdjdKZnh5eTEzWVVocTdlMU1XbTlZSjVTRE0yS2FTaWFJb0RzUFEvNjQw?x-oss-process=image/format,png
[format_png 4]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTDMxMk1iR0pnWkJkVHhsUFRlS1RwSlBZRlJUTHlFOTBLcFJPTVBQRW1jYVdUdEg3UW8zbmEwZy82NDA?x-oss-process=image/format,png
[format_png 5]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTGlhcHYyaWFuS2RpYmFwMmQzUU90RDBIenBORGcxMW80dlRGaWFnM0RpYlhGWG9DT0lSa3ZocExCcEJRLzY0MA?x-oss-process=image/format,png
[format_png 6]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTDVENVQycmFVS3oyQm9ldW5VaDkxbXRMaWNQbm91SGdiaWJqeGdnTDBPUkZBQXo0UjBCeGliNUw0QS82NDA?x-oss-process=image/format,png
[format_png 7]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTHU3dHFXVjB1ZzBHVjRhaWIxblVVMmJIYUk3MHZaYmZEdmliaENaOUpFYzN1WmJpYWs3bkRrWU44Zy82NDA?x-oss-process=image/format,png
[format_png 8]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnNDcjEyNGp5b0xrcVZVQkFpYzZwT2ljTFlRY1FGa2libVZSMHpCMTZlSDZ1YUlWczJmOFo2cVp2aWFXOWxWVGljaWNyYnhpYVNrNnZXNGlhQXQ3Zy82NDA?x-oss-process=image/format,png
[Link 1]: http://mp.weixin.qq.com/s?__biz=MzU2NDc4MjE2Ng%3D%3D&chksm=fc44f147cb33785123bff5c6f6f650b38c38bcee1dfeb6a1d4e18b5851b471aec22ac710523d&idx=1&mid=2247484542&scene=21&sn=b9ab61170044c570f6518679c230f66d#wechat_redirect
[Link 2]: http://mp.weixin.qq.com/s?__biz=MzU2NDc4MjE2Ng%3D%3D&chksm=fc44f15ecb33784854fc184993c392fd4f70efeca8b0dc6c6dec1931d24618aeaec55d2c2b7a&idx=1&mid=2247484519&scene=21&sn=590b31dc01b686121cd58e0902c1d653#wechat_redirect
[UML _]: http://mp.weixin.qq.com/s?__biz=MzU2NDc4MjE2Ng%3D%3D&chksm=fc44f173cb3378655798101119d93481d362fec85327b350e649f9109e47f0b9251ad64cb3fa&idx=1&mid=2247484490&scene=21&sn=f7e915b47cd26bee0251e9bd484e7597#wechat_redirect
[Link 3]: http://mp.weixin.qq.com/s?__biz=MzU2NDc4MjE2Ng%3D%3D&chksm=fc44f114cb33780214285c7efd4a5295f3f4c9b882d18a63ec11252d443a7c2fdb575f550f40&idx=1&mid=2247484461&scene=21&sn=eca9b30d7ecd25ba72bf61177b0a0d8c#wechat_redirect
[format_png 9]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy94aWNXWVRTSUN6UnZ6aGRLck1pY1NQSWliZzhQRWJPa2E4bmpjOHJFZmFLa09YTHAyd21wckxpY0JRaWNYMWlhdVFzWEdTTDlpYXhreFZTb3RQQ2F2U2hva1NvVHcvNjQw?x-oss-process=image/format,png
[format_png 10]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2dpZi94aWNXWVRTSUN6UnNKRmliZXRqdzJEblVBaG1VQkdrRWF0QXZlMkYxMEtuQjlTVnZzd01lRGxMVzUyY1d3RWljTmoyRU84bG9YQTZMcEhRbTQ5NFdCZUt1US82NDA?x-oss-process=image/format,png
[format_png 11]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2dpZi9iOTZDaWJDdDcwaWFhVHVDS1EwR1daaWNhMWJDYmNhb2dkM29HZ01PRFVVNDVwNDZXOG52cmljVWlhM1dRaWJYZ2RlU1gxTXFBb2liS2hTaDltdkR5d1RYODdpY2lhdy82NDA?x-oss-process=image/format,png