java 程序运行的测试与分析_Java运行时死锁检测和分析

文章目录

SUN JDK提供了一系列的运行时分析工具1可以用于分析运行时的JVM状况，这些工具包括jps、jstack、jstat、jinfo、jmap、jconsole、jvisualvm等。

本文使用其中的部分工具来检测运行时是否发生死锁。先写一个运行时会发生死锁的程序，其实最经典的哲学家就餐问题2就是一个死锁的示例，以下程序对该程序略做修改，改成一个只要运行，就很容易(几乎是必然)发生死锁的版本。

首先是Resource类，表示多个进程需要竞争的资源，即哲学家就餐问题中的“筷子”，如下，

1

2

3

4

5

6

7

8package problem1;

public class Resource{

private int id;

public Resource(int id) { this.id = id; }

public int getId() { return id; }

public String toString(){ return ""+id; };

}

然后是DeadLockExp类，表示会引发死锁的多个线程，即哲学家就餐问题中的“哲学家”，如下，

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

27package problem1;

public class DeadLockExp implements Runnable{

private Resource myOwn, myNeed;

public DeadLockExp(Resource myOwn, Resource myNeed) {

this.myOwn = myOwn; this.myNeed = myNeed;

}

@Override

public void run() {

String threadName = Thread.currentThread().getName();

try {

while(true) {

synchronized(myOwn) {

System.out.println("Thread "+threadName+" has got Resource "+myOwn);

Thread.sleep(1000);

synchronized(myNeed) {

System.out.println("Thread "+threadName+" has got Resource "+myNeed);

Thread.sleep(1000);

System.out.println("Thread "+threadName+"'s job has done.");

}

}

}

} catch(InterruptedException e) {}

}

}

本文略作修改，把“哲学家”思考的时间和就餐的时间，这两段都去掉了。将问题中的两根筷子，改为myOwn和myNeed两个成员，表示本线程运行先后需要的资源。由于一定要引发死锁，将对两个成员加锁的间隔时间加长为1s。这样，所有线程同时启动，在1s内，每个线程都加锁了自己的资源，同时也都在请求别人的资源，就形成了死锁。而1s内，完成这些事情是几乎必然的，因此这个程序就一定会引发死锁。

下面在main方法中初始化相互依赖关系，确保出现环形依赖，如下，

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21package problem1;

import java.util.concurrent.ExecutorService;

import java.util.concurrent.Executors;

public class Problem1{

public static void main(String[] args) {

int num = 4;

Resource[] res = new Resource[num];

ExecutorService exec = Executors.newFixedThreadPool(num);

for(int i = 0; i < num; i++){

res[i] = new Resource(i);

}

for(int i = 0; i < num; i++) {

exec.execute(new DeadLockExp(res[i], res[(i+1)%num]));

}

exec.shutdown();

}

}

本例使用了4个线程(不是哲学家就餐问题中的5个)，初始化DeadLockExp实例的时候，注意依赖关系为，DeadLockExp0->DeadLockExp1->DeadLockExp2->DeadLockExp3->DeadLockExp0。

于是，运行这段程序的时候就会发现每个线程的第一次循环内就进入了死锁，输出为

1

2

3

4Thread pool-1-thread-1 has got Resource 0

Thread pool-1-thread-3 has got Resource 2

Thread pool-1-thread-2 has got Resource 1

Thread pool-1-thread-4 has got Resource 3

如果这4个线程有任何一个线程没有进入死锁的话，那应该会出现类似这样的输出，

1Thread pool-1-thread-4's job has done.

本文是使用Eclipse来运行这个程序的，环境是Ubuntu Linux，下面开始用JDK提供的工具来检测这个死锁，先用jps，如下

1

2

3

4~$ jps -l -m -v

4004 /home/program/eclipse//plugins/org.eclipse.equinox.launcher_1.3.0.v20130327-1440.jar -os linux -ws gtk -arch x86_64 -showsplash /home/program/eclipse//plugins/org.eclipse.platform_4.3.2.v20140221-1700/splash.bmp -launcher /home/program/eclipse/eclipse -name Eclipse --launcher.library /home/program/eclipse//plugins/org.eclipse.equinox.launcher.gtk.linux.x86_64_1.1.200.v20140116-2212/eclipse_1508.so -startup /home/program/eclipse//plugins/org.eclipse.equinox.launcher_1.3.0.v20130327-1440.jar --launcher.appendVmargs -exitdata 22000b -product org.eclipse.epp.package.standard.product -vm /home/program/jdk1.8.0/bin/java -vmargs -Dosgi.requiredJavaVersion=1.6 -XX:MaxPermSize=256m -Xms40m -Xmx512m -jar /home/program/eclipse//plugins/org.eclipse.equinox.launcher_1.3.0.v20130327-1440.jar -Dosgi.requiredJavaVersion=1.6 -XX:MaxPermSize=256m -Xms40m -Xmx512m

