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)

Controlling Thread Pool Size in WebLogic Server

One of the critical areas that relate to the tuning of WebLogic Server is thread management^[1].  In previous versions of WebLogic Server, processing was performed in multiple execute queues. Different classes of work were executed in different queues, based on priority and ordering requirements, and to avoid deadlocks.  However, in WLS 9.0 and above, it uses a single thread pool, in which all types of work are executed.^[10] WebLogic Server prioritizes work based on rules you define, and run-time metrics, including the actual time it takes to execute a request and the rate at which requests are entering and leaving the pool.

Self-tuning Thread Pool^[7]

WebLogic uses work managers with a variable and self-tuning number of worker threads. By default, the self-tuning thread pool size limit is 400. This limit includes all running and idle threads, but does not include any standby threads. The size of thread pool grows and shrinks automatically to improve throughput.  Measurements are taken every 2 seconds and the decision to increase or decrease the thread count is based on the current throughput measurement versus past values.

Thread Management^[4]

If your server has four physical processors, theoretically you only need a thread pool with four threads. When you have more threads than there are CPU resources, the throughput may suffer. However, if your threads often make database connections or call some other long-running tasks where they need to wait, you do want to have more threads around so that the ones that aren't waiting can do some work.

In a 3-tiered architecture, you can also have a situation like this: the clients make requests coming into the application server faster than the database server can handle.  Then the clients keep adding requests on the application server until all its threads are busy, all of which just adds load to the database.  The more load you add to the application server that is overloaded, the worse you make the situation.  In other cases that clients cannot keep all threads on the application server busy and leave some of them idle, you may still lose throughput because the cache will be less efficient when a new thread takes a new request versus when a just-used thread takes a new request.

At any rate, tuning the size of thread pool is challenging and time consuming.  Internally Weblogic Server has many work managers configured for different types of work. If WLS runs out of threads in the self-tuning pool (because of system property -Dweblogic.threadpool.MaxPoolSize) due to being undersized, then important work that WLS might need to do could be starved.  While limiting the self-tuning would limit the default WorkManager and internally it also limits all other internal WorkManagers which WLS uses.  So, leaving that task to WebLogic Server seems to be a wise choice. 

However, there are some cases that we do need to set the size of thread pool manually.  For example, to make performance comparison between two different test cases, you may want to eliminate the thread-pool-size variance from the performance results.  In this article, we will show you how to set up minimum and maximum thread pool sizes and how to examine the results of the settings.

Controlling the Size of Thread Pool

There are different ways of changing the size of thread pool.  One way of doing it is by setting them from the command line:

• -Dweblogic.threadpool.MinPoolSize=5 -Dweblogic.threadpool.MaxPoolSize=5

By setting both MinPoolSize and MaxPoolSize to be the same value, we have forced WLS to use exactly five worker threads.  In our case, our two test cases will be compared with the same number of worker threads and prevent the self-tuning effects from contaminating our performance results.  In [8], it also tells us how to make similar changes via config.xml.

Threads Page on WLS Console

For a WebLogic Server administrator, the WLS console is indispensable for monitoring running server instances, including the various subsystems such as security, JTA, and JDBC. The Threads page on the WLS console provides information on the thread activity for the current server.  In Figure 1, it shows that there are five Active Execute Threads based on our configuration.  If we didn't configure the thread pool size, you could see number of Active Execute Threads changing dynamically due to WLS' self-tuning activities.


.

Default Execute Queue from Thread Dump

Besides monitoring number of worker threads from the WLS console, you can also examine them from the thread dump as generated from JStack^[3].

Unless you've customized the execute queue (or thread pool) that your application gets deployed to, you can look for "Default" execute queue.  In the dump file, you'll look for the threads marked as 'weblogic.kernel.Default' to see what's running.  As work enters an instance of WLS, it is placed in the default execute queue.  This work is then assigned to a worker thread that does the work on it.

$ grep weblogic.kernel.Default threadDump.fod1
"[STANDBY] ExecuteThread: '6' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00000000202d9800 nid=0x404a in Object.wait() [0x0000000040801000]
"[STANDBY] ExecuteThread: '5' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x0000000021813800 nid=0x3d13 in Object.wait() [0x000000004c52d000]
"[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaabc0c6800 nid=0x3811 runnable [0x000000004a107000]
"[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaabc0c5000 nid=0x3810 in Object.wait() [0x000000004a008000]
"[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaabc0c1800 nid=0x380f in Object.wait() [0x0000000049f06000]
"[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaabc0db800 nid=0x380e in Object.wait() [0x000000004194e000]
"[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaabc0bc800 nid=0x380d in Object.wait() [0x000000004184d000]

As shown above, you can find there are seven instances of 'weblogic.kernel.Default (self-tuning)'.  Five of them are active and two of them are in standby.^[11]  These five active instances match what we've found as "Active Execute Thread" on the WLS console.

References

1. Oracle WebLogic Server 11g Administration Handbook by Sam Alapati
2. Using Work Managers to Optimize Scheduled Work
3. Fun with JStack by Scott Oaks
4. Rewritten from personal's email exchanges with Scott Oaks
5. Monitoring WebLogic Server Thread Pool at Runtime
6. Understanding JVM Thread States
7. Self-Tuning Thread Pool
8. Tuning Default WorkManager - Advantages and Disadvantages
9. Fusion Middleware Performance and Tuning for Oracle WebLogic Server
10. Understanding the Differences Between Work Managers and Execute Queues
11. STANDBY thread (WLS)
• ACTIVE threads can go to STANDBY when it is deemed that you don’t need that many active threads.
• But, a STANDBY thread can still be used (without transitioning to ACTIVE) in order to satisfy a min threads constraint.
12. Top Tuning Recommendations for WebLogic Server (12.2.1.3.0)
13. Analyzing Thread Dumps in Middleware - Part 2