Dustin's Pages

Friday, October 22, 2010

Ten Tips for Using Java Stack Traces

Most Java developers are somewhat familiar with Java stack traces and how to read and analyze stack traces. However, for beginning Java developers, there are some areas of stack traces that might be a little confusing. In this post, I look at some tips for reading Java stack traces and responding appropriately based on what the stack trace reports.

1. Stack Traces Are Not Just for Errors and Exceptions

A common misconception among new Java developers and among people not familiar with Java is that stack traces indicate thrown exceptions. While stack traces are commonly associated with encountered exceptions, a Java developer can access a stack trace at any time with no exception required. One way to do this is to call Thread.currentThread().getStackTrace() to access an array of StackTraceElements. I demonstrated this previously in my post The Surprisingly Simple StackTraceElement. It can be useful to access a stack trace even outside of an exceptional situation to understand how code flows. The StackTraceElement is also useful because it allows for granular access to pieces of the stack trace.

Another non-error stack trace usage is related to Java's ability to provide details about a running process when prompted from the command-line. This is described in more detail in a later section of this post.

2. Stack Trace is Presented from Latest to Earliest

One of the most important concepts of correctly understanding a stack trace is to recognize that it lists the execution path in reverse chronological order from most recent operation to earliest operation. In many ways, analyzing a stack trace correctly is like analyzing compiler errors correctly: order matters. With the compiler errors, it is generally best to analyze the first compiler error because that often causes subsequent compiler errors. Similarly, with a stack trace, it's often most useful to start with the most recent operation and work backwards as necessary up the stack trace to see how that condition was reached. For some exceptions, like some NullPointerExceptions, analysis of the line on which the exception occurred can be all that is needed to understand what went wrong.

3. Understand Chained Exceptions

Another important observation is that stack traces that do indicate exceptions often include chained exceptions. This is important to understand because it is often the case that one of the fundamental exceptions underlying the last encountered exception is the real culprit that must be appropriately addressed. Just as addressing the last compiler error reported before addressing the first reported error rarely is a good idea, it is similarly important to analyze the underlying exception. This chained exception facility was a welcome addition to Java 1.4 because it has allowed Java developers to more easily determine the real underlying cause of various exceptions. Often the most important exception to pay attention to in a long list of chained exceptions is the first one that occurred (typically listed at the very bottom of a lengthy stack trace and often preceded by "Caused by" notation).

4. Compile with Debug Turned On

When stack traces are being used to determine why an exception occurred or what the code flow was, it can be very useful to have access to the line numbers of each executed step covered by the stack trace. By default in Oracle's Java SE 6 javac, line numbers and source file names are included in stack traces. It is easy to make disable the printing of this information by setting javac's -g:none option, but this is not typically a good idea during development. Most build tools also make it easy to turn on debugging and control the debugging level. Ant, for example, provides the debug attribute for the javac task that can be set to true to turn debugging on.

5. Logging and Handling Exception Stack Traces

Because Java stack traces are so often associated with exceptions, it is useful to know how to report these properly. Fortunately, two of the most popular Java logging frameworks, java.util.logging and log4j, provide convenient methods for logging exceptions that will handle the stack trace information automatically. For example, java.util.logging provides an overloaded version of Logger.log that accepts a Throwable and log4j provides several overloaded methods on its Logger class that allow Throwables to be logged with a normal log message.

It is sometimes necessary or at least useful to access a stack trace in code situations other than logging. One way of doing this is to use the Throwable.getStackTrace() that returns an array of StackTraceElements. Another approach is to use one of the overloaded versions of Throwable.getStackTrace() that do not simply print the stack trace to standard error. These two overloaded methods allow access to the exception's stack trace via either a PrintStream or a PrintWriter. The next two code snippets demonstrate extracting a String from a Throwable using PrintWriter and PrintStream respectively.

Java supports several approaches for accessing stack traces. Several of these are outlined in An Introduction to Java Stack Traces and I've covered a couple here already. As described in Tip #1, the stack trace of the current execution can be retrieved from the current thread. The immediately preceding tip, Tip #5, covered extracting of a stack trace from an exception/error (Throwable).

There are times when it is useful to see what the current thread and other threads are doing. Java supports this by accepting a signal and responding by displaying pertinent details. Signal handling can be a little different across platforms, so it is worth learning how to send signals from the platforms used for one's Java applications. The Sun/Oracle java launcher documentation provides significant details about its JVM signal handling in the section that describes the -Xrs option (-X indicates non-standard option). Besides explaining how to use -Xrs to turn off the JVM responding to received signals, this documentation also provides more details regarding the JVM handling of the signals SIGQUIT, SIGHUP, SIGINT, and SIGTERM.

