Classic Heap Dump Analysis in JVM Using JMap and JHat

In last couple of posts I have shown how to use various tools that are shipped with JDK to troubleshoot various issues , such as hangs, by analyzing stacks. However, obviously there are times where you may have a suspected GC issue or memory leak in production and you will have to capture a heap dump using tools that ship with JDK as well. I already noted previously that Visual VM can be used for that task.

Just right-click on your pid of the process you wish to dump on left pane, pick “Heap Dump” and next you will see lots of information on right pane that may be of interest to you:

Below for example footprint of my class objects by instance count and size:

 

 

You can drill down further and see those roots holding these objects live, etc. To me interface and actions are very similar to SciTek .NET Heap Profiler I have used extensively in the past, so it makes it easy.

JMap is a tool that comes with JDK installation as well. Its perhaps less graphical than Visual VM above, but also smaller and has even less overhead for production troubleshooting use. To use it, just like with JStack we will need first to get pid that we are planning to dump:

C:\Program Files\Java\jdk1.7.0_25\bin>jps -l –m

12020 hangme2.HangMe2

30184 sun.tools.jps.

So in my case pid 12020 will need to be dumped.

C:\Program Files\Java\jdk1.7.0_25\bin>jmap -dump:file=C:\Users\gennadyk\Document s\NetBeansProjects\HangMe2.map 12020

Dumping heap to C:\Users\gennadyk\Documents\NetBeansProjects\HangMe2.map ...

Heap dump file created

Now, how do we analyze this dump? Heap dump files can be browsed by the heap dump browser – JHat. Again, as with JStack and JMap, need to do a bit of command line here:

C:\Program Files\Java\jdk1.7.0_25\bin>jhat C:\Users\gennadyk\Documents\NetBeansP
rojects\hangme2.map
Reading from C:\Users\gennadyk\Documents\NetBeansProjects\hangme2.map...
Dump file created Sun Aug 31 16:48:04 EDT 2014
Snapshot read, resolving...
Resolving 132221 objects...
Chasing references, expect 26 dots..........................
Eliminating duplicate references..........................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

Now lets point my browser to http://localhost:7000 and here is a report one can see:

And here is all my live roots\references as I click on hyperlink to drill down on my class:

So with a bit of command line we can now troubleshoot our memory utilization\leaks in JVM with minimal production overhead as needed. Hope above was useful and happy leak hunting.

More information on the tools –

JMap – http://docs.oracle.com/javase/7/docs/technotes/tools/share/jmap.html

JHat – http://docs.oracle.com/javase/7/docs/technotes/tools/share/jhat.html

Troubleshooting guide for Java 6 with HotSpot VM – http://www.oracle.com/technetwork/java/javase/memleaks-137499.html#gdyrr

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:

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

 

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

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:

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:

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

What Is On My Threads – Debugging Java Using JStack

Through the nature of my job for last decade I spend most of my time with Microsoft technologies. I have troubleshoot .NET, COM, IIS, SharePoint, BizTalk and of course SQL Server and as part of my job frequently used Microsoft Debugging Tools for Windows (WINDBG) and multitude of extensions for stability and performance troubleshooting and performance analysis. However, my current customer is a mixed shop with fairly large Java presence. Therefore systems I troubleshoot and tune fairly commonly interface with systems built in J2EE. Lots of times it surprised me that fairly common production debugging techniques that I used with Windows\Microsoft -centric applications were virtually unknown to Java developers that attempted to reproduce issues in production on their development workstation with Eclipse\NetBeans IDE to no avail or resorted to guessing and providing fixes for that guess.

Meanwhile, Java does have tools that can be used for production debugging. One of such tools is jstack. JStack is JVM troubleshooting tool that prints stack traces of all running threads of a given JVM process, a Java core file, or remote debug server. First I have seen tool in action with one of our banking clients on performance tuning engagement few years ago and it was useful. Below I will create a simple HangMe application that will allow me to create a “hang issue” and successfully show it via JStack.

Below is simple Java Console Application that uses Thread.Sleep to essentially create that hang:

package hangme;

/** * * @author gennadyk */

public class HangMe {

/** * @param args the command line arguments */

public static void main(String[] args) {

Runtime rt = Runtime.getRuntime();

System.out.println("Lets Go To Sleep");

try {Thread.sleep(1000*60*60);}

catch (InterruptedException e) {} }

}

Now lets compile and run this program. Next step is to run jps utility to get a PID for HangMe that is being executed:

C:\Program Files\Java\jdk1.7.0_25\bin>jps -l –m

26192 C:\Users\gennadyk\Documents\NetBeansProjects\HangMe2\dist\HangMe.jar

Now lets use JStack to get thread stack information on PID 26192

:\Program Files\Java\jdk1.7.0_25\bin>jstack 26192

2014-08-06 14:18:20 Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.65-b04 mixed mode):

"Service Thread" daemon prio=6 tid=0x00000000028b8000 nid=0x2d10 runnable [0x000 0000000000000] java.lang.Thread.State: RUNNABLE

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

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

"Attach Listener" daemon prio=10 tid=0x000000001b061000 nid=0x231c waiting on co ndition [0x0000000000000000] java.lang.Thread.State: RUNNABLE

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

"Finalizer" daemon prio=8 tid=0x000000001906e800 nid=0x1a34 in Object.wait() [0x 000000001b03f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000756405608> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(Unknown Source) - locked <0x0000000756405608> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(Unknown Source) at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

"Reference Handler" daemon prio=10 tid=0x0000000019068000 nid=0x2f98 in Object.w ait() [0x000000001af3f000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000756405190> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:503) at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source) - locked <0x0000000756405190> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x00000000027be000 nid=0x6758 waiting on condition [0x00000000 027af000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at hangme2.HangMe2.main(HangMe2.java:20) "VM Thread" prio=10 tid=0x0000000019064800 nid=0x24e0 runnable "GC task thread#0 (ParallelGC)" prio=6 tid=0x00000000027d7800 nid=0x40ec runnabl e "GC task thread#1 (ParallelGC)" prio=6 tid=0x00000000027d9800 nid=0x6648 runnabl e "GC task thread#2 (ParallelGC)" prio=6 tid=0x00000000027db000 nid=0x120c runnabl e "GC task thread#3 (ParallelGC)" prio=6 tid=0x00000000027dc800 nid=0x43fc runnabl e "GC task thread#4 (ParallelGC)" prio=6 tid=0x00000000027df000 nid=0x319c runnabl e "GC task thread#5 (ParallelGC)" prio=6 tid=0x00000000027e0800 nid=0x6068 runnabl e "GC task thread#6 (ParallelGC)" prio=6 tid=0x00000000027e4800 nid=0x2114 runnabl e "GC task thread#7 (ParallelGC)" prio=6 tid=0x00000000027e6000 nid=0xbb8 runnable "VM Periodic Task Thread" prio=10 tid=0x00000000028bc000 nid=0x26d0 waiting on c ondition JNI global references: 105

As you can see above you can easily note my Thread.Sleep call on main above as a wait cause.

Some more on JStack parameters

pId = Java process id (use jps to get the info)

exe = Java executable from which the core dump was produced.

core = core file for which the stack trace is to be printed.

remote-hostname-or-IP = Debug server’s (see jsadebugd) hostname or IP address.

server-id= (optional) unique server id

More on JStack – http://docs.oracle.com/javase/1.5.0/docs/tooldocs/share/jstack.html and http://docs.oracle.com/javase/7/docs/technotes/tools/share/jstack.html