从图中可以看到,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事件监听,把相关的信息直接打印出来
再启动一次,运行一段时间后,看到下面这样的日志信息:
而是年轻代GC,而且暂停时间达到了 1869 毫秒。 一点道理都不讲,我认为这种情况不合理,而且观察CPU使用量也不高。
打印GC日志
分析GC日志
因为不涉及敏感数据,那么我们把GC日志下载到本地进行分析。 定位到这次暂停时间超长的GC事件,
限制GC的并行线程数量
设置的原因: