Using Java Thread Dumps to Diagnose Application Performance

On a holiday weekend last year, I got an emergency call from a client. One of their Java EE applications would freeze and stop servicing users within an hour after container start-up. I was called in to help investigate. I started off by requesting a thread dump and memory dump of the container once it had stopped accepting requests. It's the thread dump that I'm focusing on today.  That Java thread-dump is here (package scrubbed to protect the client).

During that exercise, I noticed that when I analyze thread dumps, I look for the same things. Whether it's a performance issue or some sort of freezing issue, I manually scanned the thread dump for the same types of conditions. This year, working for another client, I'm faced with a performance tuning exercise that will likely require analysis of numerous thread dumps and wasn't looking forward to the busy work. That prospect got me to do some introspection and figure out exactly what I look for and find or build a product that does this.

Threads that block other threads

Most developers know the syntax behind using Java's synchronized keyword and that it's used to ensure that one and only one thread executes a section of code or uses a given Java resource at one time. I'm not going to digress into a discussion of lock monitors and coding issues; if you need a refresher, please see this article. Most experienced developers use synchronization with extreme care as bugs with synchronization are intermittent and extremely hard to diagnose and fix.

Frequent symptoms of synchronization issues are performance problems or cases where applications freeze and no longer accept client requests. Essentially, synchronization causes other threads servicing other client requests to wait until the needed Java resource is available for use. Those waiting client threads are typically in a BLOCKED state. I immediately suspected this type of issue in diagnosing the issue I was investigating over the holiday last weekend.  Here's a sample of a BLOCKED thread entry in a thread dump:

"http-bio-10.13.0.222-30105-exec-427" daemon prio=6 tid=0x000000001cf24000 nid=0x2054 waiting for monitor entry [0x0000000022f9c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
 at java.beans.Introspector.getBeanInfo(Introspector.java:160)
 - waiting to lock <0x0000000680440048> (a com.sun.beans.WeakCache)
 at org.apache.axis.utils.BeanUtils$1.run(BeanUtils.java:92)
 at java.security.AccessController.doPrivileged(Native Method)

Note that the dump explicitly lists that it's waiting on resource 0x0000000680440048 which is owned by this thread:

"http-bio-10.13.0.222-30105-exec-289" daemon prio=6 tid=0x000000001bf06000 nid=0x21b0 runnable [0x000000002e0dd000]
   java.lang.Thread.State: RUNNABLE
 at java.lang.Class.getDeclaredMethods0(Native Method)
 at java.lang.Class.privateGetDeclaredMethods(Class.java:2521)
 at java.lang.Class.privateGetPublicMethods(Class.java:2641)
 at java.lang.Class.getMethods(Class.java:1457)
 at java.beans.Introspector.getPublicDeclaredMethods(Introspector.java:1280)
 - locked <0x0000000680440048> (a com.sun.beans.WeakCache)
 at java.beans.Introspector.internalFindMethod(Introspector.java:1309)

It turns out that more than one thread was waiting on this resource.

IO bound threads

One frequent source of application performance issues are threads that are waiting on Input/Output to occur. This often takes the form of a database read or write or a service call of some type.  Many developers assume that most performance issues are caused by slow database access and start looking at SQL queries. I do not make this assumption. Furthermore, if it is a database tuning issue, you need to identify the specific SQL that needs to be tuned. At any rate, if the source of your performance issue is IO, thread dumps can help you identify where in your code the issue is taking place. 

Here is an example thread that's IO-bound:

"QuartzScheduler_Worker-2" prio=6 tid=0x000000001abc7000 nid=0x2208 runnable [0x000000001df3e000]
   java.lang.Thread.State: RUNNABLE
 at java.net.SocketInputStream.socketRead0(Native Method)
 at java.net.SocketInputStream.read(SocketInputStream.java:152)
 at java.net.SocketInputStream.read(SocketInputStream.java:122)
 at java.io.DataInputStream.readFully(DataInputStream.java:195)
 at java.io.DataInputStream.readFully(DataInputStream.java:169)
 at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:850)
 at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:731)

... (many thread stack entries omitted for brevity)

        at com.jmu.scholar.dao.FormRuleDAO.findByFormId(FormRuleDAO.java:50)

Note that within the thread stack, there's an explicit reference to application code that's initiating the IO. In this case, IO is being initiate by a database query in a specific application method. 

Note that just because the dump caught this one occurrence of this query, doesn't mean it's a performance issue. If, however, a large percentage of running threads are IO-bound in the same method, then this database access would become a tuning target. To tune this specific database access, a developer can focus on this one query instead of looking at all queries within the application. How to tun the database access is out of scope for this blog entry.

Performance Hot Spots

Most developers upon being asked how to tune an application in an interview will tell you to use a Java profiler. That answer misses the point. A profiler helps you tune a specific section of code after you've identified the section of code that needs to be tuned. Often performance issues show up in production and it's not possible to run a profiler on your container in production. 

A thread dump taken in production on an active application can help you identify which section of code needs to be tuned, perhaps with a profiler. Furthermore, thread dumps are unintrusive enough that you can take them in production without material impact to users.  

