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


Contents of page :
  • jstack
  • 7 steps to setup JSTACK  >
    • In step 7 > Few Terminology used
  • complete logs generated >



jstack > jstack is very easy way to generate Thread dump and is widely used by developers. I’ll recommend every developer must understand this topic to become master in multi threading. For creating Thread dumps we need not to download any jar or any extra software.
It helps us in analyzing threads performance, thread states, CPU consumed by threads, garbage collection and much more.

7 steps to setup JSTACK  >
Let’s see how we can generate Thread dumps using jstack.

step 1) Go to Task Manager
click on Processes

step 2) Click on View,
than on Select Option

step 3) Check PID (Process Identifier)
than click Ok

step 4) You will see a new column PID generated, select PID of javaw.exe i.e. Process identifier of java.



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

Step 7) Go to CMD
And execute following commands :
cd C:\Program Files\Java\jdk1.7.0_51\bin
jstack.exe -l 245408   (where 245408 is PID)
And Thread Dump will be generated in cmd.

You may dump the generated Thread Dump in text file as well by using following command :
jstack.exe -l 245408 > ThreadDump.txt  (where ThreadDump.txt will be created on path=C:\Program Files\Java\jdk1.7.0_51\bin)

Step 6) Please note :  I have generated Thread dumps for following DeadLock program.

Executing the above command has generated Thread Dump for us.

Step 7) Further, we can analyze Thread Dump >
Before analyzing Thread dump, we must know Few Terminology used, which will help us in analyzing Thread dumps in comprehensive manner >

  • Thread Dump : Thread gives complete information of threads created in our program and state transition of Threads. i.e. from new to dead state.

  • 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 jtack>

jstack 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.


No comments:

Post a Comment