JVM系列(三十三) JVM调优实战-Jstack日志分析及死锁问题定位

1,084 阅读6分钟

Jstack日志分析及死锁问题定位

前面我们讲解了死锁产生的四个必要条件,及如何破坏其必要条件来避免死锁的方法,但是在实际项目中,难免遇到死锁,浪费大量系统资源,甚至导致系统崩溃

我们要做的就是一旦出现死锁,就能够快速的定位到死锁问题,并且找到根源,解决问题,今天我们讲解如何定位死锁问题

1.死锁场景及代码

首先,我们编写一个程序,来模拟一下死锁产生的场景,然后针对这种场景,使用Jstack 命令来分析定位问题,定位到死锁的问题代码,解决问题

场景如下:

  • 线程AAA 和 线程BBB 同时运行
  • 线程AAA 持有 对象obj1的资源信息
  • 线程BBB 持有 对象obj2的资源信息
  • 运行过程中,AAA去 请求 资源obj2 信息, 这时候因为BBB拿着 资源obj2 所以A 拿不到,AAA就等待BBB释放资源
  • 同一时间 , BBB去 请求 资源obj1 信息, 这时候因为AAA拿着 资源obj1 所以B 拿不到,BBB就等待AAA释放资源
  • 两个线程此刻都进入了等待状态 A等B释放,B等A释放,就死锁了
1.1 程序代码

程序代码如下

package com.jzj.jvmtest.mythread;

public class MyDeadLock {

    /**
     * 线程A 持有的资源1
     */
    private static Object obj1 = new Object();
    /**
     * 线程B 持有的资源2
     */
    private static Object obj2 = new Object();


    public static void main(String[] args) {
        System.out.println("程序启动");
        Thread threadA = new Thread(new TaskA());
        threadA.setName("AAA");

        Thread threadB = new Thread(new TaskB());
        threadB.setName("BBB");

        //启动线程
        threadA.start();
        threadB.start();
    }

    private static class TaskA implements Runnable {
        @Override
        public void run() {
            //线程A 对资源obj1 加锁,获取资源,不释放
            synchronized (obj1) {
                System.out.println("Thread AAA 拿到了 obj1 的锁!");

                try {
                    // 停顿10秒, 让ThreadB 线程拿到 obj2的锁
                    Thread.sleep(10000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }

                //拿完资源obj1后, 然后请求资源 obj2
                synchronized (obj2) {
                    System.out.println("Thread AAA 拿到了 obj2 的锁!");
                }
            }
        }
    }

    private static class TaskB implements Runnable {
        @Override
        public void run() {
            //线程B 对资源obj2 加锁,获取资源,不释放
            synchronized (obj2) {
                System.out.println("Thread BBB 拿到了 obj2 的锁!");

                try {
                    // 停顿10秒,让ThreadA 线程拿到 obj1的锁
                    Thread.sleep(10000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                //拿完资源obj2后, 然后请求资源 obj1
                synchronized (obj1) {
                    System.out.println("Thread BBB 拿到了 obj1 的锁!");
                }
            }
        }
    }

}

启动程序, 可以看到 线程AAA 拿到了 obj1的资源,线程BBB拿到了 obj2的资源,但是都在等待

程序启动
Thread AAA 拿到了 obj1 的锁!
Thread BBB 拿到了 obj2 的锁!

image.png

2.Jstack日志分析

在程序运行过程中,我们 执行 jps 查找进程信息, 然后执行 jstack pid 打印线程堆栈信息

执行jps, 程序Pid 30892

C:\Users\jzj>JPS
3104 Jps
25236 RemoteMavenServer36
10684 MyDeadLock
17228
27180 KotlinCompileDaemon
27980 Launcher

MyDeadLock 进程pid 10684, 执行 jstack 10684 , jstack日志如下

C:\Users\jzj>jstack 10684
2023-04-25 23:59:17
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.181-b13 mixed mode):

"DestroyJavaVM" #14 prio=5 os_prio=0 tid=0x0000000002f55000 nid=0x4b3c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"BBB" #13 prio=5 os_prio=0 tid=0x000000002006d800 nid=0x557c waiting for monitor entry [0x000000002090f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.jzj.jvmtest.mythread.MyDeadLock$TaskB.run(MyDeadLock.java:65)
        - waiting to lock <0x000000076bba56d0> (a java.lang.Object)
        - locked <0x000000076bba56e0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:748)

"AAA" #12 prio=5 os_prio=0 tid=0x000000002006c800 nid=0x7b9c waiting for monitor entry [0x000000002080f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.jzj.jvmtest.mythread.MyDeadLock$TaskA.run(MyDeadLock.java:44)
        - waiting to lock <0x000000076bba56e0> (a java.lang.Object)
        - locked <0x000000076bba56d0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:748)

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000001e2b3800 nid=0x76b0 in Object.wait() [0x000000001f60f000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000076b988ed0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
        - locked <0x000000076b988ed0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x000000000304c000 nid=0x57cc in Object.wait() [0x000000001f50f000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000076b986bf8> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x000000076b986bf8> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Periodic Task Thread" os_prio=2 tid=0x000000001e618000 nid=0x7b94 waiting on condition

JNI global references: 12

Found one Java-level deadlock:
=============================
"BBB":
  waiting to lock monitor 0x000000001cbd0d48 (object 0x000000076bba56d0, a java.lang.Object),
  which is held by "AAA"
"AAA":
  waiting to lock monitor 0x000000001cbd35d8 (object 0x000000076bba56e0, a java.lang.Object),
  which is held by "BBB"

Java stack information for the threads listed above:
===================================================
"BBB":
        at com.jzj.jvmtest.mythread.MyDeadLock$TaskB.run(MyDeadLock.java:65)
        - waiting to lock <0x000000076bba56d0> (a java.lang.Object)
        - locked <0x000000076bba56e0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:748)
"AAA":
        at com.jzj.jvmtest.mythread.MyDeadLock$TaskA.run(MyDeadLock.java:44)
        - waiting to lock <0x000000076bba56e0> (a java.lang.Object)
        - locked <0x000000076bba56d0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

3.Jstack日志解析

前面我们说过,如果线程状态出现了 Bolcked 阻塞状态,就要重点关注, 下面我们看下 线程状态

"BBB" #13 prio=5 os_prio=0 tid=0x000000002006d800 nid=0x557c waiting for monitor entry [0x000000002090f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.jzj.jvmtest.mythread.MyDeadLock$TaskB.run(MyDeadLock.java:65)
        - waiting to lock <0x000000076bba56d0> (a java.lang.Object)
        - locked <0x000000076bba56e0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:748)

