Analyze Hanging Programs Using Java Thread Traces

In this article, we will discuss the following topics:

• How to analyze hanging, deadlocked or frozen programs?
• How to generate stack traces?
• What is deadlock?

What to Do When Your Applications Hang?

If you think your program is hanging, generate a stack trace.  A stack trace of all threads can be useful when trying to diagnose a number of issues such as deadlocks or hangs.

When looking at stack traces, check the following:

• If a thread waits on
• A monitor lock
• A condition variable
• If system threads show up as the current threads
• If the program is deadlocked then some of the system threads will probably show up as the current threads, because there is nothing else for the JVM to do

How to Generate Stack Traces?

With thread stack trace, you can analyze the source of deadlocks.  There are multiple approaches:

• Using jstack command, it can 
• attach to the specified process (or core file) and prints the stack traces of all threads that are attached to the virtual machine (this includes Java threads and VM internal threads).
• For each Java frame, the full class name, method name, 'bci' (byte code index) and line number, if available, are printed.
• Obtain stack traces from a core dump:
• jstack $JAVA_HOME/bin/java core
• Be used to print a mixed stack.  That is, it can print native stack frames in addition to the java stack. 
• • Native frames are the C/C++ frames associated with VM code, and JNI/native code.
  • To print a mixed stack the -m option is used.
• When a deadlock occurs, doing a Ctrl + Break on Windows forces a Java level thread stack trace to print to standard output. On Solaris and Linux, sending a SIGQUIT signal to the Java process id does the same.
• Beginning with Java 6, the bundled JConsole tool added the capability to attach to a hung Java process and analyze the root cause of the deadlock.

What Is Deadlock?

If you're working with a moderately complex multithreaded program, then sooner or later, you'll hit the problem of deadlock^[2,3].  Deadlock is the phenomenon when, typically, two threads each hold an exclusive lock that the other thread needs in order to continue.  In principle, there could actually be more threads and locks involved. Most of the time, a deadlock is caused by acquiring locks in the wrong order.

Deadlock can occur with any locking primitive. It notably occurs with the synchronized keyword, but it's liable to occur with locks, Semaphores, blocking queues etc.

A Deadlock Example

We used jstack to generate Java thread traces as follows:
$ jstack 3554

Our VM is HotSpot Client from JDK 7:

Found one Java-level deadlock:
=============================
"RunLevelControllerThread-1377458723460":
  waiting to lock monitor 0x871756a8 (object 0x93480480, a java.util.logging.LogManager$LoggerContext),
  which is held by "RunLevelControllerThread-1388458723457"
"RunLevelControllerThread-1388458723457":
  waiting to lock monitor 0x87173448 (object 0x93472290, a java.util.logging.LogManager),
  which is held by "RunLevelControllerThread-1377458723460"

Java stack information for the threads listed above:
===================================================
"RunLevelControllerThread-1377458723460":
    at java.util.logging.LogManager$LoggerContext.findLogger(LogManager.java:489)
    - waiting to lock <0x93480480> (a java.util.logging.LogManager$LoggerContext)
    at java.util.logging.LogManager.getLogger(LogManager.java:910)
    at com.sun.enterprise.server.logging.LogManagerService.postConstruct(LogManagerService.java:412)
    - locked < x93472290> (a java.util.logging.LogManager)
    - locked <0x93465158> (a java.lang.Class for java.util.logging.Logger)


"RunLevelControllerThread-1388458723457":
    at java.util.logging.LogManager.drainLoggerRefQueueBounded(LogManager.java:811)
    - waiting to lock <0x93472290> (a java.util.logging.LogManager)
    at java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:511)
    - locked < x93480480> (a java.util.logging.LogManager$LoggerContext)

In the above example, you can see that two threads:

• RunLevelControllerThread-1377458723460 
• RunLevelControllerThread-1388458723457 

were waiting for locks that were held by each other.  This have created a deadlock.

References

1. jstack - Stack Trace
2. Deadlock
3. How to Avoid Deadlocks (Xml and More)