4633 sun.tools.jps.Jps -l -m -v -Denv.class.path=.:/home/program/jdk1.8.0/lib:/home/program/jdk1.8.0/lib/dt.jar:/home/program/jdk1.8.0/lib/tools.jar -Dapplication.home=/home/program/jdk1.8.0 -Xms8m

4607 problem1.Problem1 -Dfile.encoding=UTF-8

可以发现发生死锁的进程是4607，用linux下的工具pidstat(需要安装sysstat)可以看到该进程的线程情况，

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22~$ pidstat -p 4607 -u 1 1 -t

19时22分15秒 TGID TID %usr %system %guest %CPU CPU Command

19时22分16秒 4607 - 0.00 0.00 0.00 0.00 0 java

19时22分16秒 - 4607 0.00 0.00 0.00 0.00 0 |__java

19时22分16秒 - 4609 0.00 0.00 0.00 0.00 2 |__java

19时22分16秒 - 4610 0.00 0.00 0.00 0.00 1 |__java

19时22分16秒 - 4611 0.00 0.00 0.00 0.00 1 |__java

19时22分16秒 - 4612 0.00 0.00 0.00 0.00 1 |__java

19时22分16秒 - 4613 0.00 0.00 0.00 0.00 1 |__java

19时22分16秒 - 4618 0.00 0.00 0.00 0.00 3 |__java

19时22分16秒 - 4620 0.00 0.00 0.00 0.00 2 |__java

19时22分16秒 - 4621 0.00 0.00 0.00 0.00 3 |__java

19时22分16秒 - 4622 0.00 0.00 0.00 0.00 1 |__java

19时22分16秒 - 4623 0.00 0.00 0.00 0.00 2 |__java

19时22分16秒 - 4624 0.00 0.00 0.00 0.00 1 |__java

19时22分16秒 - 4625 0.00 0.00 0.00 0.00 0 |__java

19时22分16秒 - 4626 0.00 0.00 0.00 0.00 0 |__java

19时22分16秒 - 4627 0.00 0.00 0.00 0.00 1 |__java

19时22分16秒 - 4628 0.00 0.00 0.00 0.00 2 |__java

19时22分16秒 - 4629 0.00 0.00 0.00 0.00 0 |__java

19时22分16秒 - 4630 0.00 0.00 0.00 0.00 0 |__java

用jstack打印线程的dump，如下

1~$ jstack 4607 >> a.txt

然后打开该文件，线程dump文件中的线程号用的是16进制，不利于分析，不过由于我们使用了ExecutorService，所以可以用线程名称来查找，线程名称以pool-1-thread-开头。文件的前一部分是每一个线程的状态和调用栈，在最后的地方，提示发现了一个死锁，如下，

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

32Java stack information for the threads listed above:

===================================================

"pool-1-thread-4":

at problem1.DeadLockExp.run(DeadLockExp.java:19)

- waiting to lock <0x00000000ebf96a00> (a problem1.Resource)

- locked <0x00000000ebf96a30> (a problem1.Resource)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)

at java.lang.Thread.run(Thread.java:662)

"pool-1-thread-1":

at problem1.DeadLockExp.run(DeadLockExp.java:19)

- waiting to lock <0x00000000ebf96a10> (a problem1.Resource)

- locked <0x00000000ebf96a00> (a problem1.Resource)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)

at java.lang.Thread.run(Thread.java:662)

"pool-1-thread-2":

at problem1.DeadLockExp.run(DeadLockExp.java:19)

- waiting to lock <0x00000000ebf96a20> (a problem1.Resource)

- locked <0x00000000ebf96a10> (a problem1.Resource)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)

at java.lang.Thread.run(Thread.java:662)

"pool-1-thread-3":

at problem1.DeadLockExp.run(DeadLockExp.java:19)

- waiting to lock <0x00000000ebf96a30> (a problem1.Resource)

- locked <0x00000000ebf96a20> (a problem1.Resource)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)

at java.lang.Thread.run(Thread.java:662)

Found 1 deadlock.

更加可视化的方式是用jvisualvm，在线程那一栏也可以看到有提示发现死锁，如下，

也可以点击线程dump，得到线程的dump文件，内容和我们之前用jstack得到几乎一样，

这个线程dump文件和之前不同的地方在于多了一些jmx和rmi的线程，从此也可以看出来，jvisualvm这个工具是使用jmx做出来的。

至此，分析完毕。