"AAA" #12 prio=5 os_prio=0 tid=0x000000002006c800 nid=0x7b9c waiting for monitor entry [0x000000002080f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.jzj.jvmtest.mythread.MyDeadLock$TaskA.run(MyDeadLock.java:44)
        - waiting to lock <0x000000076bba56e0> (a java.lang.Object)
        - locked <0x000000076bba56d0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:748)
  • BBB线程 tid=0x000000002006d800
    • 线程状态 BLOCKED
    • 代码位置 MyDeadLock.java:65
    • waiting to lock <0x000000076bba56d0> 等待资源 <0x000000076bba56d0>
    • locked <0x000000076bba56d0> 自身持有资源 <0x000000076bba56d0>
  • AAA tid=0x000000002006c800
    • 线程状态 BLOCKED
    • 代码位置 MyDeadLock.java:44
    • waiting to lock <0x000000076bba56e0> 等待资源 <0x000000076bba56e0>
    • locked <0x000000076bba56d0> 自身持有资源 <0x000000076bba56d0>
  • BBB 线程等待 0x000000076bba56d0, 而AAA 线程 持有资源 0x000000076bba56d0
  • AAA 线程等待 0x000000076bba56e0 ,而BBB 线程 持有资源 0x000000076bba56d0
  • AAA 不会主动释放自己的资源, 所以BBB也就不会获得资源,同样BBB不释放,AAA也不会获得
  • 就这样死锁了

下面打印的日志更加清晰

Found one Java-level deadlock:
=============================
"BBB":
  waiting to lock monitor 0x000000001cbd0d48 (object 0x000000076bba56d0, a java.lang.Object),
  which is held by "AAA"
"AAA":
  waiting to lock monitor 0x000000001cbd35d8 (object 0x000000076bba56e0, a java.lang.Object),
  which is held by "BBB"

Java stack information for the threads listed above:
===================================================
  • 找到了一个 死锁
  • BBB 等待 锁监视器 0x000000001cbd0d48, 这个监视器被 AAA持有
  • AAA 等待 锁监视器 0x000000001cbd35d8, 这个监视器被 BBB持有

通过jstack日志,我们可以很清晰的定位到死锁的位置及很清晰都知道死锁形成的原因

4.Jprofiler 分析死锁信息

下面我们使用Jprofiler来启动进程,看看能否使用jprofiler来定位到线程中的死锁信息 启动程序

  • 程序Total number of threads 一共2个线程, Bolcked threads 阻塞线程 2个 image.png

  • 点击左侧Thread 线程分析,可以看到AAA 和BBB 现在处于阻塞状态 image.png

  • 点击左侧Thread下面的 Thread History 线程监视器,可以看到 AAA和BBB 处于阻塞状态 image.png

  • 点击左侧Thread下面的 Thread monitor 线程监视器,可以看到 AAA和BBB 处于阻塞状态 image.png

-点击Thread Dumps 也可以分析出 AAA阻塞状态,代码位置在 44行,BBB阻塞状态代码位置在65行 image.png


至此 ,我们通过jstack日志,可以分析出死锁问题出现在哪里,死锁如何解决,另外本文也通过jprofiler来分析了线程死锁问题定位,给出多种定位问题的办法,解决线程死锁问题