一次Full GC导致CPU飙升的排查过程

本文主要是介绍一次Full GC导致CPU飙升的排查过程，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！

文章目录

- 现象
- 异常分析思考
- 问题排查
- - 接口调用量异常排查
  - 内存使用率异常排查
  - JVM 对象分配，GC流程
- 问题处理
- 问题分析

现象

生产环境突然间大量接口超时告警,监控发现，问题发生的时间，cpu使率飙升，网络磁盘抖动大，内存使用率飙升，大约3-5分钟后系统自动恢复。
cpu,网络监控异常
内存磁盘监控异常

异常分析思考

从监控看到，cpu，内存，磁盘，网络在异常发生时都有明显的抖动。
内存使用率突然飙升，应用IO也突然陡增。猜测可能是该时刻有定时任务，或者大量请求导致。问题发生时刻，细致对比变化时间，发现是首先网络IO飙升，磁盘突然增加，猜测可能是该时刻有大量请求导致。
综合分析下，我们猜测，最大可能是请求量突然暴增，导致系统负载过高，内存，cpu使用率飙升。

问题排查

接口调用量异常排查

根据监控异常，我们猜测最有可能的是该时刻有大量的请求，或者定时任务，导致系统负载突然增加。我们从监控上找到对应的几个问题发生时间段，调用量明显增多的接口。排查代码后，发现没有变更，调用量突然增大是因为cpu异常导致积累了一些请求，所以会看起来调用量突然增加。

内存使用率异常排查

应用异常时，根据监控发现内存使用率飙升，我们找到当时该实例的jvm相关指标监控，发现发生问题时，触发了FullGc，Full Gc次数明显增多，gc耗时增加，堆内存飙升，老年代空间飙升。这里使用的是默认的垃圾收集器 Parallel Scavenge（新生代）+ Serial Old（老年代），后续我们调整为G1垃圾收集器。
下图可见，full gc次数增加多，gc耗时增加，老年代突然增加
绿色的表示Full Gc 黄色的表示young GC
发现老年代突然飙升
错误日志中也有gc oom的日志。超出了GC开销限制，GC占用大量时间为释放很小空间的时候发生的，是一种保护机制。一般是因为堆太小，导致异常的原因：没有足够的内存。
GC错误日志
到这里我们猜测，应该是某个使用率低的接口请求，或者某种特定的条件查询，导致突然加载了大量数据，对象实例过大，内存不够用，大对象进入老年代，触发FullGc，Full Gc导致cpu飙升，造成系统卡顿。下一步是需要找到这个对象，确定是哪一块代码引起的。

JVM 对象分配，GC流程

JVM对象分配，GC过程
因为问题发生时系统卡顿，进入容器已经无法执行堆栈打印，内存快照打印，jvm已经触发了垃圾回收无法查看哪个对象过大导致系统卡顿。这里我们想到的是如何减少gc，尤其是full gc,尽可能的保留大对象，又不影响系统，有利益排查问题。

JVM内存大小设置
在这里插入图片描述

问题处理

因为gc后，系统自动恢复了，无法确定是哪个对象过大，无法定位到具体的问题，只能确定是内存不够，触发full gc，导致cpu飙升系统卡顿。
我们决定调整jvm参数，扩大内存，修改jvm垃圾收集器，扩大内存后，后面还是出现了该问题，不过这次只是cpu飙升，系统没有出现卡顿，出现问题后，我们使用如下命令，查看jvm堆内存快照，线程堆栈，等信息。发现系统cpu飙升的时候，占用cpu高的线程是full gc的线程。
调整参数配置后，容器部署的实例再次出现问题，不过这次出现问题cpu占用比率没有之前高，没有导致整个应用不可用，我们利用下面的命令获取堆内存，线程堆栈，堆内对象大小，进一步分析问题。

//打印内存快照 然后利用MAT工具分析是否存在内存泄漏等等
jmap -J-d64  -dump:live,format=b,file=dumpfile.hprof [pid]
//打印线程堆栈
jstack pid
//查看内存对象大小
jmap -histo  pid | sort -n -r -k 3 | head -20
查看进程里面占用cpu高的线程
ps -mp pid -o THREAD,tid,time | sort -k2r

打印的线程堆栈，发现有线程正在进行垃圾回收，对应的线程id转成16进制是 14 15 16

查看线程发现占用cpu高的线程正是正在进行垃圾回收的那几个线程，对应的线程id是 14 15 16 跟进行垃圾回收的线程id一致

因为这次调整了堆内存大小，触发问题后，没有进行full gc，对象还在，查看内存对象占用比，发现相关代码问题，一次性加载了150万的实例到对象中，调整内存之前加载该对象后，导致内存飙升，触发gc，进而引起cpu使用率飙升。