Friday, March 7, 2014

(HOWTO: Java) – BLOCKED Thread Locking Tree

Understanding which Thread is waiting and which Thread is blocking

Finding the root cause of a block in java may be difficult sometimes, as thread dumps may be difficult to follow, and is hard to understand which thread is waiting and which thread is locking it.

Unfortunately, I have not seen any tools that can represent clearly a lock tree of a Threads running in a java process. This is the reason I thought to build a tool that can help to determine BLOCKER and WAITER threads from a java thread dump.

The idea is to take a thread dump and store the output to a file, then process that file using a perl script which I called “thread_lock_tree.pl”. The script will represent a list of threads and its status grouping the threads that a BLOCKING together with the ones that are WAITING. All this is done in a visual way using indentation, so that everyone can understand and see.

You start by taking a thread dump, using your favorite tool, for Example jstack.

$JAVA_HOME/bin/jstack 8978 > thread_dump_pid8978.tdump

As you can see from the below, it is difficult to determine which threads are waiting for which thread to finish.

$ cat thread_dump_pid8978.tdump
"AJPRequestHandler-HTTPThreadGroup-2744" prio=10 tid=0x36f92000 nid=0x6206 waiting for monitor entry [0x18621000]
java.lang.Thread.State: BLOCKED (on object monitor)
- waiting to lock <0x84095160> (a oracle.jdbc.driver.T4CConnection)
- locked <0xe2447c99> (a java.lang.Byte)
"AJPRequestHandler-HTTPThreadGroup-2743" prio=10 tid=0x36f98c00 nid=0x6177 waiting for monitor entry [0x18255000]
java.lang.Thread.State: BLOCKED (on object monitor)
- waiting to lock <0x779ce6b8> (a java.lang.Byte)
- locked <0xe2447c59> (a java.lang.Byte)
"AJPRequestHandler-HTTPThreadGroup-2742" prio=10 tid=0x36f92800 nid=0x60d7 runnable [0x182f6000]
java.lang.Thread.State: RUNNABLE
- locked <0x84095160> (a oracle.jdbc.driver.T4CConnection)
- locked <0xe2447c58> (a java.lang.Byte)
- locked <0x779ce6b8> (a java.lang.Byte)
"AJPRequestHandler-HTTPThreadGroup-2749" prio=10 tid=0x36f92000 nid=0x6206 waiting for monitor entry [0x18621000]
java.lang.Thread.State: BLOCKED (on object monitor)
- waiting to lock <0xe2447c59> (a java.lang.Byte)
- waiting to lock <0xe2447c99> (a java.lang.Byte)
- locked <0xe2457c99> (a java.lang.Byte)
"AJPRequestHandler-HTTPThreadGroup-4749" prio=10 tid=0x36f92000 nid=0x6206 waiting for monitor entry [0x18621000]
java.lang.Thread.State: BLOCKED (on object monitor)
- waiting to lock <0xe2447c59> (a java.lang.Byte)
- waiting to lock <0xe2447c99> (a java.lang.Byte)
"AJPRequestHandler-HTTPThreadGroup-5749" prio=10 tid=0x36f92000 nid=0x6206 waiting for monitor entry [0x18621000]
java.lang.Thread.State: BLOCKED (on object monitor)
- waiting to lock <0xe2457c99> (a java.lang.Byte)

To understand the lock situation, you can parse “tdump” file using the script.

Usage: perl thread_lock_tree.pl <file.tdump>

$ perl thread_lock_tree.pl thread_dump_pid8978.tdump
~~ Analyzing thread lock tree in thread dump file: thread_dump_pid8978.tdump ~~
AJPRequestHandler-HTTPThreadGroup-2742(RUNNABLE) (2)
|_AJPRequestHandler-HTTPThreadGroup-2744(BLOCKED) (2)
  |_AJPRequestHandler-HTTPThreadGroup-2749(BLOCKED) (1)
    |_AJPRequestHandler-HTTPThreadGroup-5749(BLOCKED) (0)
  |_AJPRequestHandler-HTTPThreadGroup-4749(BLOCKED) (0)
|_AJPRequestHandler-HTTPThreadGroup-2743(BLOCKED) (2)
  |_AJPRequestHandler-HTTPThreadGroup-2749(BLOCKED) (1)
    |_AJPRequestHandler-HTTPThreadGroup-5749(BLOCKED) (0)
  |_AJPRequestHandler-HTTPThreadGroup-4749(BLOCKED) (0)

As you can see in the above output, you can easily see which threads are locking and which ones are waiting in a simple locking tree format.

Click link to download script  thread_lock_tree.pl 

No comments:

Post a Comment