Java 多线程死锁问题

发表于 更新于

本文描述一个 Java 多线程死锁问题，并演示使用 jstack、arthas 工具来发现应用程序中的线程死锁。

先编写一段死锁的代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
public class App {

    public static void main(String[] args) {
        String x = "x";
        String y = "y";
        Thread a = new Thread(new Runnable() {
            @Override
            public void run() {
                String threadName = Thread.currentThread().getName();
                synchronized (x) {
                    System.out.println(String.format("Thread %s Start %s", threadName, "------"));
                    System.out.println(String.format("Thread %s, x = %s", threadName, x));
                    synchronized (y) {
                        System.out.println(String.format("Thread %s, y = %s", threadName, y));
                    }
                    System.out.println(String.format("Thread %s End %s", threadName, "------"));
                }
            }
        });

        Thread b = new Thread(new Runnable() {
            @Override
            public void run() {
                String threadName = Thread.currentThread().getName();
                synchronized (y) {
                    System.out.println(String.format("Thread %s Start %s", threadName, "------"));
                    System.out.println(String.format("Thread %s, y = %s", threadName, y));
                    synchronized (x) {
                        System.out.println(String.format("Thread %s, x = %s", threadName, x));
                    }
                    System.out.println(String.format("Thread %s End %s", threadName, "------"));
                }
            }
        });

        a.start();
        b.start();
    }
}

运行以上代码，发现如下输出：

1
2
3
4
Thread Thread-0 Start ------
Thread Thread-0, x = x
Thread Thread-1 Start ------
Thread Thread-1, y = y

由于 Thread-0 和 Thread-1 均没有输出 End 信息，可知线程陷入了死锁。

jstack 分析

jstack 是 jdk 自带的线程堆栈分析工具，使用该命令可以查看或导出 Java 应用程序中线程堆栈信息。

Useage:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
Usage:
    jstack [-l] <pid>
        (to connect to running process)
    jstack -F [-m] [-l] <pid>
        (to connect to a hung process)
    jstack [-m] [-l] <executable> <core>
        (to connect to a core file)
    jstack [-m] [-l] [server_id@]<remote server IP or hostname>
        (to connect to a remote debug server)

Options:
    -F  强制转储线程信息，当 jstack 不响应时使用
    -m  打印Java和本机框架的所有栈信息（混合模式）
    -l  长列表，答应更多关于锁的附加信息
    -h or -help 打印帮住信息

通过 jps 命令查询到程序的 pid，使用 jstack -l 来查看线程堆栈信息

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
PS C:\Users\fuyongde> jstack -l 151792
2019-11-19 16:20:14
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.162-b12 mixed mode):

"DestroyJavaVM" #15 prio=5 os_prio=0 tid=0x0000000003103800 nid=0x240b8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Thread-1" #14 prio=5 os_prio=0 tid=0x00000000227d2000 nid=0x21898 waiting for monitor entry [0x00000000235df000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.exp.App$2.run(App.java:34)
        - waiting to lock <0x0000000740da48c0> (a java.lang.String)
        - locked <0x0000000740da48f0> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Thread-0" #13 prio=5 os_prio=0 tid=0x00000000227d1000 nid=0x23f90 waiting for monitor entry [0x00000000234df000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.exp.App$1.run(App.java:19)
        - waiting to lock <0x0000000740da48f0> (a java.lang.String)
        - locked <0x0000000740da48c0> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Service Thread" #12 daemon prio=9 os_prio=0 tid=0x000000002271c000 nid=0x21868 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C1 CompilerThread2" #11 daemon prio=9 os_prio=2 tid=0x0000000022681800 nid=0x21874 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread1" #10 daemon prio=9 os_prio=2 tid=0x0000000022678800 nid=0x24288 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread0" #9 daemon prio=9 os_prio=2 tid=0x0000000022661000 nid=0x21870 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"JDWP Command Reader" #8 daemon prio=10 os_prio=0 tid=0x00000000225fe000 nid=0x21864 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"JDWP Event Helper Thread" #7 daemon prio=10 os_prio=0 tid=0x00000000225fa800 nid=0x21834 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"JDWP Transport Listener: dt_socket" #6 daemon prio=10 os_prio=0 tid=0x0000000021291800 nid=0x21854 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x00000000212dc800 nid=0x21860 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x00000000225f0800 nid=0x2184c runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000002126a000 nid=0x240c4 in Object.wait() [0x00000000225df000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000740988ec0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
        - locked <0x0000000740988ec0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212)

   Locked ownable synchronizers:
        - None

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

   Locked ownable synchronizers:
        - None

