image.png
从图中可以看到,GC暂停时间的峰值达到了 546ms
客户表示这种情况必须解决,因为服务调用的超时时间为1秒,要求最大GC暂停时间 不超过200ms,平均暂停时间达到100ms以内,对客户的交易策略产生了极大的影 响。

CPU负载

从图中可以看到:系统负载为 4.92 , CPU使用率 7% 左右,其实这个图中隐含了一 22.6.2 CPU负载 些重要的线索,但我们此时并没有发现什么问题。

GC内存使用情况

old_gen 使用量大幅下跌,确实是发生了 FullGC 。 但 09:20 前后,老年代空间的使用量在缓慢上升,并没有下降,也就是说引发最大暂 停时间的这个点并没有发生FullGC。
我们使用的是JDK8,启动参数中没有指定GC,确定这个服务使用了默认的并行垃圾 收集器。 于是怀疑问题出在这款垃圾收集器上面,因为很多情况下 ParallelGC 为了最大的 系统处理能力,即吞吐量,而牺牲掉了单次的暂停时间,导致暂停时间会比较长

使用G1垃圾收集器

看看暂停时间,每个节点的GC暂停时间都降下来了,基本上在50ms以内,比较符合 我们的预期。

“彩蛋”惊喜

中奖了,运行一段时间后,最大GC暂停时间达到了 1300ms 。
于是想了个办法,通过JMX注册GC事件监听,把相关的信息直接打印出来。
注册GC事件监听
,通过JMX注册GC事件监听,把相关的信息直接打印出来
image.png
再启动一次,运行一段时间后,看到下面这样的日志信息:

而是年轻代GC,而且暂停时间达到了 1869 毫秒。 一点道理都不讲,我认为这种情况不合理,而且观察CPU使用量也不高。

打印GC日志
image.png

分析GC日志

因为不涉及敏感数据,那么我们把GC日志下载到本地进行分析。 定位到这次暂停时间超长的GC事件,
image.png
image.png
image.png

限制GC的并行线程数量

image.png
设置的原因:
image.png