1. 使用jstack分析线程-示例
通过两个demo来学习如何使用jstack
1.1. 死锁
1.1.1. 死锁示例代码
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
|
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.LockSupport;
import java.util.concurrent.locks.ReentrantLock;
class DeadLockDemo {
public static void main(String[] args) throws Exception {
dead1();
dead2();
System.out.println("main-done");
}
public static void dead1() {
String a = "a";
String b = "b";
new Thread(() -> {
String name = "线程1";
synchronized (a) {
LockSupport.parkNanos(TimeUnit.SECONDS.toNanos(2));
System.out.println(name + " - lock - a");
synchronized (b) {
System.out.println(name + " - lock - b");
}
}
}).start();
new Thread(() -> {
String name = "线程2";
synchronized (b) {
LockSupport.parkNanos(TimeUnit.SECONDS.toNanos(2));
System.out.println(name + " - lock - a");
synchronized (a) {
System.out.println(name + " - lock - b");
}
}
}).start();
}
public static void dead2() {
ReentrantLock a = new ReentrantLock();
ReentrantLock b = new ReentrantLock();
new Thread(() -> {
String name = "线程3";
a.lock();
{
LockSupport.parkNanos(TimeUnit.SECONDS.toNanos(2));
System.out.println(name + " - lock - a");
b.lock();
System.out.println(name + " - lock - b");
b.unlock();
}
a.unlock();
}).start();
new Thread(() -> {
String name = "线程4";
b.lock();
{
LockSupport.parkNanos(TimeUnit.SECONDS.toNanos(2));
System.out.println(name + " - lock - a");
a.lock();
System.out.println(name + " - lock - b");
a.unlock();
}
b.unlock();
}).start();
}
}
|
1.1.2. 查找死锁
1
2
3
4
5
6
7
|
D:\>jps
183716 Jps
168072
182296 RemoteMavenServer
178780 Launcher
183740 DeadLockDemo
D:\>jstack 183740 > dead-info.txt
|
运行死锁代码后， 通过jps得到 DeadLockDemo 的 pid为 183740
然后将 jstack 183740 信息打印到 dead-info.txt 中
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
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
|
2019-06-19 12:48:17
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.201-b09 mixed mode):
"DestroyJavaVM" #15 prio=5 os_prio=0 tid=0x0000000003463800 nid=0x2cab0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Thread-3" #14 prio=5 os_prio=0 tid=0x0000000022db3800 nid=0x2c028 waiting on condition [0x00000000241ce000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000740e9fde0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at demo.DeadLockDemo.lambda$dead2$3(Test01_cache.java:64)
at demo.DeadLockDemo$$Lambda$4/1329552164.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Thread-2" #13 prio=5 os_prio=0 tid=0x0000000022db2800 nid=0x2ba04 waiting on condition [0x00000000240cf000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000740e9fe10> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at demo.DeadLockDemo.lambda$dead2$2(Test01_cache.java:51)
at demo.DeadLockDemo$$Lambda$3/668386784.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Thread-1" #12 prio=5 os_prio=0 tid=0x0000000022dae000 nid=0x2b224 waiting for monitor entry [0x0000000023fce000]
java.lang.Thread.State: BLOCKED (on object monitor)
at demo.DeadLockDemo.lambda$dead1$1(Test01_cache.java:35)
- waiting to lock <0x00000007408ec448> (a java.lang.String)
- locked <0x00000007408ec478> (a java.lang.String)
at demo.DeadLockDemo$$Lambda$2/1607521710.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Thread-0" #11 prio=5 os_prio=0 tid=0x00000000235d6800 nid=0x2c874 waiting for monitor entry [0x0000000023ecf000]
java.lang.Thread.State: BLOCKED (on object monitor)
at demo.DeadLockDemo.lambda$dead1$0(Test01_cache.java:25)
- waiting to lock <0x00000007408ec478> (a java.lang.String)
- locked <0x00000007408ec448> (a java.lang.String)
at demo.DeadLockDemo$$Lambda$1/1452126962.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x0000000022ae2800 nid=0x2b484 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread2" #9 daemon prio=9 os_prio=2 tid=0x0000000022a68800 nid=0x2cde0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #8 daemon prio=9 os_prio=2 tid=0x0000000022a81000 nid=0x2cd54 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #7 daemon prio=9 os_prio=2 tid=0x0000000022a67800 nid=0x2afc8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Monitor Ctrl-Break" #6 daemon prio=5 os_prio=0 tid=0x0000000022a5c800 nid=0x1ab0c runnable [0x00000000230ce000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
- locked <0x00000007409abd98> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at java.io.BufferedReader.fill(BufferedReader.java:161)
at java.io.BufferedReader.readLine(BufferedReader.java:324)
- locked <0x00000007409abd98> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:389)
at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:64)
"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x000000002166a000 nid=0x24148 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x0000000021620000 nid=0x2c244 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000000355c000 nid=0x2cec4 in Object.wait() [0x000000002296f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000740788ed0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x0000000740788ed0> (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=0x0000000003553000 nid=0x1cd0c in Object.wait() [0x000000002286f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000740786bf8> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x0000000740786bf8> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"VM Thread" os_prio=2 tid=0x00000000215d7800 nid=0x2c4cc runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000003479000 nid=0x2c2b4 runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x000000000347a800 nid=0x2bcac runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x000000000347c000 nid=0x29578 runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x000000000347e800 nid=0x1ca24 runnable
"VM Periodic Task Thread" os_prio=2 tid=0x0000000022b3a000 nid=0x2a978 waiting on condition
JNI global references: 320
Found one Java-level deadlock:
=============================
"Thread-3":
waiting for ownable synchronizer 0x0000000740e9fde0, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
which is held by "Thread-2"
"Thread-2":
waiting for ownable synchronizer 0x0000000740e9fe10, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
which is held by "Thread-3"
Java stack information for the threads listed above:
===================================================
"Thread-3":
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000740e9fde0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at demo.DeadLockDemo.lambda$dead2$3(Test01_cache.java:64)
at demo.DeadLockDemo$$Lambda$4/1329552164.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Thread-2":
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000740e9fe10> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at demo.DeadLockDemo.lambda$dead2$2(Test01_cache.java:51)
at demo.DeadLockDemo$$Lambda$3/668386784.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x0000000003558ed8 (object 0x00000007408ec448, a java.lang.String),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x000000000355b6b8 (object 0x00000007408ec478, a java.lang.String),
which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at demo.DeadLockDemo.lambda$dead1$1(Test01_cache.java:35)
- waiting to lock <0x00000007408ec448> (a java.lang.String)
- locked <0x00000007408ec478> (a java.lang.String)
at demo.DeadLockDemo$$Lambda$2/1607521710.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Thread-0":
at demo.DeadLockDemo.lambda$dead1$0(Test01_cache.java:25)
- waiting to lock <0x00000007408ec478> (a java.lang.String)
- locked <0x00000007408ec448> (a java.lang.String)
at demo.DeadLockDemo$$Lambda$1/1452126962.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
Found 2 deadlocks.
|
在线程信息的尾部: Found one Java-level deadlock: 和 Found 2 deadlocks.
工具已经帮我们分析出了死锁的线程。
1.2. 死循环
有时线程的代码逻辑有问题会导致cpu占用率很高。
1.2.1. 死循环示例代码
1
2
3
4
5
6
7
8
9
10
11
12
13
14
|
cat > LoopDemo.java <<EOF
class LoopDemo {
public static void main(String[] args) throws Exception {
new Thread(() -> {
int x = 1, y = x;
while (true) {
y = x + 1;
x = y - 1;
}
}).start();
System.out.println("main-done");
}
}
EOF
|
直接写个死循环
1
2
|
root@b3c8cc4ef0ae:/usr/games# javac LoopDemo.java
root@b3c8cc4ef0ae:/usr/games# java LoopDemo &
|
运行死循环代码
1.2.2. 追踪占用cpu的代码
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
|
root@b3c8cc4ef0ae:/usr/games# top
top - 07:40:58 up 24 min, 0 users, load average: 0.77, 0.63, 0.45
Tasks: 3 total, 1 running, 2 sleeping, 0 stopped, 0 zombie
%Cpu(s): 18.4 us, 1.1 sy, 0.0 ni, 79.0 id, 1.3 wa, 0.0 hi, 0.0 si, 0.1 st
KiB Mem : 2040828 total, 722372 free, 455908 used, 862548 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 1423680 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
190 root 20 0 2697428 27740 15524 S 106.7 1.4 0:55.63 java
1 root 20 0 20180 4060 3592 S 0.0 0.2 0:00.57 bash
218 root 20 0 38288 3480 3052 R 0.0 0.2 0:00.00 top
root@b3c8cc4ef0ae:/usr/games# jps
219 Jps
190 LoopDemo
|
运行top 可发现 pid=190 的程序占用cpu严重
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
|
root@b3c8cc4ef0ae:/usr/games# top -p 190 -H
top - 07:42:05 up 25 min, 0 users, load average: 0.92, 0.70, 0.49
Threads: 13 total, 1 running, 12 sleeping, 0 stopped, 0 zombie
%Cpu(s): 50.4 us, 0.0 sy, 0.0 ni, 49.6 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 2040828 total, 722332 free, 455836 used, 862660 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 1423720 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
202 root 20 0 2697428 27740 15524 R 99.9 1.4 2:02.57 java
190 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
191 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.27 java
192 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
193 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
194 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
195 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
196 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
197 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
198 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.03 java
199 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.09 java
200 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.00 java
201 root 20 0 2697428 27740 15524 S 0.0 1.4 0:00.11 java
###或者 ps -mp 190 -o THREAD,tid,time | sort -rn
###或者 top -bn1 -H -p 190
root@b3c8cc4ef0ae:/usr/games# printf "%x \n" 202
ca
|
针对 pid=190 的程序 ， 使用top 查看其线程状态
发现 pid=202 的线程在占用cpu， 把202换算为16进制为 ca
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
|
root@b3c8cc4ef0ae:/usr/games# jstack 190 > deadloop.txt
root@b3c8cc4ef0ae:/usr/games# cat deadloop.txt
2019-06-19 07:49:57
Full thread dump OpenJDK 64-Bit Server VM (25.212-b04 mixed mode):
"Attach Listener" #10 daemon prio=9 os_prio=0 tid=0x00007f79a0001000 nid=0xf5 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"DestroyJavaVM" #9 prio=5 os_prio=0 tid=0x00007f79d800b000 nid=0xbf waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Thread-0" #8 prio=5 os_prio=0 tid=0x00007f79d818f000 nid=0xca runnable [0x00007f79c6163000]
java.lang.Thread.State: RUNNABLE
at LoopDemo.lambda$main$0(LoopDemo.java:7)
at LoopDemo$$Lambda$1/471910020.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f79d80c2800 nid=0xc8 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f79d80b7800 nid=0xc7 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f79d80b4800 nid=0xc6 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f79d80b3000 nid=0xc5 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f79d8080800 nid=0xc4 in Object.wait() [0x00007f79c6904000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000f5988ed0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x00000000f5988ed0> (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=0 tid=0x00007f79d807e000 nid=0xc3 in Object.wait() [0x00007f79c6a05000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000f5986bf8> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000000f5986bf8> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"VM Thread" os_prio=0 tid=0x00007f79d8074800 nid=0xc2 runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f79d8020800 nid=0xc0 runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f79d8022800 nid=0xc1 runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007f79d80c5000 nid=0xc9 waiting on condition
JNI global references: 309
|
通过jstack命令查看程序的线程信息
可以找到 nid=0xca 的线程 “Thread-0”
1.3. 思考
如果说代码比较复杂， 死锁jstack不一定能找到。
可以优先关注线程状态为 BLOCKED 或 WAITING 的线程，看线程的阻塞是否合理。
除了死循环可能导致cpu飙高， 也可能是多线程自旋锁之间频繁的竞争。
文章作者
duansheli
上次更新
2019-12-25
(325c7b3)