jvm根据堆栈日志定位问题

堆栈日志工作中一直在用，每次都是随用随看，没有系统的记录过，今天正好有空编辑一个demo系统记录下如何打印堆栈日志，以及堆栈日志的查看。

一、文章介绍

首先我会编辑一个demo工程模仿三种较常见的堆栈问题场景，其次打包上传到linux服务器，最后调用接口分别模拟出对应的问题场景。最后介绍哪些命令查看堆栈信息，以及查看堆栈日志中的一些常见技巧。（生产中一般都是使用linux，所以这里并没有介绍windows中可以使用的jvisualvm程序，虽然jvisualvm可以远程连接服务器，并查看服务器上jvm相关的堆栈和垃圾回收等信息，但是实际使用较少，一般本地测试或者纯windows部署，可以通过jvisualvm查看）

二、demo编辑

栈日志一般和线程调用相关，线程调用最常见的问题就是死锁，JDK中常见的锁则有两种，一个是底层系统实现的synchronize锁，还有一个则是比较灵活的类锁ReadWriteLock（这这两种锁不熟悉或者感兴趣的可以我的jdk锁系列文章：jdk锁知识（一）—— 总览_Interest1_wyt的博客-CSDN博客）。这里我针对两类锁模拟了两种场景，核心代码如下：

2.1 死锁场景1：synchronize

代码逻辑：启动两个线程，每个线程各自持有一把锁，但是现在都需要获取对方的锁才能完成调用，进而形成死锁。

public class DeadLockSimulate1 {

    private Object lock1 = new Object();
    private Object lock2 = new Object();

    private void method1() {
        System.out.println("method1 等待获取 lock1");
        synchronized (lock1) {
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            System.out.println("method1 获取 lock1");
            method12();
        }
    }

    private void method12() {
        System.out.println("method12 等待获取 lock2");
        synchronized (lock2) {
            System.out.println("method12 获取 lock2");
        }
    }

    private void method2() {
        System.out.println("method2 等待获取 lock2");
        synchronized (lock2) {
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            System.out.println("method2 获取 lock2");
            method21();
        }
    }

    private void method21() {
        System.out.println("method21 等待获取 lock1");
        synchronized (lock1) {
            System.out.println("method21 获取 lock1");
        }
    }

    public void run() {
        Thread thread1 = new Thread(() -> {
            method1();
        });
        thread1.setName("自定义线程1");
        thread1.start();

        Thread thread2 = new Thread(() -> {
            method2();
        });
        thread2.setName("自定义线程2");
        thread2.start();

    }

    public static void main(String[] args) {
        DeadLockSimulate1 simulate1 = new DeadLockSimulate1();
        simulate1.run();
    }
    
}

2.2 死锁场景2：ReentrantLock

我这里并没有直接调用ReentrantLock进行加锁解锁，而是通过一个阻塞队列来观察锁的等待和释放情况，最终的目的是查看队列满了的情况锁的等待信息，这个场景虽然不是严格意义上的死锁，但是也是生产上常见的类型之一，所以和死锁一块放在这讲。

代码逻辑：启动线程池，三个线程生产数据放阻塞队列，三个线程消费队列中数据，但消费线程每30秒自动结束一个。因此队列会被放满，且最终没有消费者消费，进而形成无限等待的场景。

public class DeadLockSimulate2 {

    public ArrayBlockingQueue<String> queue = new ArrayBlockingQueue(20);