To see how dumps help, let's review how a profiler works. A profiler works by taking a thread dump periodically, perhaps every 5 milliseconds. That thread dump specifies where in your code you're spending time. For example, if your test causes the profiler to take 100 samples and method Work.do() appears in 33 of them, then your spending 33% of your time in that method. If that's the method with the highest percentage, that is where you'll often start tuning.

In fact, thread dump data is better than profiler data in several ways:

• It measures what's actually happening in production vs. a profile of a specific business process or unit test case.
• It includes any synchronization issues between threads that won't show up in a profile of one thread in a unit test case (there are no other threads to contend with).

The problem is collecting the data. Yes, thread dumps are easy to collect. Counting occurrences of method references in running threads is laborious, tedious, and annoyingly time consuming.

Introducing StackWise

The first thing I did was scan for products that analyze thread dumps for these types of issues. There are many products that analyze thread dumps, but they tend to be interactive tools that summarize threads and allow you to selectively expand and contract them. A couple categorized threads by state (e.g. RUNNING, BLOCKED, etc.). However, none of these really looked for the three items I look for. Hence, I created the product StackWise, which is open source and freely available for you to use.

StackWise will analyze a thread dump and report useful information on all three of these conditions.  A sample of StackWise output can be found here.  Note that you get the following items of information:

• The percentage of threads that are IO bound and a summary of those IO-bound threads.
• Threads that are locking resources needed by other threads.
• A list of application method reference counts listed in descending order. 

In interpreting performance hot spots, StackWise will report application methods in which you're spending the most time. Methods belonging to ServletFilter classes can be ignored as they are often listed in all running threads.  Other method mentions, however, are possible tuning targets.

If you analyze thread dumps in ways other than what StackWise already covers, I'd like to hear your ideas.  Thanks for reading this entry.

With Java: 'private' does not mean private.

It turns out, you can get access to fields and methods in JDK classes declared as 'private' through reflection.  I don't recommend this and prefer not to use what I'm about to describe.  In fact, I consider what I'm about to describe as an option of last resort.

Recently, I ran into bug 6526376 which describes a memory leak in the JDK that impacts products that use java.io.File.deleteOnExit().  This method tracks the file that will be deleted in a statically defined Set in class java.io.DeleteOnExitHook.  This set grows, but never shrinks during the life of the JVM, creating a memory leak. 

While this bug is marked as fixed in the latest release of the JDK, upgrading to the latest release wasn't an option.  Furthermore, this Set is defined as 'private' with no way to get access to its contents and clear the Set (after doing its work), or so I thought.  Upon reading a post from Cedriks weblog, I realized that there was a way to access the files listed in this private Set and perform its work through a batch job.

The secret ingredient for this solution is the following four lines:

Class<?> exitHookClass = Class.forName("java.io.DeleteOnExitHook");
Field privateField = exitHookClass.getDeclaredField("files");
privateField.setAccessible(true);
LinkedHashSet<String> fileSet = (LinkedHashSet<String>) privateField.get(null);
// You then have full access to the privately defined Set and can modify its content.

With this particular solution, you do want to take care to synchronize access to the Set and not to delete files that are currently in use.  I haven't tried this trick to execute private methods yet, but I see no reason why it wouldn't work.  Furthermore, these four lines could easily be abstracted and consolidated into a utility class somewhere and re-used in other situations.

I've mixed feelings about this solution.  I'm glad that I was able to work around the memory leak with a short amount of code. We would have been stuck recycling our containers periodically, otherwise.  I've run into bugs with open source products where this solution could conceivably be used as well.

On the other hand, this breaks encapsulation and leaves developers no way to really guard against unauthorized access to private fields and methods.  An architecture principle I try to follow is 'Swim with the stream'.  That is, use products as they are intended to be used.  This hack definitely breaks this principle.  Should we really be able to do this?

There is no question that this is a dangerous tactic.  Private methods and fields are effectively unpublished from the perspective of the developers who wrote the code in question.  Those developers, can and should feel completely free to refactor (e.g. change or even remove) those private methods and fields with the understanding that they aren't directly affecting calling code.  These private fields/methods may disappear in future releases of the code being accessed this way or their intended use may be drastically changed.  My solution is fragile and will likely break with a future release of the JDK.

It's possible that developers using this tactic to break into sections of code they weren't given access to might not understand the full context of the fields and methods being used; there may be unintended runtime consequences to accessing and changing private data that hasn't been considered.  In my case, how can I really tell if a File listed in the shutdown hook isn't still being used?  I elected to address this issue by not deleting any file until an hour after last update or later, but this isn't fool-proof.  It's possible that by deleting these files early and removing the set entry, I've created a derivative bug somewhere that will likely be much harder now to find and fix.

On further consideration, the creators of the JDK were wise to allow this.  It gives us options when dealing with bugs like this.  If I've a developer on staff that routinely uses fragile solutions like this, I've got larger issues.  Changing the JDK to prevent this type of unauthorized access to private fields/methods won't save me from the other damage a developer like that can cause.