"VM Thread" os_prio=2 tid=0x0000000021246800 nid=0x218a0 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000003119000 nid=0x240ac runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x000000000311a800 nid=0x2188c runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x000000000311c000 nid=0x2189c runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x000000000311e000 nid=0x2409c runnable

"VM Periodic Task Thread" os_prio=2 tid=0x00000000227c9000 nid=0x240f8 waiting on condition

JNI global references: 1880


Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00000000031fdbd8 (object 0x0000000740da48c0, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00000000031fc5d8 (object 0x0000000740da48f0, a java.lang.String),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at com.exp.App$2.run(App.java:34)
        - waiting to lock <0x0000000740da48c0> (a java.lang.String)
        - locked <0x0000000740da48f0> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)
"Thread-0":
        at com.exp.App$1.run(App.java:19)
        - waiting to lock <0x0000000740da48f0> (a java.lang.String)
        - locked <0x0000000740da48c0> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

通过观察可以发现 Thread-0、Thread-1 两个线程均处于 BLOCKED 状态，而且堆栈信息的最后明确提示了 Found 1 deadlock.，相关锁定的代码行也都有非常明确的提示，相关提示如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00000000031fdbd8 (object 0x0000000740da48c0, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x00000000031fc5d8 (object 0x0000000740da48f0, a java.lang.String),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at com.exp.App$2.run(App.java:34)
        - waiting to lock <0x0000000740da48c0> (a java.lang.String)
        - locked <0x0000000740da48f0> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)
"Thread-0":
        at com.exp.App$1.run(App.java:19)
        - waiting to lock <0x0000000740da48f0> (a java.lang.String)
        - locked <0x0000000740da48c0> (a java.lang.String)
        at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

arthas 分析

Arthas 是 Alibaba 开源的 Java 诊断工具，深受开发者喜爱。在线排查问题，无需重启；动态跟踪 Java 代码；实时监控 JVM 状态。详情可参考官网

启动 arthas 并选择我们的程序。

由于我们是要查询线程死锁问题，故需要用到 thread 命令。

Useage：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
USAGE:
   thread [-h] [-b] [-i <value>] [-n <value>] [id]

 SUMMARY:
   Display thread info, thread stack

 EXAMPLES:
   thread
   thread 51
   thread -n -1
   thread -n 5
   thread -b
   thread -i 2000

 WIKI:
   https://alibaba.github.io/arthas/thread

 OPTIONS:
 -h, --help                                                                     this help
 -b, --include-blocking-thread                                                  Find the thread who is holding a lock that blocks the most number of threads.
 -i, --sample-interval <value>                                                  Specify the sampling interval (in ms) when calculating cpu usage.
 -n, --top-n-threads <value>                                                    The number of thread(s) to show, ordered by cpu utilization, -1 to show all.
 <id>                                                                           Show thread stack

从帮助信息中可知 thread -b 可以帮我们查询阻塞时间最长的线程。

1
2
3
4
5
6
7
8
[arthas@664776]$ thread -b
"Thread-0" Id=13 BLOCKED on java.lang.String@45db1404 owned by "Thread-1" Id=14
    at com.exp.App$1.run(App.java:19)
    -  blocked on java.lang.String@45db1404
    -  locked java.lang.String@2fa93a25 <---- but blocks 1 other threads!
    at java.lang.Thread.run(Thread.java:748)

Affect(row-cnt:0) cost in 22 ms.

通过观察输出可以发现，相比 jstack，arthas 可以更加快速的定位到阻塞线程。