Performance Analysis By jstack Practice

1. Background

Tomcat 7.0, JDK 1.7, Linux

The application based on spring framework, powered by CometD to push price feed and a multi-threaded back end.

The application also use Redis heavily.

The application depends on third party web service heavily.

Very poor performance, can support less than 60 clients simultaneously.

2. Thread Dump Analysis

As web service calling would block a thread for remarkable time, my first strategy is to analyze blocked threads.

2.1 Know your Tomcat thread pool setting

2.2 jstack analysis

2.2.1 Get the Process ID (PID)

For applications hosted by Tomcat

ps -ef | grep tomcat

For standalone applications, you can refer to reference [3], use thetopcommand.

2.2.2 Get the Thread ID if you target a particular thread

You need to know different thread ID type first.

(1) JVM thread ID in decimal (TID)

(2) Native thread ID in decimal (NID)

(3) Native thread ID in hexadecimal (NID), you need this kind of thread id to analyze jstack thread dump.

Now we can use the top command to get the thread id now.

2.2.3 jstack thread dump

./jstack ${PID} > jstackdump.log

2.2.4 Thread Dump Analysis

Note that there are various thread states, we need to understand each state's meaning first.

typical example:

"Keep-Alive-Timer" daemon prio=10 tid=0x00007fc5d163a000 nid=0x5c85 waiting on condition [0x00007fc5accf3000]   java.lang.Thread.State: TIMED_WAITING (sleeping)at java.lang.Thread.sleep(Native Method)at sun.net.www.http.KeepAliveCache.run(KeepAliveCache.java:172)at java.lang.Thread.run(Thread.java:722)"Attach Listener" daemon prio=10 tid=0x00007fc5f8047800 nid=0x5c81 waiting on condition [0x0000000000000000]   java.lang.Thread.State: RUNNABLE"org.springframework.scheduling.concurrent.ScheduledExecutorFactoryBean#0-10" prio=10 tid=0x00007fc5d8047000 nid=0x55e9 waiting on condition [0x00007fc5acf5d000]   java.lang.Thread.State: WAITING (parking)at sun.misc.Unsafe.park(Native Method)- parking to wait for  <0x00000000db89ca50> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1085)at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)at java.lang.Thread.run(Thread.java:722)"javamelody bas-log" daemon prio=10 tid=0x00007fc5d0f23000 nid=0x4d1f in Object.wait() [0x00007fc621f8d000]   java.lang.Thread.State: TIMED_WAITING (on object monitor)at java.lang.Object.wait(Native Method)- waiting on <0x00000000d1bdf998> (a java.util.TaskQueue)at java.util.TimerThread.mainLoop(Timer.java:552)- locked <0x00000000d1bdf998> (a java.util.TaskQueue)at java.util.TimerThread.run(Timer.java:505)"Finalizer" daemon prio=10 tid=0x00007fc628125000 nid=0x4cea in Object.wait() [0x00007fc623990000]   java.lang.Thread.State: WAITING (on object monitor)at java.lang.Object.wait(Native Method)- waiting on <0x00000000d0336f70> (a java.lang.ref.ReferenceQueue$Lock)at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)- locked <0x00000000d0336f70> (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)"VM Thread" prio=10 tid=0x00007fc62811b800 nid=0x4ce8 runnable "Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x00007fc628011800 nid=0x4ce3 runnable "Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x00007fc628013800 nid=0x4ce4 runnable "Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x00007fc628015000 nid=0x4ce5 runnable "Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x00007fc628017000 nid=0x4ce6 runnable "Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00007fc6280a6000 nid=0x4ce7 runnable "VM Periodic Task Thread" prio=10 tid=0x00007fc6282ce000 nid=0x4cf3 waiting on condition JNI global references: 431

Let's take a look at Java documentation about thread state.

public static enum Thread.Stateextends Enum<Thread.State>A thread state. A thread can be in one of the following states:    NEW    A thread that has not yet started is in this state.    RUNNABLE    A thread executing in the Java virtual machine is in this state.    BLOCKED    A thread that is blocked waiting for a monitor lock is in this state.    WAITING    A thread that is waiting indefinitely for another thread to perform a particular action is in this state.    TIMED_WAITING    A thread that is waiting for another thread to perform an action for up to a specified waiting time is in this state.    TERMINATED    A thread that has exited is in this state.A thread can be in only one state at a given point in time. These states are virtual machine states which do not reflect any operating system thread states.

we can 5 states in our thread dump as following:
TIMED_WAITING (sleeping)
TIMED_WAITING (on object monitor)
RUNNABLE
WAITING (parking)
WAITING (on object monitor)

Quoted from reference [4], Permit means a permission to continue execution. Parking means suspending execution until permit is available.

In reference [5], we can see the more detailed thread state meaning.

A thread can be in only one state at a given point in time. These states are virtual machine states which do not reflect any operating system thread states. As an example, here shows different threads in different states on a HotSpot VM:$ cat thread.tmp | grep "java.lang.Thread.State" | sort | uniq -c      3    java.lang.Thread.State: BLOCKED (on object monitor)     18    java.lang.Thread.State: RUNNABLE      6    java.lang.Thread.State: TIMED_WAITING (on object monitor)      2    java.lang.Thread.State: TIMED_WAITING (sleeping)     13    java.lang.Thread.State: WAITING (on object monitor)      3    java.lang.Thread.State: WAITING (parking)Below we describe some of the thread states that can be found in a thread dump:    NEW - this state represents a new thread which is not yet started.    RUNNABLE - this state represents a thread which is executing in the underlying JVM. Here executing in JVM doesn't mean that the thread is always executing in the OS as well - it may wait for a resource from the Operating system like the processor while being in this state.    BLOCKED (on object monitor)- this state represents a thread which has been blocked and is waiting for a moniotor to enter/re-enter a synchronized block/method. A thread gets into this state after calling Object.wait method.    WAITING - this state represnts a thread in the waiting state and this wait is over only when some other thread performs some appropriate action. A thread can get into this state either by calling - Object.wait (without timeout), Thread.join (without timeout), or LockSupport.park methods.    TIMED_WAITING - this state represents a thread which is required to wait at max for a specified time limit. A thread can get into this state by calling either of these methods: Thread.sleep, Object.wait (with timeout specified), Thread.join (with timeout specified), LockSupport.parkNanos, LockSupport.parkUntil    TERMINATED - this state reprents a thread which has completed its execution either by returning from the run() method after completing the execution OR by throwing an exception which propagated from the run() method and hence caused the termination of the thread.    WAITING (parking)- it means a wait state after being parked. A thread can suspend its execution until permit is available (or thread is interrupted, or timeout expired, etc) by calling park(). You can give permit to a thread by calling unpark(). When permit is available, the parked thread consumes it and exits a park() method. Unlike Semaphore's permits, permits of LockSupport are associated with threads (i.e. permit is given to a particular thread) and doesn't accumulate (i.e. there can be only one permit per thread, when thread consumes the permit, it disappears).

Reference:

[1] <Java Performance: The Definitive Guide> 

[2] http://www.cnblogs.com/zhengyun_ustc/archive/2013/03/18/tda.html

[3] http://loudou.info/blog/2014/03/01/yong-jstack-xian-cheng-ding-wei-chu-ti-yan/

[4] http://stackoverflow.com/questions/7497793/understanding-java-lang-thread-state-waiting-parking

[5] http://xmlandmore.blogspot.hk/2012/08/understanding-jvm-thread-states.html