Assuming that the -Xrs option is not used, using CTRL-BREAK in the Windows console window from which a Java application started leads to a thread dump of the current threads being displayed. This is demonstrated in the following screen snapshot of running a Java application and seeing the thread dump in Windows PowerShell.

For Linux and Unix systems, this same signal is sent differently. It can be sent with CTRL-\ (CTRL button followed by back slash) or with the command kill -QUIT pid (where 'pid' is the process ID). The jstack utility tool is also easily used to see the threads associated with a particular process (often for specified process identifier).

Java IDEs such as Eclipse and NetBeans also provide mechanisms for seeing current thread dumps and stack traces.

7. Understand Java Class/Interface Naming Conventions

When reading and analyzing a Java stack trace, it is helpful to understand the class and interface naming conventions. One source of information on these conventions is provided in the Javadoc documentation for Class.getName(). This documentation explains the naming conventions for classes, interfaces, arrays, primitives, and so forth. It states that arrays are denoted with square brace: [. It also explains that array elements are marked with various letters depending on their types: L for classes and interfaces, Z for boolean, B for byte, C for char, D for double, F for float, I for int, J for long, and S for short. Knowing what these letters represent in array representations can make it easier to read information regarding these within stack traces. As I discussed in the blog post Heap Dump and Analysis with VisualVM, these same naming conventions are also described in the JVM specification for .class file format.

The naming conventions in stack traces can be dependent on the JVM implementation, so it's worthwhile to learn what the naming conventions are for the particular JVM being used.

8. Be Cognizant of Synthetic and Bridge Methods

In many stack traces, it is fairly obvious which methods are being successively invoked by tracing through the stack trace. Sometimes, however, there can be unrecognized methods. These might be from injected aspects or might be compiler-generated methods such as synthetic and bridge methods. I discussed synthetic methods in greater detail in my blog post Java's Synthetic Methods. As I stated in that post, synthetic methods are created by the compiler and usually have, in Sun's/Oracle's JVM, names such as access$100 and access$200.

9. Dude, Where's My Stack Trace?

Stack traces can be extremely useful in debugging and understanding how an application works, but they are obviously less than effective if not readily available. As described above, some Java products (such as the logging frameworks) make logging of stack traces easier. Other products log stack traces or write out their own stack traces to product-specific directories or logs. Therefore, it's important when using a new framework, tool, library, or IDE to learn where it writes its logs and stack traces. This tip also covers other essential steps such as configuring loggers appropriately to write to the appropriate locations.

10. Magnify the Power of Stack Traces with Tooling

The majority of this post has focused on reading and manually analyzing stack traces. Tools are now available that can make use of stack traces and make use of stack traces much more efficient. Eclipse's Stacktrace Console is a good example of what a Java IDE can do to make use of stack traces easier. Stack traces can be pasted into this tool and then portions of the stack trace can be clicked on to be taken directly to that class and method. NetBeans offers similar tooling features that support easier access of stack traces to the underlying classes and methods displayed in the stack trace. Likewise, these IDEs also support generating/displaying thread dumps.

Another "tool" that is useful in conjunction with thread analysis is the powerful search engine. Although I agree that there is merit to not going right to the search engine for every problem, I have also been the beneficiary more times than I can recall of others' insight and experiences in resolving especially difficult problems. This is why I have written before that more software developers should write blogs. Search engines make it much easier to find a description of a potential fix to some nasty problems. It is often the stack trace that provides the best clues for finding the appropriate matches via search engines such as Google, Yahoo!, and Bing. Stack trace excerpts are often found in forum threads and blog posts that either directly address the issue or provide enough information to help think through what related condition might be causing the issue.

Conclusion

The humble stack trace is one of the Java developer's most powerful tools. It is especially powerful in debugging and analyzing existing software, but can even be useful in software development. In this post I have attempted to outline some simple techniques for getting the most value from these stack traces.

The blog post Logging exceptions root cause first demonstrates that LOGBack 0.9.3 now supports an option for "printing stack traces 'root cause first' instead of the standard "root cause last" (Logback News - 21 September 2011). There is an obvious appeal to this because this is the part of the exception stack trace that is typically most useful and interesting, but it might be confusing to developers who are accustomed to going to the bottom of the stack trace. In short, it invalidates the #2 tip in my post when used.