    public void run() {

        ThreadPoolExecutor executor = new ThreadPoolExecutor(6, 6, 0, TimeUnit.MINUTES, new ArrayBlockingQueue<>(10));

        //三个生产者，每秒生产一个数据
        for (int i = 0; i < 3; i++) {
            executor.execute(() -> {
                try {
                    while (true) {
                        System.out.println(System.currentTimeMillis() / 1000 + " - " + Thread.currentThread().getName() + " 放数据");
                        queue.put("200");
                        Thread.sleep(1000);
                    }
                } catch (Exception e) {
                    e.printStackTrace();
                }
            });
        }

        //下面为三个消费者，每秒消费一个数据，但是线程依次在30秒、60秒、90秒死亡，最终造成队列满等的情况
        executor.execute(() -> {
            try {
                int cnt = 30;
                while (cnt > 0) {
                    System.out.println(System.currentTimeMillis() / 1000 + " - " + Thread.currentThread().getName() + " 取数据");
                    queue.take();
                    Thread.sleep(1000);
                    cnt = cnt - 1;
                }
                System.out.println(System.currentTimeMillis() / 1000 + " - " + Thread.currentThread().getName() + " 消亡");
            } catch (Exception e) {
                e.printStackTrace();
            }
        });

        executor.execute(() -> {
            try {
                int cnt = 60;
                while (cnt > 0) {
                    System.out.println(System.currentTimeMillis() / 1000 + " - " + Thread.currentThread().getName() + " 取数据");
                    queue.take();
                    Thread.sleep(1000);
                    cnt = cnt - 1;
                }
                System.out.println(System.currentTimeMillis() / 1000 + " - " + Thread.currentThread().getName() + " 消亡");
            } catch (Exception e) {
                e.printStackTrace();
            }
        });

        executor.execute(() -> {
            try {
                int cnt = 90;
                while (cnt > 0) {
                    System.out.println(System.currentTimeMillis() / 1000 + " - " + Thread.currentThread().getName() + " 取数据");
                    queue.take();
                    Thread.sleep(1000);
                    cnt = cnt - 1;
                }
                System.out.println(System.currentTimeMillis() / 1000 + " - " + Thread.currentThread().getName() + " 消亡");
            } catch (Exception e) {
                e.printStackTrace();
            }
        });
    }

    public static void main(String[] args) {
        DeadLockSimulate2 simulate2 = new DeadLockSimulate2();
        simulate2.run();
    }


}

2.3 内存溢出

代码逻辑：创建两个线程，一个往map集合放大量字节数组信息，一个往list集合放不断累加的字符串信息，实际上两个线程各自都可以造成内存溢出。

public class OutOfMemorySimulate1 {

    public Map<Integer, byte[]> map = new HashMap<>();

    public List<String> list = new ArrayList<>();

    public void run() {
        Thread thread1 = new Thread(() -> {
            for (int i = 0; i < Integer.MAX_VALUE; i++) {
                map.put(i, new byte[1024]);
            }
        });
        thread1.setName("自定义线程1");
        thread1.start();

        Thread thread2 = new Thread(() -> {
            String temp = "out of memory";
            for (int i = 0; i < Integer.MAX_VALUE; i++) {
                list.add(temp);
            }
        });
        thread2.setName("自定义线程2");
        thread2.start();
    }

    public static void main(String[] args) {
        OutOfMemorySimulate1 simulate1 = new OutOfMemorySimulate1();
        simulate1.run();
    }

}

2.4 其它

这里我还编辑了controller类，并且有三个接口调用，进而调用上述的三个场景run方法。因为这不是核心代码，所以自己简单编辑下就行，这里就不浪费篇幅讲解。

最终代码被打成jar并上传到linux服务器。这里提供一个服务器上jar包启动命令，大家如果启动后不能打印日志，可以参考该命令重新启动：

nohup java -jar  demo-0.0.1-SNAPSHOT.jar >demo.log 2>&1 &

三、堆栈以及垃圾回收日志打印分析

生产中通用分析jvm问题时，一般都会看下堆栈日志和垃圾回收是否正常，但这里为了避免展示过多的冗余信息，所以下面针对每种场景只展示相关的日志打印和查看操作。

3.1 死锁场景1 synchronize

调用接口触发场景1 run方法的执行，当日志中看到如下信息，说明死锁已经形成

 这里我们通过如下命令打印栈信息：

jstack -l 2079 > deadlock1/deadlock1_stack.txt

栈日志里面有两处信息比较关键，一个在日志中间地方，通过它可以看到两个线程都处于阻塞状态，都在等待一个Object对象锁。

 还有一处关键信息在日志底部，因为我们打印日志加了 -l 参数，因此当出现死锁时会把死锁信息打印出来，这个一般就放在日志底部，如下：

  所以，当判断可能出现死锁时，就可以打印对应的栈日志，然后拉到日志底部进行查看是否死锁。不过这种方式只能查看死锁比较明显的场景，对于一些因为资源不够而等待的锁问题就无法定位，所以我又加了一个“死锁”场景，当然这并不是死锁，只是同一个锁因为资源问题而无线等待而已。下面来看一看具体的信息。

