堆栈日志工作中一直在用,每次都是随用随看,没有系统的记录过,今天正好有空编辑一个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不是本篇文章讨论的重点,所以这里只是提一下,感兴趣的可以再查下。

 

Logo

更多推荐