Tuesday, September 29, 2009

Analyzing Java Thread Dump - "main" thread

A Sample Thread Dump

Below is a sample thread dump from a single-threaded application that is using the Sun JVM 1.4.1.

  • The thread named "main" is the main application thread.
  • All other threads are created by the JVM to do housekeeping work.
  • While analyzing application-level problems, we generally focus only on the application threads.
Let's analyze the stack trace of the "main" thread from below TD

"main" prio=5 tid=0x002358B8 nid=0x7f8 runnable [6f000..6fc40] at test.method1(test.java:10) at test.main(test.java:5)

From this code snippet you can see that a thread stack trace has a
name,
thread priority (prio=5),
state (runnable),
source code line numbers,
and the method calls.

You can conclude from this stack trace that the thread "main" is executing some code in the method "method1" of class "test". The call to this method came from the method "main" of the same class. You can also see the exact source code line numbers in those methods.

Before moving on to analyzing thread dumps from more complex scenarios, let's discuss the different state of threads that we normally see in the thread dumps and what they mean.

  • Runnable: Either running or ready to run when it gets its CPU turn. JRockit thread dumps refer to this state as ACTIVE.
  • Waiting on monitor: Either sleeping or waiting on an object for said period of time or waiting to be notified by another thread. This will happen when any of the sleep() methods on Thread object or wait() method on an Object is called.
  • Waiting for monitor entry: Waiting to lock an object (some other thread may be holding the lock). This happens if two or more threads try to execute some synchronized code blocks/methods of an object at the same time. Please note that the lock is always for an object and not for individual methods. That is, if a thread has to execute a synchronized method of an object, it has to first lock that object.
For example, in BEA WebLogic Server the idle execute threads are in this condition and they wait until a socket reader thread notifies them of some new work to be done. The stack trace will look like this:

"ExecuteThread: '2' for queue: 'weblogic.admin.RMI'" daemon prio=5 tid=0x1752F040 nid=0x180c in Object.wait() [1887f000..1887fd8c] at java.lang.Object.wait(Native Method) waiting on <04134d98> (a weblogic.kernel.ExecuteThread) at java.lang.Object.wait(Object.java:426)

Some other versions of the JVM call this state CW. JRockit and refers to this state as WAITING.

The following is a sample stack trace of a thread in "Waiting for monitor entry" condition:

"ExecuteThread: '24' for queue: 'DisplayExecuteQueue'" daemon prio=5 tid=0x5541b0 nid=0x3b waiting for monitor entry [49b7f000..49b7fc24] at weblogic.cluster.replication.ReplicationManager.createSecondary (ReplicationManager.java:908)
- waiting to lock <6c4b9130> (a java.lang.Object) at weblogic.cluster.replication.ReplicationManager.updateSecondary (ReplicationManager.java:715)

In this snippet you can see that this thread holds the lock on an object (6c408700) and is waiting to lock another object (6c4b9130).

Some other version of a JVM may not give the object IDs lock information in the stack trace. In those cases, we can guess that the thread is waiting to lock the object from the state of the thread. The same state may also be called as "MW". JRockit refers to this state as LOCKED.

Now, let's see some thread dumps from different scenarios and analyze them to find the problem in the application.

No comments: