How To Get And Analyze Java Thread Dumps

Overview

This post explains how to get Java thread dump using kill and jstack and how to analyze the dump file, an example of dead lock analysis is given too.

Why We Want A Java Thread Dump

A Java thread dump is a snapshot of what all the threads are doing in the JVM at the particular time we send the request of the dump. The Java thread dump results contains a lot of information, that is, earch thread in the JVM is listed with its name, id, current state and the Java call stack, if also provides other useful information like which lock each thread is waiting for if any. It is quite useful for investigation when we find the Java application seems to hang or be stuck which is probably because of dead locks under heavy load, and in this case, the Java thread dump will list all the deadlocks it found, I ll give an example of it in the following sections.

How to Get A Java Thread Dump

There are two ways to get the Java thread dump.

  1. run command “kill -3 pid”, we can use “ps -ef grep java” to find the Java process pid, “kill -3 pid” just send a request to that JVM, and by default, JVM will output the dump result into the standard output (same destination as System.out.print).
  2. use jstack, simple run command “jstack pid”, there are some options available for jstack, like -f forces the JVM to do a Java thread dump.

Note the differences between the above two ways, kill -3 just send a request, but jstack will need to receive the result and output it to the standard output. That is, kill -3 simply send the request, and it is not resposible for displaying the Java thead dump, after JVM get the requst from kill -3, the JVM will take the resposiblity to output the dump, so say if you have a eclipse test app, and in your terminal, you send kill -3 to that java process, in the eclipse output panel, you will see the results. On the other hand, jstack directly handles the results and output it to the terminal directly, so we can redirect the outputs, do something like “jstack pid > threads.dump”.

jstack is the preferable way.

Example of DeadLock Java Thread Dump

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
public class TestApp {
	private final ExecutorService pool; 
	private final SharedObj sharedObj;

	private final Object lock1 = new Object();
	private final Object lock2 = new Object();
	
	public TestApp() {
		pool = Executors.newFixedThreadPool(2);
		sharedObj = new SharedObj();
		sharedObj.f1 = -1;
		sharedObj.f2 = -2;
		sharedObj.volativleField = 1_000;
	}


	public void shutDown() {
		pool.shutdown();
	}

	public void runTest() {
		pool.submit(() -> {
			for (int i = 0; i < 100; ++i) {
				synchronized(lock1) {
					synchronized(lock2) {
						sharedObj.echo();
						sharedObj.f2 = sharedObj.f2 + 1;
						sharedObj.volativleField = sharedObj.volativleField + 1;
						sharedObj.f1 = sharedObj.f1 + 1;
					}
				}
			}
		});

		pool.submit(() -> {
			for (int i = 0; i < 100; ++i) {
				synchronized(lock2) {
					synchronized(lock1) {
						sharedObj.echo();
						sharedObj.f2 = sharedObj.f2 - 1;
						sharedObj.volativleField = sharedObj.volativleField - 1;
						sharedObj.f1 = sharedObj.f1 - 1;
					}
				}
			}
		});
	}

	public static void main(String[] arg) {
		TestApp test = new TestApp();
		test.runTest();
		test.shutDown();
    }
   
    static class SharedObj {
    	public int f1;
    	public volatile int volativleField;
    	public int f2;

	public void echo() {
		System.out.println(
		"Current Thread:" + Thread.currentThread() + 
		"SharedObj [f1=" + f1 
		+ ", volativleField=" + volativleField 
		+ ", f2=" + f2 + "]");
	}
    }
}

We can run the above test code, and we could see the application hang, and the standard output will be stuck at some time point (less than 200 lines), something like the following:

1
2
3
4
5
6
7
8
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=-1, volativleField=1000, f2=-2]
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=0, volativleField=1001, f2=-1]
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=1, volativleField=1002, f2=0]
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=2, volativleField=1003, f2=1]
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=3, volativleField=1004, f2=2]
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=4, volativleField=1005, f2=3]
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=5, volativleField=1006, f2=4]
Current Thread:Thread[pool-1-thread-1,5,main]SharedObj [f1=6, volativleField=1007, f2=5]

Then we will want to see what are those thread doing. Use jstack to get the following results:

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
Found one Java-level deadlock:
=============================
"pool-1-thread-2":
  waiting to lock monitor 0x00007f8728004ed8 (object 0x00000000ece26f78, a java.lang.Object),
  which is held by "pool-1-thread-1"
"pool-1-thread-1":
  waiting to lock monitor 0x00007f8728004f88 (object 0x00000000ece26f88, a java.lang.Object),
  which is held by "pool-1-thread-2"

Java stack information for the threads listed above:
===================================================
"pool-1-thread-2":
	at com.sigmainfy.TestApp.lambda$1(TestApp.java:50)
	- waiting to lock <0x00000000ece26f78> (a java.lang.Object)
	- locked <0x00000000ece26f88> (a java.lang.Object)
	at com.sigmainfy.TestApp$$Lambda$2/1418481495.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
"pool-1-thread-1":
	at com.sigmainfy.TestApp.lambda$0(TestApp.java:37)
	- waiting to lock <0x00000000ece26f88> (a java.lang.Object)
	- locked <0x00000000ece26f78> (a java.lang.Object)
	at com.sigmainfy.TestApp$$Lambda$1/791452441.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

Found 1 deadlock.

In this case, the thread dump reveals the problem directly, and we can come up with some solutions, one strategry is to make sure all the threads follow a globally fixed lock acquisition order.

More on Java Thread Dump Analysis

Usually, it would be enough to just use text editor to view the dump results directly so we know what is happening, there are some useful tools to assist the analysis as well, and more explaination about the terminologies used in the Java thread dump results, refer to the following good posts:

  1. How to Analyze Java Thread Dumps
  2. Thread Dump analysis

Summary

I have explained how to get Java thread dump using kill and jstack and how to analyze the dump file, an example of dead lock analysis is given too.

Written on May 29, 2016