VisualVM - Thread dumps - Generating and analyzing Thread Dumps using VisualVM - step by step detail to setup VisualVM with screenshots in java
Contents of page :
  • VisualVM
  • 10 steps to setup VisualVM  >
    • In step 10 > Few Terminology used
  • complete logs generated >


VisualVM > VisualVM is most popular way to generate Thread Dump and is most widely used by developers. It’s important to understand usage of VisualVM for in depth knowledge of VisualVM. I’ll recommend every developer must understand this topic to become master in multi threading.
It helps us in analyzing threads performance, thread states, CPU consumed by threads, garbage collection and much more.




10 steps to setup VisualVM  >
First of all we will learn how to setup VisualVM in eclipse in windows platform.
Step 1) First we are going to download VisualVM Launcher(Eclipse 3.6+) depending on your eclipse version , extract downloaded zip file.
Click on Help > Install new software


Step 2)  Click on Add...
Then click on Local…
Select location of extracted zip files (done in step 1).


Step 3) Give name = “visualvm_launcher” or you may name it whatever you may like.
Click Ok.


Step 4)  Now, you will see this kind of wizard, check visualvm_launcher Launcher Feature
then click Next >  
Follow the instruction, it will ask you restart eclipse.


Step 5)
Software will start getting installed, wait for few moments, it may take up to 10 minutes.
Now our visualVm Launcher is installed and ready to use.


Now, we are left with only bit of configuration work.
step 6) Go to windows > Preference > type VisualVM
Select visualVM executable location
Select Jdk available on your system.


Step 7) Right click on class which you want to run visualVm Launcher
Step 8) Now multiple launchers are available to us , click on Select one...

Check Use configuration specific setting
Select ViusalVM Launcher
Click Ok.
Run button will become Active, and click on Run



Now, comes the most important and interesting section - Creating Thread Dump using VisualVM and analyzing them.


Step 9) Here we have used the Deadlock Program.
After clicking Run, Java VisualVM will be launched in another window automatically from eclipse.
Java VisualVM will be launched and there you can see system saying DeadLock detected.


Step 10)
Further, we can click Thread Dump button to analyze logs >
Before analyzing Thread dump, we must know Few Terminology used, which will help us in analyzing Thread dumps in comprehensive manner >
  • Thread Name : Name of the Thread.
Extract taken from Thread dump (It gives complete information about thread, i have highlighted specific field) :
"RMI TCP Connection(3)-10.175.2.71" daemon prio=6 tid=0x0000000011459000 nid=0x3bf4c runnable [0x00000000120ef000]


Extract taken from Thread dump (It gives complete information about thread, i have highlighted specific field) :
"RMI TCP Connection(3)-10.175.2.71" daemon prio=6 tid=0x0000000011459000 nid=0x3bf4c runnable [0x00000000120ef000]


  • Thread Priority : Priority of the thread can be between 1 to 10, where 1 is MIN_PRIORITY  and 10 is MAX_PRIORITY.
Extract taken from Thread dump (It gives complete information about thread, i have highlighted specific field) :
"RMI TCP Connection(3)-10.175.2.71" daemon prio=6 tid=0x0000000011459000 nid=0x3bf4c runnable [0x00000000120ef000]


  • tid (Thread id) :  Every thread is assigned a unique id. We can get this id by calling Thread.getId() method.
Extract taken from Thread dump (It gives complete information about thread, i have highlighted specific field) :
"RMI TCP Connection(3)-10.175.2.71" daemon prio=6 tid=0x0000000011459000 nid=0x3bf4c runnable [0x00000000120ef000]


  • nid (Native thread id) :  It gives us information about which thread is consuming most of CPU.
Extract taken from Thread dump (It gives complete information about thread, i have highlighted specific field) :
"RMI TCP Connection(3)-10.175.2.71" daemon prio=6 tid=0x0000000011459000 nid=0x3bf4c runnable [0x00000000120ef000]


  • daemon : Tells whether thread is daemon or not.
Extract taken from Thread dump (It gives complete information about thread, i have highlighted specific field) :
"RMI TCP Connection(3)-10.175.2.71" daemon prio=6 tid=0x0000000011459000 nid=0x3bf4c runnable [0x00000000120ef000]


  • Java stack information for the threads :  It gives us complete information about threads state, one should observe them carefully for detecting line numbers which are responsible for deadlock deadlock formation.
