Ambulans Mortuus – Troubleshooting JVM Thread Deadlock with VisualVM

In my previous post I shown how you can troubleshoot various Java hangs and performance conditions by using JStack utility, which is a part of JDK. Today I will show a lot cooler and more advanced tool called VisualVM that allows you to take and analyze thread and heap dumps in Java.

First, what is threading deadlock? A deadlock is a situation where an application locks up because two or more activities are waiting for each other to finish. This occurs in multithreading software where a shared resource is locked by one thread and another thread is waiting to access it and something occurs so that the thread holding the locked item is waiting for the other thread to execute.  In the past I have had multiple opportunities to troubleshoot threading deadlocks in .NET and Windows unmanaged code with WinDBG , but not in Java. However, concepts are the same.

However, first things first. Lets create a quick deadlock condition in code. Easiest way that I am aware of is via lock nesting. Following little application creates deadlock and terminates due to that condition:

package threaddeadlock
 
public class ThreadDeadlock {
 
    public static void main(String[] args) throws InterruptedException {
        Object obj1 = new Object();
        Object obj2 = new Object();
        Object obj3 = new Object();
     
        Thread t1 = new Thread(new SyncThread(obj1, obj2), "t1");
        Thread t2 = new Thread(new SyncThread(obj2, obj3), "t2");
        Thread t3 = new Thread(new SyncThread(obj3, obj1), "t3");
         
        t1.start();
        Thread.sleep(5000);
        t2.start();
        Thread.sleep(5000);
        t3.start();
         
    }
 
}
 
class SyncThread implements Runnable{
    private Object obj1;
    private Object obj2;
 
