JVM故障分析篇

2020-04-03 本文已影响0人千淘萬漉

在上一篇文章《JVM实战优化篇》中，梳理了JVM内存的核心参数，同时对新业务系统上线如何预估容量、垃圾回收器如何选择进行了总结，最后文末还给大家总结了一套通用的JVM参数模板。JVM的调优基本都发生在上线前，尽量争取在压测环节就可以把JVM参数调整到最优，最有效的优化手段是架构和代码层面的优化，如果上线以后发生了JVM故障，最常见的比如频繁FullGC导致CPU飙升、系统响应迟钝，OOM导致的服务不可用等场景，下面就工具和思路进行总结。

大纲

一、JVM命令

1.jps，虚拟机进程状况

./jsp直接输出各个JVM进程的PID。

image.png

2.jstat，虚拟机统计信息监视工具

jstat命令可以查看堆内存各部分的使用量，以及加载类的数量。主要常用这个查看堆的使用情况：

jstat -gc pid

pid是VM的进程号，即当前运行的java进程号，后面还可以加几个参数。

interval：执行的间隔时间，单位为毫秒
count ：打印次数，如果缺省则一直打印

使用jstat -gc vmid

上面的缩写解释：
E-eden, S-suviror, M-metaspace, C-capacity, U-used 前面均为瞬时统计容量(byte)
以下统计了从应用程序启动到采样时的统计综合
YGC ：年轻代中gc次数
YGCT ：年轻代中gc所用时间(s)
FGC：old代(全gc)gc次数
FGCT： (全gc)gc所用时间(s)
GCT：gc用的总时间(s)

3.jmap 虚拟机内存映像工具

jmap命令是一个可以输出所有内存中对象的工具，甚至可以将VM 中的heap，以二进制输出成文本。

堆转储文件：jmap -dump:live,format=b,file=heap-dump.bin <pid>
输出所有内存中对象统计，jmap -gc pid，输入的demo如下：

./jmap -heap 5932
Attaching to process ID 5932, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.91-b15

