JVM线上故障排查(一)

前言

大部分的开发都没有接触到线上故障排查的经历, 本篇通过对生产事故的复盘做下记录分析。
公司是做IM机器人的。 某次, 售后反馈, 大量客户的机器人出现延迟对话的情况, 此时, 看业务日志发现业务未出现问题, 而数据入口处MQ无日志埋点, 无法判断是哪个环节出现了延迟。

现象

1. load average偏高
2. top查看gc进程占用了大量的cpu
3. 内存free空间还比较多
4. gc日志显示大量的 Full GC

理论

要排查问题, 首先需要了解各个指标的具体含义

• load average 表示的是CPU的负载. 一般业界能够被接受的值是, load average <= CPU核数 *0.7。

• Full GC 会导致 STW ：top一the一World，简称STW，指的是Gc事件发生过程中，会产生应用程序的停顿。停顿产生时整个应用程序线程都会被暂停，没有任何响应，有点像卡死的感觉，这个停顿称为STW

• 线程池 队列是一种消息堆积策略, 比如下边的线程池, 最大线程100, 队列长度10000, 在高并发下, queue可能被堆积满。假设每个任务的执行耗时为200ms, 则该场景下任务需要 10000/100*200ms=20000ms=20s 能够执行完。则 TPS=10000/20=500。所以, 理论上单点最大并发500。

new ThreadPoolExecutor(50, 100, 30L, TimeUnit.SECONDS, new ArrayBlockingQueue(10000), new AbortPolicy())

• gc日志 所示, MinorGC 已无法回收内存, 只能触发 Full GC。 出现这种情况说明: 1. 内存还在使用中, 无法释放(可能内存分配太小, 正常内存溢出; 可能有IO、三方调用等耗时操作, 任务执行效率低, 导致内存长时间占用); 2. 内存泄露

[644572.936s][info][gc] GC(288066) To-space exhausted
[644572.936s][info][gc] GC(288066) Pause Young (Concurrent Start) (G1 Evacuation Pause) 497M->497M(512M) 59.255ms
[644572.936s][info][gc] GC(288068) Concurrent Cycle
[644573.994s][info][gc] GC(288067) Pause Full (G1 Evacuation Pause) 497M->369M(512M) 1058.025ms
[644573.995s][info][gc] GC(288068) Concurrent Cycle 1058.250ms

分析

通过上边的现象分析

1. 任务延时, 说明阻塞率比较高, 可能是业务阻塞(业务日志可以排查耗时), 也可能是得到的cpu执行单元降低
2. load average高, 说明无法再扩大线程池最大线程数
3. GC Thread占用大量cpu, 需要排查gc日志, 查看gc日志可知, Full GC频繁, 说明需要分析内存(看哪些对象占用内存高)。同时 Full GC会阻塞业务线程(有效内存得不到释放), 且会造成线程池中Queue进一步堆积, 加剧内存的消耗, 降低线程执行效率。内存分析过程下边再详细阐述。到这里基本可以确认, 线上的512M内存需要扩容了。

内存分析模拟

导出线程快照: jstack -l pid > xxx.log
导出内存快照: jmap -dump:live,format=b,file=/data/xxxx.hprof pid

live表示只dump活跃对象，format=b表示二进制格式，file表示保存文件的路径，pid表示进程号。

详细的JVM在线指令可以参考 https://idcent.cn/#/note/JVM调优指令

1. 查看我们应用的pid

ps -ef | grep xxx

2. 利用top命令找到CPU占用高的进程pid

top

显示pid: 381179

381179 root      20   0 6222740 996436   9272 S   0.7  12.5 133:34.36 java

3. 利用top找到该pid 381179下所有的线程数据

top -Hp 381179

可以看到占用cpu资源最高的为385444

385444 root      20   0 6222740 996436   9272 S   0.3  12.5  22:06.56 dubbo-future-ti

4. 占用率最高的线程 ID 为385444，将其转换为 16 进制形式 (因为 java native 线程以 16 进制形式输出)

printf '%x\n' 385444

得到线程ID: 5e1a4

5. 利用 jstack 打印出 java 线程调用栈信息

# 1. 在线查询
jstack 381179 | grep '5e1a4' -A 50 --color 

# 2. 导出线程快照查询
jstack -l 381179 > ./381179.stack 
cat 381179.stack ｜ grep '5e1a4' -C 50

模拟故障

1. 堆内存溢出

package com.example.demo;

import java.util.ArrayList;
import java.util.List;

/**
 * 堆溢出: java对象在堆中分配内存
 *
 * VM options: -Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError
 *
 * 执行结果:
 *
 * 分配次数：1
 * 分配次数：2
 * 分配次数：3
 * java.lang.OutOfMemoryError: Java heap space
 * Dumping heap to java_pid17426.hprof ...
 * Heap dump file created [17431809 bytes in 0.026 secs]
 * Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
 *  at HeapOOm.main(HeapOOm.java:15)
 */
public class HeapOOm {

    public static void main(String[] args) throws InterruptedException {
        List<byte[]> list = new ArrayList<>();
        int i=0;
        while(true){
            list.add(new byte[5*1024*1024]);
            System.out.println("分配次数："+(++i));
        }
    }
}