    public SyncThread(Object o1, Object o2){
        this.obj1=o1;
        this.obj2=o2;
    }
    @Override
    public void run() {
        String name = Thread.currentThread().getName();
        System.out.println(name + " acquiring lock on "+obj1);
        synchronized (obj1) {
         System.out.println(name + " acquired lock on "+obj1);
         work();
         System.out.println(name + " acquiring lock on "+obj2);
         synchronized (obj2) {
            System.out.println(name + " acquired lock on "+obj2);
            work();
        }
         System.out.println(name + " released lock on "+obj2);
        }
        System.out.println(name + " released lock on "+obj1);
        System.out.println(name + " finished execution.");
    }
    private void work() {
        try {
            Thread.sleep(30000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

And here is the output once we run in NetBeans:

image

Now we need to download VisualVM, The tool actually, just like JStack ships in JDK, or it’s a quick download from Project Kenai site – http://visualvm.java.net/.  I downloaded latest stable version

 

image

Once you downloaded and launched executable ( on Windows visualvm.exe) from /bin folder you see this:

image

On left pane you will see my two instances of code running in NetBeans – latest is pid 1919. Right click on the icon and you can create Thread Dump:

Once its created you will see thread dump right under the pid you clicked:

image

And here in the thread dump output in the right pain you can see easily all of the details on our deadlock –

2014-08-16 17:47:06
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.25-b01 mixed mode):

"DestroyJavaVM" prio=6 tid=0x000000000213d800 nid=0x4164 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"t3" prio=6 tid=0x000000001b779000 nid=0x37c4 waiting for monitor entry [0x000000001e02f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at threaddeadlock.SyncThread.run(SyncThread.java:28)
	- waiting to lock <0x0000000756456b20> (a java.lang.Object)
	- locked <0x0000000756456b40> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
	- None

"t2" prio=6 tid=0x000000001b778800 nid=0x1ff0 waiting for monitor entry [0x000000001df2f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at threaddeadlock.SyncThread.run(SyncThread.java:28)
	- waiting to lock <0x0000000756456b40> (a java.lang.Object)
	- locked <0x0000000756456b30> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
	- None

"t1" prio=6 tid=0x000000001b777800 nid=0x1824 waiting for monitor entry [0x000000001de2f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at threaddeadlock.SyncThread.run(SyncThread.java:28)
	- waiting to lock <0x0000000756456b30> (a java.lang.Object)
	- locked <0x0000000756456b20> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
	- None

"Service Thread" daemon prio=6 tid=0x000000001b753000 nid=0x62b4 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread1" daemon prio=10 tid=0x000000001b750800 nid=0x653c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread0" daemon prio=10 tid=0x000000001b74e800 nid=0x61ec waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Attach Listener" daemon prio=10 tid=0x000000001b74b800 nid=0x2f80 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Signal Dispatcher" daemon prio=10 tid=0x000000001b746800 nid=0x4718 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Finalizer" daemon prio=8 tid=0x000000001b6e1000 nid=0x314c in Object.wait() [0x000000001d72f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000756405798> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
	- locked <0x0000000756405798> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:189)

   Locked ownable synchronizers:
	- None

"Reference Handler" daemon prio=10 tid=0x000000001b6d9800 nid=0x55ec in Object.wait() [0x000000001d62f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000756405320> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:503)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
	- locked <0x0000000756405320> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:
	- None

"VM Thread" prio=10 tid=0x000000001b6d4000 nid=0x2c74 runnable 

"GC task thread#0 (ParallelGC)" prio=6 tid=0x0000000001f4e800 nid=0x50c8 runnable 

"GC task thread#1 (ParallelGC)" prio=6 tid=0x0000000001f50800 nid=0x4a58 runnable 

"GC task thread#2 (ParallelGC)" prio=6 tid=0x0000000001f52000 nid=0x5264 runnable 

"GC task thread#3 (ParallelGC)" prio=6 tid=0x0000000001f53800 nid=0x860 runnable 

"GC task thread#4 (ParallelGC)" prio=6 tid=0x0000000001f57000 nid=0x6290 runnable 

"GC task thread#5 (ParallelGC)" prio=6 tid=0x0000000001f59000 nid=0x5de4 runnable 

"GC task thread#6 (ParallelGC)" prio=6 tid=0x0000000001f5c000 nid=0x4968 runnable 

"GC task thread#7 (ParallelGC)" prio=6 tid=0x0000000001f5d800 nid=0x6180 runnable 

"VM Periodic Task Thread" prio=10 tid=0x000000001b76b000 nid=0x5fc4 waiting on condition 

JNI global references: 108


Found one Java-level deadlock:
=============================
"t3":
  waiting to lock monitor 0x000000001e031588 (object 0x0000000756456b20, a java.lang.Object),
  which is held by "t1"
"t1":
  waiting to lock monitor 0x000000001b6df378 (object 0x0000000756456b30, a java.lang.Object),
  which is held by "t2"
"t2":
  waiting to lock monitor 0x000000001b6e07d0 (object 0x0000000756456b40, a java.lang.Object),
  which is held by "t3"

Java stack information for the threads listed above:
===================================================
"t3":
	at threaddeadlock.SyncThread.run(SyncThread.java:28)
	- waiting to lock <0x0000000756456b20> (a java.lang.Object)
	- locked <0x0000000756456b40> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:724)
"t1":
	at threaddeadlock.SyncThread.run(SyncThread.java:28)
	- waiting to lock <0x0000000756456b30> (a java.lang.Object)
	- locked <0x0000000756456b20> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:724)
"t2":
	at threaddeadlock.SyncThread.run(SyncThread.java:28)
	- waiting to lock <0x0000000756456b40> (a java.lang.Object)
	- locked <0x0000000756456b30> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:724)

Found 1 deadlock.

But VisualVM is more than JStack on steroids. As I stated you can troubleshoot memory issues with heap dumps, and even use it as profiler to see where application is spending its time via snapshots.  Below for example JVM resource utilization in remote Tomcat via VisualVM:

image

Profiling, however, isn’t something you will do in production, but periodic thread stack dumps are quite an affective weapon to troubleshoot all kinds of hangs and performance issues, including such complex and dreaded as threading deadlock as you can see above.

For more see – http://visualvm.java.net/, http://docs.oracle.com/javase/7/docs/technotes/guides/visualvm/ and http://docs.oracle.com/javase/8/docs/technotes/guides/visualvm/intro.html

Advertisements

One thought on “Ambulans Mortuus – Troubleshooting JVM Thread Deadlock with VisualVM

  1. Pingback: Let Me Count The Ways – Various methods of generating stack dump for JVM in production | A posteriori

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s