"Thread-2":
   at p13_0_createDeadlock.B.run(DeadlockCreation.java:43)
   - waiting to lock <0x00000007ab2009a0> (a java.lang.Class for java.lang.String)
   - locked <0x00000007ab2007e0> (a java.lang.Class for java.lang.Object)
   at java.lang.Thread.run(Unknown Source)
"Thread-1":
   at p13_0_createDeadlock.A.run(DeadlockCreation.java:18)
   - waiting to lock <0x00000007ab2007e0> (a java.lang.Class for java.lang.Object)
   - locked <0x00000007ab2009a0> (a java.lang.Class for java.lang.String)
   at java.lang.Thread.run(Unknown Source)


  • Finalizer : Gives information about reference objects. Reference objects are implemented in close cooperation with the garbage collector. It helps in freeing memory.
"Finalizer" daemon prio=8 tid=0x000000000f6a2000 nid=0x3bfc0 in Object.wait() [0x0000000010b9e000]
  java.lang.Thread.State: WAITING (on object monitor)


  • Reference Handler : It allows high-priority thread to execute after completion of previously queued threads i.e. high-priority thread to enqueue pending References.
"Reference Handler" daemon prio=10 tid=0x000000000f69a800 nid=0x3c0b8 in Object.wait() [0x000000001094f000]
  • VM Thread :  This thread is managed internally by hotspot VM.
"VM Thread" prio=10 tid=0x000000000f697000 nid=0x3c0d8 runnable


  • GC task thread : These threads are responsible for garbage collection.

"GC task thread#0 (ParallelGC)" prio=6 tid=0x000000000230c800 nid=0x3c078 runnable
"GC task thread#1 (ParallelGC)" prio=6 tid=0x000000000230e000 nid=0x3c070 runnable
"GC task thread#2 (ParallelGC)" prio=6 tid=0x000000000230f800 nid=0x390f4 runnable
"GC task thread#3 (ParallelGC)" prio=6 tid=0x0000000002311800 nid=0x3b5f0 runnable


  • VM Periodic Task Thread :  This thread is managed internally by hotspot VM.
"VM Periodic Task Thread" prio=10 tid=0x000000000f71c000 nid=0x3bd30 waiting on condition


  • JNI global references : It gives us count of number of objects which have live reference available to them in our java code. If object does not have any live reference available to it than that object’s count is not counted in JNI global reference and object is available for garbage collection.
JNI global references: 232



complete logs generated >
Now, I have mentioned complete logs generated. It shows us in detail that how threads went from RUNNING to WAITING state and then stayed in Waiting state. I have highlighted few important states of Thread, which will help you in analyzing logs very quickly.
2015-02-27 17:15:55
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.51-b03 mixed mode):
"RMI TCP Connection(3)-10.175.2.71" daemon prio=6 tid=0x0000000011459000 nid=0x3bf4c runnable [0x00000000120ef000]
  java.lang.Thread.State: RUNNABLE
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.read(Unknown Source)
   at java.net.SocketInputStream.read(Unknown Source)
   at java.io.BufferedInputStream.fill(Unknown Source)
   at java.io.BufferedInputStream.read(Unknown Source)
   - locked <0x00000007ae2a74a0> (a java.io.BufferedInputStream)
   at java.io.FilterInputStream.read(Unknown Source)
   at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
   at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
   at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
   at java.lang.Thread.run(Unknown Source)
  Locked ownable synchronizers:
   - <0x00000007abb0c600> (a java.util.concurrent.ThreadPoolExecutor$Worker)