using thread-local object allocation.
Parallel GC with 4 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 1073741824 (1024.0MB)
   NewSize                  = 42991616 (41.0MB)
   MaxNewSize               = 357564416 (341.0MB)
   OldSize                  = 87031808 (83.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 60293120 (57.5MB)
   used     = 44166744 (42.120689392089844MB)
   free     = 16126376 (15.379310607910156MB)
   73.25337285580842% used
From Space:
   capacity = 5242880 (5.0MB)
   used     = 0 (0.0MB)
   free     = 5242880 (5.0MB)
   0.0% used
To Space:
   capacity = 14680064 (14.0MB)
   used     = 0 (0.0MB)
   free     = 14680064 (14.0MB)
   0.0% used
PS Old Generation
   capacity = 120061952 (114.5MB)
   used     = 19805592 (18.888084411621094MB)
   free     = 100256360 (95.6119155883789MB)
   16.496143590935453% used

20342 interned Strings occupying 1863208 bytes.

4.jstack 虚拟机堆栈跟踪工具

jstack是JDK自带的线程跟踪工具，用于打印指定Java进程的线程堆栈信息。常用于排查cpu使用率过高的问题，其排查思路也比较套路：
1、通过top命令找出cpu使用率最高的进程
2、然后通过top -Hp pid查看该进程下各个线程的cpu使用情况
3、继续使用jstack pid命令查看当前java进程的堆栈状态，且将内容输出到dump文件中。
4、将PID（十进制）转换成十六进制后，用转换后的数字去定位线程的一个执行状态和堆栈信息。
5、也可以使用jca工具分析线程dump文件，找出来线程处于BLOCKED和WAITING状态的，并进行堆栈分析

dump分析

可以重点怀疑那种应该很快执行但是并未执行的线程，比如dubbo调用等。

RUNNABLE，线程处于执行中
BLOCKED，线程被阻塞
WAITING，线程正在等待

二、频繁FullGC实战

FullGC发生时一般会导致CPU升高、系统响应变长，服务会短暂停顿等现象，如果频繁的发生FGC的话，那么就会导致系统的服务处于一个不稳定的状况，引发FullGC的原因会很多，我们尽量要做的就是在上线之前，做好压测，避免JVM参数的不合理导致频繁FGC。

1.模拟压测

模拟一个压测场景，频繁的创建对象，然后又很快的回收处理，分析步骤如下：

每秒执行一次loadData()方法
创建了40M的字节数组指向data变量，但是马上成为垃圾；
data1和data2指向两个10M数组，有引用而可以存活
data3依次指向了两个10M数组

public class FullGCOptmize {
    public static void main(String[] args) throws Exception{
        Thread.sleep(1000);
        while (true) {
            loadData();
        }
    }
    public static void loadData() throws Exception{
        byte[] data = null;
        for (int i = 0; i < 4; i++) {
            data = new byte[10 * 1024 * 1024];
        }
        data = null;
        byte[] data1 = new byte[10 * 1024 * 1024];
        byte[] data2 = new byte[10 * 1024 * 1024];
        byte[] data3 = new byte[10 * 1024 * 1024];
        data3 = new byte[10 * 1024 * 1024];
        Thread.sleep(1000);
    }
}

此处设定的一个不太合理的JVM参数：

-Xms200M -Xmx200M -XX:NewSize=100m 
-XX:MaxNewSize=100m -XX:SurvivorRatio=8 
-XX:PretenureSizeThreshold=20m -XX:+UseConcMarkSweepGC 
-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps 
-XX:+PrintGCTimeStamps

100M新生代，Eden区80M，S区10M，Old区100M，1s内执行完loadData()方法产生80M垃圾，一定会触发一次MinorGC。所以我们用jstat命令监控会发现：

第一次ygc，30M数组（data1、2、3）直接进入老年代(OU)，data和data3的数组对象直接被回收。
后续每秒一次的ygc，都会有大约10~30M进入老年代(OU)
大约在60M的时候，发生了一次老年代GC，老年代的内存使用从60M->30M。
ygc太频繁，导致每次回收后存活对象太多，频繁进入老年代，频繁触发FullGC。

使用jstat -gc vmid

上面采用的jstat可以准确的去观察数值上的精确变化，但是如果想利用可视化的工具，观察一个总的盘面情况，可以采用VisualGC工具：

visualGC观察GC情况

2.优化思路

优化思路：扩大新生代，扩大Survivor区空间，堆大小300M，其中新生代扩大至200M（Eden区100M，S区各50M）。JVM参数设定如下：

-Xms300M -Xmx300M -XX:NewSize=200m -XX:MaxNewSize=200m 
-XX:SurvivorRatio=2 -XX:PretenureSizeThreshold=20m 
-XX:+UseConcMarkSweepGC -Xloggc:gc.log 
-XX:+PrintGCDetails -XX:+PrintGCDateStamps 
-XX:+PrintGCTimeStamps

此时再次观察GC频率和耗时每秒新增80M，每次ygc后有10M对象进入survivor区，8次ygc后才有600k数据进入老年代，FullGC已经完全消失。

jstatc观察gc情况

visualGC统计情况

3.FullGC原因及思路总结

上线前要充分做好压测和JVM调优，这样在线上就不会因为参数不合理而导致正常的业务运行而触发了FullGC的情况。这里调优的思路仍然遵循前面文章中的方案来进行：

让短命对象在MinorGC阶段就被回收；
MinorGC后的存活对象<Survivor区域50%，可控制保留在新生代；
长命对象尽早进入老年代，不要在新生代来回复制；

参数已经优化完毕，且上线一段时间以后，如果还会出现FullGC频繁或者时间过长，分析思路就要从JVM调优转化到架构和代码调优上去，且需要一些特殊手段去排查GC问题，尤其需要结合dump分析来解决，首先要抓住FullGC时前后的堆dump日志，然后再利用MAT工具进行堆栈分析和对象分布分析，这个工具的使用后面会继续讲到。这种层面的故障分析就需要结合业务+代码一起联合分析，而不是再去调整JVM参数能够做到的了！

FullGC原因及思路

如果FullGC无法准确的去抓取快照dump，那么还是可以在JVM启动的时候增加下面两个参数-XX:+HeapDumpBeforeFullGC -XX:+HeapDumpAfterFullGC就可以在FGC的前后dump一下内存。不过增加这两个参数会在每次FGC的时候dump内存，dump内存本身对应用有影响，但是不会导致JVM停机。特别是在web应用启动的时候，就会不断的去dump内存，因为web应用启动的时候会频繁发生FGC，所以这个命令需要慎用。

三、OOM实战

1.OOM类型及原因

之前的FullGC尚只是对系统的性能和使用造成一定的冲击，影响至少可控，但是假如发生了OOM，那就相当于系统挂掉一样，内存溢出无法再分配对象空间，那也就意味着系统无法接受任何请求，这个直接就是生产事故级别了。通常要分析OOM事件，就少不了要去排查内存泄漏的问题。内存泄漏是因，内存溢出是果：

内存泄露：申请使用完的内存没有释放，导致虚拟机不能再次使用该内存，此时这段内存就泄露了，因为申请者不用了，而又不能被虚拟机分配给别人用。
内存溢出：申请的内存超出了JVM能提供的内存大小，此时称之为溢出。

能发生OOM的地方通常是四个：堆内，堆外，元空间（jdk8以前叫老年代）和虚拟机栈。

2.heap dump分析

为了能够在OOM发生的时候能留下现场证据，线上服务的JVM参数中一般需要配置-XX:+HeapDumpOnOutOfMemoryError，在发生OOM之前将堆中对象和内存dump一份快照出来。我们这里模拟一个触发OOM的场景，非常简单，即无线的创造对象且不被回收，直到JVM内存打爆触发OOM：

public class HeapOOM {
    static class OOMObject {
    }
    public static void main(String[] args) {
        int i = 0;
        List<OOMObject> list = new ArrayList<OOMObject>();
        cycle(list, i);
    }
    public static void cycle(List<OOMObject> list, int i) {
        //在堆中无限创建对象
        while (true) {
            System.out.println("already create objects=" + i++);
            list.add(new OOMObject());
        }
    }
}

同时设置一个JVM参数如下：

-Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=d:/dump/

执行主程序以后，没过几秒函数就挂掉了，此时我们拿出堆MAT dump工具进行分析：

1、查看对象分布饼图，一般选择前面几个大对象进行分析

image.png

2、GC Roots线程追踪和被引用分析，从创建最多的大对象里，右键点选进行GC Roots线程追踪、incoming reference分析，可以把大对象的根引用对象以及所在的线程方法名打印出来，基本可以判断大对象的出处和来源。

gcroot追踪和引用分析

3、通过MAT给出内存泄漏分析报告，查看诊断出来可能存在内存泄漏的线程栈和详细的大对象信息。

内存分析报告

下面就总结一下常见的OOM类型和原因，业务系统中最常发生就是堆内存的溢出，它的排查方法就是要结合dump日志+mat分析工具，分析大对象类型，线程堆栈，并结合业务场景来分析为何会发生内存泄漏的原因。

OOM类型与原因

以上类型的OOM都已更新在我的github地址，每种类型除了给出了执行代码，还需要同步修改IDE的jvm参数方能快速触发OOM场景，下载地址在文章最末尾。

故障分析总结

综合来看，故障分析篇，主要是三个核心观点：
1、要在上线前的压测环节将JVM参数调整至最优，后续就不在改动这一块的参数。
2、如果上线以后还会发生了FullGC和OOM等情况，那么有限需要去做架构和代码层级的优化，这个时候分析GC日志要比直接调优JVM参数要好。
3、JVM诊断和分析工具，利用好jstat或者VisualGC观察GC次数和频率，利用好jmap dump关键证据，然后使用MAT工具去分析可能内存泄漏的地方！

推荐一个学习库：
https://github.com/StabilityMan/StabilityGuide
实例中涉及到的代码：
https://github.com/tisonkong/JavaAssemble/tree/master/jvm

关注公众号获取更多学习资料

]