This article discusses troubleshooting techniques for Java applications by analyzing Java thread dumps. We can use thread dumps to analyze situations like application hang, poor application response times, and application crash. Before getting into the details of analyzing the thread dumps, let's look briefly at the thread dump itself.

A Java thread dump is a snapshot of all the Java threads in a running Java application. It shows information like the current stack trace, state, and name of the threads. The list of threads includes the threads created by the JVM itself (to do housekeeping work like garbage collection, signal handling, etc.) and the threads created by the application.

You can get a thread dump by sending a SIGQUIT signal to the JVM. In case of Unix operating systems (Solaris/Linux/HP-Unix etc), this can be done by the "kill -3 <pid>" command. In the case of Windows, you can do a "ctrl-break" in the command window to get the thread dump. The thread dump is printed to the stdout or stderr of the JVM. The application will continue running normally after printing the dump. When you send the SIGQUIT signal to the JVM, the signal handler of the JVM responds to this signal by printing the thread dump. You can take thread dumps at any point while the application is running.

A Sample Thread Dump
Listing 1 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 Listing 1

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

  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.

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

The following is a sample stack trace of a thread in this 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.

Thread Dump from a Deadlocked Application
In Listing 2 (only part of the thread dump is shown), you can see that the JVM has found the deadlock and it has given that information along with the thread dump. It clearly says that the "ExecuteThread: '47' for queue: 'default'" is waiting to lock an object that has been locked by "ExecuteThread: '57' for queue: 'default'". (This thread dump is from a WebLogic Server. These threads are WebLogic Server's worker threads, which process the client requests.) At the same time, ExecuteThread: '47' has locked an object for which ExecuteThread: '57' is waiting. This is a deadlock. Both the threads will never move from this state, waiting for the other thread to release the lock.

In Listing 2, Execute thread: 1 is waiting to lock the "ConnectionScavanger" object, but this has been locked by thread 47, which is in a deadlock with thread 57 as mentioned before. Therefore, Execute thread: 1 also won't move further. This will eventually result in a hang because the other execute threads in the server will also try to get the lock for the same objects locked by Execute thread: 47 and 57 at some later time.

In some JVMs, the JVM will not give the deadlock information. It will just give the thread dump. In that case, we can arrive at this same conclusion by looking at the state and stack trace of the threads.

In this case the problem was due to a bug in WebLogic that was later fixed.

Other Hang Scenarios
In some scenarios, you may see that most of the threads are "runnable" but the server may appear hung and won't respond to client requests. If the threads are doing IO, they may be blocked in read() - the state will be "runnable" (database or some other network response may be poor). If this is the case, you need to check the health of the database and network.

Other reasons for a "runnable" thread to be stuck at the same place could be:

• An infinite looping in the code. This may also lead to high CPU usage.
• JVM garbage collection may be running for a long time, taking most of the CPU.
• The JVM process might have run out of file descriptors.

If the application code calls wait() or sleep(), the threads won't move for the specified sleep time - the state of the threads in this case will be "Waiting on Monitor". In this scenario, check the application code.

A lot of contention for a single object may also slow down the performance of the system, which may eventually lead to a hang-like situation. In this scenario, the state of most of the threads is "Waiting for monitor entry". The application code needs to be investigated to reduce the contention on that particular object. The threads may also be waiting to get a response from another server and the other server may be hung for a different reason and it may not be able to send the response to this server.

In all of the above scenarios, it is also required that you take multiple thread dumps with a few seconds interval so that you can compare the state of a particular thread in all the thread dumps and you can decide whether the thread is moving or stuck.

JVM Crash Scenarios
A JVM crash can happen due to:

1. Bugs in the JVM library
2. Incorrect use of JNI APIs by the application
3. Bugs in the native modules used by the application - native database drivers, etc.

Normally, when the JVM crashes it gives the stack trace of the Java thread that caused the crash. Some JVMs give a complete thread dump (stack trace of all the threads) before exiting. Our interest in those thread dumps is to find which thread was running when the crash happened. This thread is called as a "current thread". If the JVM gives a complete thread dump, it marks the "current thread". Therefore, generally it's easy to find the thread that caused the crash.

Note that the crash dump usually goes to stdout/stderr. The JVM may also generate a core file, which will be in binary format.

Sample Crash Dump
If you look at the crash dump in Listing 3 you can see that the thread that caused the crash has the following stack trace:

Current Java thread:
at com.aaa.bbb.qqq.Direct.setString(Native Method)
at com.aaa.bbb.qqq.PreparedStatement.setString(PreparedStatement.java:51)
- locked <0x45029c60> (a com.aaa.bbb.qqq.PreparedStatement)

The last method executed (setString) was a "native method" in the class "com.aaa.bbb.qqq.Direct". Therefore, we can guess that this crash is due to the native code in the implementation of the setString method. It could also be due to the JVM library code that has the implementation for the JNI API.

You can also see that the JVM gave the following in the dump:

Unexpected Signal : 11 occurred at PC=0x403AC9D1
Function=(null)+0x403AC9D1
Library=/opt/sunjdk/1.4.1_01-b01/jre/lib/i386/client/libjvm.so
# HotSpot Virtual Machine Error : 11
# Error ID : 4F530E43505002E6
# Please report this error at
# http://java.sun.com/cgi-bin/bugreport.cgi

This means that the code that caused the crash (PC=0x403AC9D1) is part of the JVM library: "/opt/sunjdk/1.4.1_01-b01/jre/lib/i386/client/libjvm.so". This doesn't mean that this is necessarily a JVM bug. Even though the instruction that caused the crash is in the JVM code, the crash could be due to a JNI call made by the application code (in this case, the implementation of the native method "setString") that could have passed some incorrect arguments, which caused the crash in the JVM module.

If you don't have the "current thread" info in the dump, then we need to analyze core dumps. This is out of the scope of this document.

Comments

Search

!joomlacomment 4.0 Copyright (C) 2009 Compojoom.com . All rights reserved."