"RMI TCP Connection(idle)" daemon prio=6 tid=0x0000000011766000 nid=0x3c150 waiting on condition [0x0000000012dff000]
  java.lang.Thread.State: TIMED_WAITING (parking)
   at sun.misc.Unsafe.park(Native Method)
   - parking to wait for  <0x00000007aba016c0> (a java.util.concurrent.SynchronousQueue$TransferStack)
   at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
   at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(Unknown Source)
   at java.util.concurrent.SynchronousQueue$TransferStack.transfer(Unknown Source)
   at java.util.concurrent.SynchronousQueue.poll(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
   at java.lang.Thread.run(Unknown Source)
  Locked ownable synchronizers:
   - None
"JMX server connection timeout 17" daemon prio=6 tid=0x000000001169e000 nid=0x3c2c4 in Object.wait() [0x00000000124cf000]
  java.lang.Thread.State: TIMED_WAITING (on object monitor)
   at java.lang.Object.wait(Native Method)
   - waiting on <0x00000007abddcff8> (a [I)
   at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(Unknown Source)
   - locked <0x00000007abddcff8> (a [I)
   at java.lang.Thread.run(Unknown Source)
  Locked ownable synchronizers:
   - None
"RMI Scheduler(0)" daemon prio=6 tid=0x000000001154f000 nid=0x3bef0 waiting on condition [0x00000000123ce000]
  java.lang.Thread.State: TIMED_WAITING (parking)
   at sun.misc.Unsafe.park(Native Method)
   - parking to wait for  <0x00000007aba19138> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
   at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
   at java.lang.Thread.run(Unknown Source)
  Locked ownable synchronizers:
   - None
"RMI TCP Accept-0" daemon prio=6 tid=0x000000001167e000 nid=0x3c35c runnable [0x0000000011f4e000]
  java.lang.Thread.State: RUNNABLE
   at java.net.DualStackPlainSocketImpl.accept0(Native Method)
   at java.net.DualStackPlainSocketImpl.socketAccept(Unknown Source)
   at java.net.AbstractPlainSocketImpl.accept(Unknown Source)
   at java.net.PlainSocketImpl.accept(Unknown Source)
   - locked <0x00000007aba27808> (a java.net.SocksSocketImpl)
   at java.net.ServerSocket.implAccept(Unknown Source)
   at java.net.ServerSocket.accept(Unknown Source)
   at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(Unknown Source)
   at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(Unknown Source)
   at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(Unknown Source)
   at java.lang.Thread.run(Unknown Source)
  Locked ownable synchronizers:
   - None
"DestroyJavaVM" prio=6 tid=0x000000000078e000 nid=0x3b95c waiting on condition [0x0000000000000000]
  java.lang.Thread.State: RUNNABLE
  Locked ownable synchronizers:
   - None
"Thread-2" prio=6 tid=0x0000000011451800 nid=0x3bb00 waiting for monitor entry [0x000000001082f000]
  java.lang.Thread.State: BLOCKED (on object monitor)
   at p13_0_createDeadlock.B.run(DeadlockCreation.java:43)
   - waiting to lock <0x00000007ab2009a0> (a java.lang.Class for java.lang.String)
   - locked <0x00000007ab2007e0> (a java.lang.Class for java.lang.Object)
   at java.lang.Thread.run(Unknown Source)
  Locked ownable synchronizers:
   - None
"Thread-1" prio=6 tid=0x0000000011451000 nid=0x3bf88 waiting for monitor entry [0x000000001196f000]
  java.lang.Thread.State: BLOCKED (on object monitor)
   at p13_0_createDeadlock.A.run(DeadlockCreation.java:18)
   - waiting to lock <0x00000007ab2007e0> (a java.lang.Class for java.lang.Object)
   - locked <0x00000007ab2009a0> (a java.lang.Class for java.lang.String)
   at java.lang.Thread.run(Unknown Source)
  Locked ownable synchronizers:
   - None
"Service Thread" daemon prio=6 tid=0x000000000f70b800 nid=0x3b9fc runnable [0x0000000000000000]
  java.lang.Thread.State: RUNNABLE
  Locked ownable synchronizers:
   - None
"C2 CompilerThread1" daemon prio=10 tid=0x000000000f707800 nid=0x3ba38 waiting on condition [0x0000000000000000]
  java.lang.Thread.State: RUNNABLE
  Locked ownable synchronizers:
   - None
"C2 CompilerThread0" daemon prio=10 tid=0x000000000f703000 nid=0x3b918 waiting on condition [0x0000000000000000]
  java.lang.Thread.State: RUNNABLE
  Locked ownable synchronizers:
   - None
"Attach Listener" daemon prio=10 tid=0x000000000f6fd800 nid=0x3c104 waiting on condition [0x0000000000000000]
  java.lang.Thread.State: RUNNABLE
  Locked ownable synchronizers:
   - None
"Signal Dispatcher" daemon prio=10 tid=0x000000000f6f6000 nid=0x3bb18 runnable [0x0000000000000000]
  java.lang.Thread.State: RUNNABLE
  Locked ownable synchronizers:
   - None
"Finalizer" daemon prio=8 tid=0x000000000f6a2000 nid=0x3bfc0 in Object.wait() [0x0000000010b9e000]
  java.lang.Thread.State: WAITING (on object monitor)
   at java.lang.Object.wait(Native Method)
   - waiting on <0x00000007ab205568> (a java.lang.ref.ReferenceQueue$Lock)
   at java.lang.ref.ReferenceQueue.remove(Unknown Source)
   - locked <0x00000007ab205568> (a java.lang.ref.ReferenceQueue$Lock)
   at java.lang.ref.ReferenceQueue.remove(Unknown Source)
   at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)
  Locked ownable synchronizers:
   - None
"Reference Handler" daemon prio=10 tid=0x000000000f69a800 nid=0x3c0b8 in Object.wait() [0x000000001094f000]
  java.lang.Thread.State: WAITING (on object monitor)
   at java.lang.Object.wait(Native Method)
   - waiting on <0x00000007ab2050f0> (a java.lang.ref.Reference$Lock)
   at java.lang.Object.wait(Object.java:503)
   at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
   - locked <0x00000007ab2050f0> (a java.lang.ref.Reference$Lock)
  Locked ownable synchronizers:
   - None
"VM Thread" prio=10 tid=0x000000000f697000 nid=0x3c0d8 runnable
"GC task thread#0 (ParallelGC)" prio=6 tid=0x000000000230c800 nid=0x3c078 runnable
"GC task thread#1 (ParallelGC)" prio=6 tid=0x000000000230e000 nid=0x3c070 runnable
"GC task thread#2 (ParallelGC)" prio=6 tid=0x000000000230f800 nid=0x390f4 runnable
"GC task thread#3 (ParallelGC)" prio=6 tid=0x0000000002311800 nid=0x3b5f0 runnable
"VM Periodic Task Thread" prio=10 tid=0x000000000f71c000 nid=0x3bd30 waiting on condition
JNI global references: 232
Found one Java-level deadlock:
=============================
"Thread-2":
 waiting to lock monitor 0x000000000f6a0388 (object 0x00000007ab2009a0, a java.lang.Class),
 which is held by "Thread-1"
"Thread-1":
 waiting to lock monitor 0x000000000f6a1828 (object 0x00000007ab2007e0, a java.lang.Class),
 which is held by "Thread-2"
Java stack information for the threads listed above:
===================================================
"Thread-2":
   at p13_0_createDeadlock.B.run(DeadlockCreation.java:43)
   - waiting to lock <0x00000007ab2009a0> (a java.lang.Class for java.lang.String)
   - locked <0x00000007ab2007e0> (a java.lang.Class for java.lang.Object)
   at java.lang.Thread.run(Unknown Source)
"Thread-1":
   at p13_0_createDeadlock.A.run(DeadlockCreation.java:18)
   - waiting to lock <0x00000007ab2007e0> (a java.lang.Class for java.lang.Object)
   - locked <0x00000007ab2009a0> (a java.lang.Class for java.lang.String)
   at java.lang.Thread.run(Unknown Source)
Found 1 deadlock.


/** JavaMadeSoEasy.com */
Application of VisualVM >
VisualVm can be very handy in detecting Deadlocks in multithreaded programs.




RELATED LINKS>


DeadLock and it’s detection >

Deadlock in multithreading - program to form DeadLock, solving DeadLock, measures to avoid Deadlock.

VisualVM - Thread dumps - Generating and analyzing Thread Dumps using VisualVM - step by step detail to setup VisualVM with screenshots

JSTACK - Thread dumps - Generating and analyzing Thread Dumps using JSATCK - step by step detail to setup JSTACK with screenshots

Reason why suspend() and resume() methods are deprecated and Deadlock prone

destroy() method in java - usage, reason why destroy() method is deprecated and Deadlock prone.




eEdit
Must read for you :