Jstack来判断死循环、线程等待、死锁、IO等待情况

介绍

上一篇介绍了jstack基本用法,在一篇里将对具体的几种情况进行演示和分析。

死循环

示例代码

1
2
3
4
5
6
7
8
9
10
11
package jstack;

public class Demo1 {
public static void loop() {
while (true) {
}
}
public static void main(String[] args) {
loop();
}
}

编译,运行,用jstack输出结果,参考上篇操作(下同)。

这里主要是观测结果,分析结果。
省去上篇里介绍的一些通用线程(下同)。
选出的main函数的调用栈,如下:

1
2
3
4
"main" #1 prio=5 os_prio=0 tid=0x000000000215d800 nid=0x1224 runnable [0x000000000251f000]
java.lang.Thread.State: RUNNABLE
at jstack.Demo1.loop(Demo1.java:5)
at jstack.Demo1.main(Demo1.java:9)

在多次打出函数的调用栈时,可以发现程序一直在loop函数的第5行。从而在源代码中去查看相关代码,来诊断代码。

线程等待

示例代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
package jstack;

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

public class Demo2 {
public static void main(String[] args) {
ExecutorService ex = Executors.newCachedThreadPool();
ex.execute(new Runnable() {
@Override
public void run() {
synchronized (this) {
try {
wait();
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
});
}
}

线程进入同步块中后,调用wait等待通知。

jstack打印的结果为

1
2
3
4
5
6
7
8
9
10
"pool-1-thread-1" #10 prio=5 os_prio=0 tid=0x00000000585ff800 nid=0x40c in Object.wait() [0x00000000590cf000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d61e0e60> (a jstack.Demo2$1)
at java.lang.Object.wait(Unknown Source)
at jstack.Demo2$1.run(Demo2.java:14)
- locked <0x00000000d61e0e60> (a jstack.Demo2$1)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

可以看到线程在WAITING状态,等待的位置在jstack.Demo2$1,$1表示是一个匿名类,也就是程序中的第14行。

wait为什么要在synchronized里呢,不然会抛出IllegalMonitorStateException
因为当前线程必须拥有此对象监视器。

死锁

所谓死锁,是指两个或两个以上的进程在执行过程中,因争夺资源而造成的一种互相等待的现象,若无外力作用,它们都将无法推进下去。

示例代码

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
package jstack;

public class DeadLockThreadDemo extends Thread {

private Object lock1 = null;
private Object lock2 = null;

public DeadLockThreadDemo(Object lock1, Object lock2) {
this.lock1 = lock1;
this.lock2 = lock2;
}

@Override
public void run() {
System.out.println(Thread.currentThread().getName() + " info: lock1->" + lock1 + ", lock2" + lock2);
synchronized (lock1) {
System.out.println(Thread.currentThread().getName() + " enter synchronized " + lock1);
try {
Thread.sleep(2000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lock2) {
System.out.println(Thread.currentThread().getName() + "enter synchronized " + lock2);
System.out.println("exec...");
}
}
}
}

这是一个线程类。先获取到第一个锁,等待2秒,模拟线程执行,再获取第二个锁,再输出。

1
2
3
4
5
6
7
8
9
10
11
package jstack;

public class Demo3 {
public static void main(String[] args) {
Object lock1 = new Object();
Object lock2 = new Object();
new DeadLockThreadDemo(lock1, lock2).start();
new DeadLockThreadDemo(lock2, lock1).start();
}
}

这是执行函数,初始化的时候,按先后不同的顺序执行。

console输出的结果可能是

1
2
3
4
Thread-0 info:  lock1->java.lang.Object@43e8772d, lock2java.lang.Object@4d2f9120
Thread-0 enter synchronized java.lang.Object@43e8772d
Thread-1 info: lock1->java.lang.Object@4d2f9120, lock2java.lang.Object@43e8772d
Thread-1 enter synchronized java.lang.Object@4d2f9120

可以看到线程0拿到43e8772d对象的锁。可以看到线程1拿到4d2f9120对象的锁。
但是互要对方手上的锁。这样就互相等待下去,形成死锁。

用jstack查看结果

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

"Thread-1" #11 prio=5 os_prio=0 tid=0x0000000058716800 nid=0xf30 waiting for monitor entry [0x00000000596ee000]
java.lang.Thread.State: BLOCKED (on object monitor)
at jstack.DeadLockThreadDemo.run(DeadLockThreadDemo.java:24)
- waiting to lock <0x00000000d6257f40> (a java.lang.Object)
- locked <0x00000000d6257f50> (a java.lang.Object)

"Thread-0" #10 prio=5 os_prio=0 tid=0x0000000058716000 nid=0x12e0 waiting for monitor entry [0x000000005945f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at jstack.DeadLockThreadDemo.run(DeadLockThreadDemo.java:24)
- waiting to lock <0x00000000d6257f50> (a java.lang.Object)
- locked <0x00000000d6257f40> (a java.lang.Object)


Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x0000000057095ce8 (object 0x00000000d6257f40, a java.lang.Object),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x0000000057098628 (object 0x00000000d6257f50, a java.lang.Object),
which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
at jstack.DeadLockThreadDemo.run(DeadLockThreadDemo.java:24)
- waiting to lock <0x00000000d6257f40> (a java.lang.Object)
- locked <0x00000000d6257f50> (a java.lang.Object)
"Thread-0":
at jstack.DeadLockThreadDemo.run(DeadLockThreadDemo.java:24)
- waiting to lock <0x00000000d6257f50> (a java.lang.Object)
- locked <0x00000000d6257f40> (a java.lang.Object)

Found 1 deadlock.

显示找到了一个死锁。

IO等待

示例代码

1
2
3
4
5
6
7
8
9
10
package jstack;

import java.io.IOException;

public class Demo4 {
public static void main(String[] args) throws IOException {
int i = System.in.read();
System.out.println(i);
}
}

用jstack输出

1
2
3
4
5
6
7
8
"main" #1 prio=5 os_prio=0 tid=0x000000000220e000 nid=0x890 runnable [0x00000000024de000]
java.lang.Thread.State: RUNNABLE
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000d61597e0> (a java.io.BufferedInputStream)
at jstack.Demo4.main(Demo4.java:7)

可以看到线程在运行中,但一直在readBytes的本地方法中。

参考

IllegalMonitorStateException on wait() call
正确理解线程等待和释放(wait/notify)
jstack简单使用
线上高CPU占用


Jstack来判断死循环、线程等待、死锁、IO等待情况
https://blog.fengcl.com/2017/08/18/jstack-use-2/
作者
frank
发布于
2017年8月18日
许可协议