2. 栈内存溢出

package com.example.demo;


/**
 * 栈空间不足溢出
 *
 * 执行结果：
 *
 * 递归次数：18117
 * Exception in thread "main" java.lang.StackOverflowError
 *  at StackOverflowErrorDemo.sofMethod(StackOverflowErrorDemo.java:13)
 */
public class StackOverflowErrorDemo {

    int depth = 0;

    public void sofMethod(){
        depth ++ ;
        sofMethod();
    }

    public static void main(String[] args) {
        StackOverflowErrorDemo test = null;
        try {
            test = new StackOverflowErrorDemo();
            test.sofMethod();
        } finally {
            System.out.println("递归次数："+test.depth);
        }
    }
}

3. 永久代-方法区溢出

package com.example.demo;

import org.springframework.cglib.proxy.Enhancer;
import org.springframework.cglib.proxy.MethodInterceptor;
import org.springframework.cglib.proxy.MethodProxy;

import java.lang.reflect.Method;

/**
 * java7 方法区溢出
 * -XX:PermSize=10m -XX:MaxPermSize=10m
 */
public class MethodAreaOOMTest {

    public static void main(String[] args) {
        int i=0;
        try {
            while(true){
                Enhancer enhancer = new Enhancer();
                enhancer.setSuperclass(OOMObject.class);
                enhancer.setUseCache(false);
                enhancer.setCallback(new MethodInterceptor() {
                    @Override
                    public Object intercept(Object obj, Method method, Object[] args, MethodProxy proxy) throws Throwable {
                        return proxy.invokeSuper(obj, args);
                    }
                });
                enhancer.create();
                i++;
            }
        } finally{
            System.out.println("运行次数："+i);
        }
    }

    static class OOMObject{

    }
}

4. 元空间溢出

package com.example.demo;

import sun.misc.Unsafe;

import java.lang.reflect.Field;

/**
 * -Xms20m -Xmx20m -XX：MaxDirectMemorySize=10m
 */
public class DirectMemoryOOMTest {

    public static void main(String[] args) {
        int i=0;
        try {
            Field field = Unsafe.class.getDeclaredFields()[0];
            field.setAccessible(true);
            Unsafe unsafe = (Unsafe) field.get(null);
            while(true){
                unsafe.allocateMemory(1024*1024);
                i++;
            }
        } catch (Exception e) {
            e.printStackTrace();
        }finally {
            System.out.println("分配次数："+i);
        }
    }
}

5. Young GC 模拟

package com.example.demo;

import java.util.ArrayList;
import java.util.List;

/**
 * @author cuishiying
 */
public class TestYGC {
    /**
     * 设置参数 -Xms10m -Xmx20m -Xmn5m -XX:+PrintGCDetails
     * -Xms10m 初始化堆内存大小
     * -Xmx20m 堆最大内存
     * -Xmn5m 年轻代的大小
     * -XX:+PrintGCDetails 打印gc明细日志
     **/
    public static void main(String[] args) {
        List<Object> list = new ArrayList<>();

        for (int i = 0; i < 4; i++) {
            byte[] b = new byte[1024 * 1024];
            list.add(b);
        }
    }
}

6. Full GC 模拟

package com.example.demo;

import java.util.ArrayList;
import java.util.List;

/**
 * @author cuishiying
 */
public class TestFullGC {
    /**
     * 设置参数 -Xms10m -Xmx20m -Xmn5m -XX:+PrintGCDetails
     * -Xms10m 初始化堆内存大小
     * -Xmx20m 堆最大内存
     * -Xmn5m 年轻代的大小
     * -XX:+PrintGCDetails 打印gc明细日志
     * 新生代占堆内存的1/3
     * 老年代占堆内存的2/3
     **/
    public static void main(String[] args) {
        List<Object> list = new ArrayList<>();

        for (int i = 0; i < 8; i++) {
            byte[] b = new byte[1024 * 1024];
            list.add(b);
        }
    }
}

哪些对象触发了Full GC, 可以通过如下查看

jmap -histo:live pid | head -10

参考 http://static.kancloud.cn/alex_wsc/javajvm/1844985

7. 死锁模拟

package com.javaedge.concurrency.example.deadLock;


public class DeadLockDemo {
    private static Object resource1 = new Object();//资源 1
    private static Object resource2 = new Object();//资源 2

    public static void main(String[] args) {
        new Thread(() -> {
            synchronized (resource1) {
                System.out.println(Thread.currentThread() + "get resource1");
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                System.out.println(Thread.currentThread() + "waiting get resource2");
                synchronized (resource2) {
                    System.out.println(Thread.currentThread() + "get resource2");
                }
            }
        }, "线程 1").start();

        new Thread(() -> {
            synchronized (resource2) {
                System.out.println(Thread.currentThread() + "get resource2");
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                System.out.println(Thread.currentThread() + "waiting get resource1");
                synchronized (resource1) {
                    System.out.println(Thread.currentThread() + "get resource1");
                }
            }
        }, "线程 2").start();
    }
}

最后

简单总结下: CPU看线程, 内存看GC

本文到此结束，感谢阅读。如果您觉得不错，请关注公众号【当我遇上你】，您的支持是我写作的最大动力。