3.2 “死锁”场景2 类锁

调用接口触发场景2 run方法的执行，当日志中出现三次消亡，且不再刷新时，说明阻塞队列已经放满，且没有消费者消费，线程进入无限等待阶段。

 这里我们还是通过栈命令打印栈信息：

jstack -l 2311 > deadlock2/deadlock2_stack.txt

这个栈日志查看技巧就比较多了，首先栈日志中会有很多线程信息，我们要学会分辨哪些线程是我们的。因为我们使用了线程池，所以可以分辨出poo开头的线程名是我们的线程

 其次线程池中正常来说只有三个在运行，但是有六个都是等待中，是不是感觉很疑惑，其实这是因为六个线程中还有三个线程在等待接收任务，即它们在线程池中等待接收任务（感兴趣的可以阅读线程池相关文章：jdk线程池（一）——介绍及使用_Interest1_wyt的博客-CSDN博客）

 而我们需要定位的则是另外的三个线程信息，可以看到它们都在等待状态，且代码都卡在DeadLockSimulate2类的第29行，至此便可以定位到源码中的位置了，剩下的就是根据业务和源码梳理出问题点并改正。

3.3 内存溢出

为了在内存溢出时主动打印一份堆日志，一般在启动的时候就会加上内存溢出相关的参数，这里我的启动命令如下：

nohup java -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=outofmemory/outmemorydump2.hprof  -jar demo-0.0.1-SNAPSHOT.jar > demo.log 2>&1

启动后调用接口触发场景3 run方法的执行，当日志中出现内存溢出异常时，说明场景3已经形成：

 

 此时调用jmap命令打印堆日志信息：

jmap -dump:format=b,file=outofmemory/outofmemory.dump 2533

至此我们获得了两份堆日志，我们先看我们自己通过jmap命令生成的dump日志。堆日志一般很大，不可能直接打开查看，一般要借用命令或者工具，jdk本身带有一个jhat命令可以生成简单的html页面展示，但是功能太简单，且解析不彻底。故这里使用jdk本身带有的另外一个工具jvisualvm。

 双击打开该工具，随后将jmap生成的堆文件加载进来。

 进入首页后可以看到如下信息：

 可以看到我们的堆日志还会包括线程信息，所以在生产中一般是导出保存堆日志，因为堆日志包含的信息比较全面。这里我们不再看线程信息，直接点击查看类相关的数据。

 可以看到，是我们的map集合导致的线程溢出，而且类实例数量前三个分别对应map集合和它的value以及key信息，而map中的value直接占用了百分七十多的空间。所以可以断定这次内存溢出的主要原因是map集合。

看到这里可能部分人会有疑惑，为什么项目的输出日志中还显示list的内存溢出信息，其实是因为map集合占用了内存，导致堆内存空间很小，所以这时list集合即使放入的字符串很小也会报内存溢出异常。

接下来我们再看下系统自动生成的堆日志，流程与上述相同，我们直接看类信息：

可以看到具体的数值可能略有出入，但是整体情况是一样的。至此我们可以定位到有问题的类信息。然后我们双击类名信息进入对应的实例信息，在其引用模块可以看到相关的引用类信息，以此便可定位内存溢出所在的具体位置。

 至此，我们堆栈信息都查看了一遍。但是打印堆数据再解析还是比较繁琐，如果能先大致确定了有内存溢出或者内存泄漏再打印堆信息，则可以避免做无用功。

这里就用到了另外一个命令jstat，内存溢出势必会造成频繁的垃圾回收，这个命令正好可以监测jvm性能以及垃圾回收相关的信息。这里简单展示下本demo中垃圾回收的统计信息：

 可以看到再内存溢出后年轻代老年代空间几乎被用满，垃圾回收次数增大且回收时间也在逐渐变长。通过这便可快速判断出是否有内存溢出的情况存在。jstat不是本篇文章讨论的重点，所以这里只是提一下，感兴趣的可以再查下。