Monday, September 29, 2008

The Surprisingly Simple StackTraceElement

JDK 1.4 introduced so many new features to the Java landscape that it was easy to focus on a few at the expense of others. New JDK 1.4 features such as built-in Java logging, built-in XML support, Java WebStart, the Assertion Facility, the Preferences API, and the incorporation of key Java security APIs dominated the long list of new features for many of us.

One feature that I appreciated when JDK 1.4 was released, but did not focus on, was the Chained Exception Facility. This was a feature that I have taken advantage of countless times since in my application exception handling, but I did not need to and chose not to focus much on it. It was just there and I have benefited from it tremendously. As part of JDK 1.4's renovation of exception handling, an important advancement was the ability to access the exception stack trace programmatically. This blog entry looks at this feature that has been around for some time now, but is useful in multiple different circumstances.

JDK 1.4 added the getStackTrace method to Throwable and this method returns an array of StackTraceElement. The StackTraceElement class provides easy access to information about each stack frame in the stack trace.

There are two obvious uses of the StackTraceElement that come to mind. One is for parsing the contents of an exception stack trace for specific details. The other obvious use of StackTraceElement is to provide metadata when implementing simple logging messages. I'll demonstrate brief examples of each of these two primary uses of StackTraceElement in this blog entry.

There are several reasons that a Java developer may want to parse an exception's metadata. These reasons include conditional logic based on exception metadata and generation of appropriate responses to service calls from internally thrown exceptions. The following code listing demonstrates how an exception's metadata can be extracted through the StackTraceElement. [Note that all code listings in this blog entry exist in a class called StackTraceElementDemonstrator.]


/**
* Extract exception details from Exception using StackTraceElement. The
* StackTraceElement class makes it simple to extract specific details from
* a given Exception because Throwable (Exception's parent) provides a
* getStackTrace method.
*
* http://java.sun.com/javase/6/docs/api/java/lang/Throwable.html
*/
public void demonstrateExceptionExtraction()
{
try
{
intentionallyThrowException();
}
catch (Exception exception)
{
parseExceptionContents(exception, System.out);
}
}

/**
* Intentionally throw an exception that can be caught and processed with
* StackTraceElement instances.
*/
private void intentionallyThrowException()
{
throw new UnsupportedOperationException(
"You called a method that has not yet been implemented.");
}

/**
* Parse the contents of the passed-in exception.
*
* @param exception Exception whose contents are desired.
* @param out OutputStream to which to write the exception contents.
*/
private void parseExceptionContents(
final Exception exception,
final OutputStream out)
{
final StackTraceElement[] stackTrace = exception.getStackTrace();
int index = 0;
for (StackTraceElement element : stackTrace)
{
final String exceptionMsg =
"Exception thrown from " + element.getMethodName()
+ " in class " + element.getClassName() + " [on line number "
+ element.getLineNumber() + " of file " + element.getFileName() + "]";
try
{
out.write((headerLine + newLine).getBytes());
out.write((headerTitlePortion + index++ + newLine).getBytes() );
out.write((headerLine + newLine).getBytes());
out.write((exceptionMsg + newLine + newLine).getBytes());
out.write(
("Exception.toString: " + element.toString() + newLine).getBytes());
}
catch (IOException ioEx)
{
System.err.println(
"IOException encountered while trying to write "
+ "StackTraceElement data to provided OutputStream.\n"
+ ioEx.getMessage() );
}
}
}


The code listing above leads to the output shown in the following screen snapshot:



From this screen snapshot, we clearly see that the useful StackTraceElement in this particular array is the first entry (index of zero). This is not surprising when considered in light of the Javadoc documentation for StackTraceElement, which states that the top frame is normally the generation point of the exception.

A second use of StackTraceElement is to provide metadata for a simple logging implementation. This concept is demonstrated in How to Get Java Source Code Line Number and File Name in Code. While the array of StackTraceElement returned from the Throwable.getStackTrace() method helped extract exception details in the example above, the same approach can be used even for logging non-exceptional circumstances when using in conjunction with the Thread class.

The Thread class has a static method called currentThread() that can be used to statically acquire a handle on the current thread and then the method getStackTrace() can be called on that current thread. That method returns an array of StackTraceElement just as the same-named method on Throwable did in the Exception example above. However, in the case of normal thread execution, the particular StackTraceElement of interest in the array is not likely to be the top (zero index) element.

The following code demonstrates using Thread.currentThread().getStackTrace() to get a handle of the array of StackTraceElement and demonstrates using the StackTraceElement with index of 2 to get information on the method that actually called the log statement.


/**
* Demonstrate use of StackTraceElement in custom logging.
*/
public void demonstrateLogging()
{
logThisMessage("Entered the demonstrateLogging() method.", System.out);
}

/**
* Log the provided String along with log-related metadata such as file name
* and line number.
*
* @param messageToLog String message to log.
* @param out OutputStream to which to write the log message.
*/
private void logThisMessage(
final String messageToLog,
final OutputStream out)
{
final StackTraceElement[] stackTrace =
Thread.currentThread().getStackTrace();
StackTraceElement logElement = stackTrace[2];
printContentsOfStackTrace(stackTrace, out);
try
{
final String messageToOutput =
"[" + logElement.getFileName() + ":" + logElement.getLineNumber()
+ "] " + logElement.getClassName() + "." + logElement.getMethodName()
+ ": " + messageToLog;

out.write((newLine + headerLine + newLine).getBytes());
out.write(("-- Logging Message: " + messageToLog + newLine).getBytes());
out.write((headerLine + newLine).getBytes());
out.write((messageToOutput + newLine).getBytes());
}
catch (IOException ioEx)
{
System.err.println(
"IOException encountered trying to log message with "
+ "StackTraceElement:\n" + ioEx.getMessage());
}
}

/**
* Print contents of stack trace to provided OutputStream.
*
* @param stackTrace Stack Trace to write out.
* @param out OutputStream to which to write stack trace elements.
*/
public void printContentsOfStackTrace(
final StackTraceElement[] stackTrace,
final OutputStream out)
{
int index = 0;
for (StackTraceElement element : stackTrace)
{
try
{
out.write(newLine.getBytes());
out.write(("Index: " + index++ + newLine).getBytes() );
out.write(("ClassName: " + element.getClassName() + newLine).getBytes() );
out.write(("MethodName: " + element.getMethodName() + newLine).getBytes() );
out.write(("FileName: " + element.getFileName() + newLine).getBytes() );
out.write(("LineNumber: " + element.getLineNumber() + newLine).getBytes());
}
catch (IOException ioEx)
{
System.err.println(
"IOException trying to write out contents of StackTraceElement[]:\n"
+ ioEx.getMessage() );
}
}
}


The example code above leads to two different portions of output. The method in the code listing above called logThisMessage logs the stack trace element details from the one entry in the returned StackTraceElement array that represents the code invoking the logging. Its output is depicted in the screen snapshot below:



This output demonstrates that the index value of 2 (third array element) was the appropriate choice for extracting information on the source code that called the logging method. If one wonders why it is 2, the next code sample (parseExceptionContents method) answers that question.


/**
* Parse the contents of the passed-in exception.
*
* @param exception Exception whose contents are desired.
* @param out OutputStream to which to write the exception contents.
*/
private void parseExceptionContents(
final Exception exception,
final OutputStream out)
{
final StackTraceElement[] stackTrace = exception.getStackTrace();
int index = 0;
for (StackTraceElement element : stackTrace)
{
final String exceptionMsg =
"Exception thrown from " + element.getMethodName()
+ " in class " + element.getClassName() + " [on line number "
+ element.getLineNumber() + " of file " + element.getFileName() + "]";
try
{
out.write((headerLine + newLine).getBytes());
out.write((headerTitlePortion + index++ + newLine).getBytes() );
out.write((headerLine + newLine).getBytes());
out.write((exceptionMsg + newLine + newLine).getBytes());
out.write(
("Exception.toString: " + element.toString() + newLine).getBytes());
}
catch (IOException ioEx)
{
System.err.println(
"IOException encountered while trying to write "
+ "StackTraceElement data to provided OutputStream.\n"
+ ioEx.getMessage() );
}
}
}


The parseExceptionContents method produces output like that shown in the next screen snapshot.



This output demonstrates why the magical "2" was needed to get the appropriate StackTraceElement from the array returned by Thread.currentThread.getStackTrace(). The first StackTraceElement (index of 0) represents the last stack frame (the call to current thread to get the stack trace) and the second index (index of 1) represents the stack frame for the logThisMessage method that was called by the method wanting to log. The third StackTraceElement with index value of 2 actually belongs to the method wanting to log (demonstrateLogging) and the last stack frame (index of 3) is the main function that called the method that would want to log a message. This is summarized here:

0 -> Thread.getStackTrace
  1 -> StackTraceElementDemonstrator.logThisMessage
    2 -> StackTraceElementDemonstrator.demonstrateLogging
      3 -> StackTraceElementDemonstrator.main


In this blog entry, I have summarized the ease and convenience of the StackTraceElement in parsing exceptions and in simple logging mechanisms. All of the code listings shown above are shown again below in a complete class listing for the StackTraceElementDemonstrator class.


StackTraceElementDemonstrator.java


package dustin.example;

import java.io.IOException;
import java.io.OutputStream;

/**
* This class demonstrates the great utility of the StackTraceElement class
* that was introduced with JDK 1.4.
*
* @author Dustin
*/
public class StackTraceElementDemonstrator
{
final String newLine = System.getProperty("line.separator");
final String headerLine =
"-----------------------------------------------------------------------";
final String headerTitlePortion =
"-- StackTraceElement Index #";

/** No-argument constructor. **/
public StackTraceElementDemonstrator() {}

/**
* Extract exception details from Exception using StackTraceElement. The
* StackTraceElement class makes it simple to extract specific details from
* a given Exception because Throwable (Exception's parent) provides a
* getStackTrace method.
*
* http://java.sun.com/javase/6/docs/api/java/lang/Throwable.html
*/
public void demonstrateExceptionExtraction()
{
try
{
intentionallyThrowException();
}
catch (Exception exception)
{
parseExceptionContents(exception, System.out);
}
}

/**
* Intentionally throw an exception that can be caught and processed with
* StackTraceElement instances.
*/
private void intentionallyThrowException()
{
throw new UnsupportedOperationException(
"You called a method that has not yet been implemented.");
}

/**
* Parse the contents of the passed-in exception.
*
* @param exception Exception whose contents are desired.
* @param out OutputStream to which to write the exception contents.
*/
private void parseExceptionContents(
final Exception exception,
final OutputStream out)
{
final StackTraceElement[] stackTrace = exception.getStackTrace();
int index = 0;
for (StackTraceElement element : stackTrace)
{
final String exceptionMsg =
"Exception thrown from " + element.getMethodName()
+ " in class " + element.getClassName() + " [on line number "
+ element.getLineNumber() + " of file " + element.getFileName() + "]";
try
{
out.write((headerLine + newLine).getBytes());
out.write((headerTitlePortion + index++ + newLine).getBytes() );
out.write((headerLine + newLine).getBytes());
out.write((exceptionMsg + newLine + newLine).getBytes());
out.write(
("Exception.toString: " + element.toString() + newLine).getBytes());
}
catch (IOException ioEx)
{
System.err.println(
"IOException encountered while trying to write "
+ "StackTraceElement data to provided OutputStream.\n"
+ ioEx.getMessage() );
}
}
}

/**
* Demonstrate use of StackTraceElement in custom logging.
*/
public void demonstrateLogging()
{
logThisMessage("Entered the demonstrateLogging() method.", System.out);
}

/**
* Log the provided String along with log-related metadata such as file name
* and line number.
*
* @param messageToLog String message to log.
* @param out OutputStream to which to write the log message.
*/
private void logThisMessage(
final String messageToLog,
final OutputStream out)
{
final StackTraceElement[] stackTrace =
Thread.currentThread().getStackTrace();
StackTraceElement logElement = stackTrace[2];
printContentsOfStackTrace(stackTrace, out);
try
{
final String messageToOutput =
"[" + logElement.getFileName() + ":" + logElement.getLineNumber()
+ "] " + logElement.getClassName() + "." + logElement.getMethodName()
+ ": " + messageToLog;

out.write((newLine + headerLine + newLine).getBytes());
out.write(("-- Logging Message: " + messageToLog + newLine).getBytes());
out.write((headerLine + newLine).getBytes());
out.write((messageToOutput + newLine).getBytes());
}
catch (IOException ioEx)
{
System.err.println(
"IOException encountered trying to log message with "
+ "StackTraceElement:\n" + ioEx.getMessage());
}
}

/**
* Print contents of stack trace to provided OutputStream.
*
* @param stackTrace Stack Trace to write out.
* @param out OutputStream to which to write stack trace elements.
*/
public void printContentsOfStackTrace(
final StackTraceElement[] stackTrace,
final OutputStream out)
{
int index = 0;
for (StackTraceElement element : stackTrace)
{
try
{
out.write(newLine.getBytes());
out.write(("Index: " + index++ + newLine).getBytes() );
out.write(("ClassName: " + element.getClassName() + newLine).getBytes() );
out.write(("MethodName: " + element.getMethodName() + newLine).getBytes() );
out.write(("FileName: " + element.getFileName() + newLine).getBytes() );
out.write(("LineNumber: " + element.getLineNumber() + newLine).getBytes());
}
catch (IOException ioEx)
{
System.err.println(
"IOException trying to write out contents of StackTraceElement[]:\n"
+ ioEx.getMessage() );
}
}
}

/**
* @param arguments The command line arguments; none anticipated.
*/
public static void main(final String[] arguments)
{
final StackTraceElementDemonstrator me =
new StackTraceElementDemonstrator();
me.demonstrateExceptionExtraction();
me.demonstrateLogging();
}
}



While I have used and do use many of the features introduced with JDK 1.4 every day and take advantage of the chained exception handling frequently without even thinking about it, use of the StackTraceElement is something that only comes up occasionally, but is very welcome when needed.

4 comments:

William Louth said...

This mechanism is absolutely incredibly expensive (performance cost) especially with Spring based server and applications were the stack size can easily grow beyond a depth of 300.

http://www.jinspired.com/products/jxinsight/callstackbenchmark.html

jakob said...

this blog post has some JavaScript that locks up the browser. It's the combination of these:

http://dustinmarx.googlepages.com/shCore.js
http://dustinmarx.googlepages.com/shBrushCpp.js
http://dustinmarx.googlepages.com/shBrushCSharp.js
http://dustinmarx.googlepages.com/shBrushCss.js
http://dustinmarx.googlepages.com/shBrushJava.js

Tested in Firefox 2/3 and IE 7.

Dustin said...

William,

Thanks for pointing out the performance impact of these approaches. It doesn't surprise me that the Thread.currentThread().getStackTrace() is an especially bad performer with large stack traces. This reinforces my recommended use of this only for very simple logging needs. For any real application, I tend to use Log4J or java.util.logging.

As for the relatively better (but still not great) performance of Throwable.getStackTrace(), that seems acceptable for many of the situations in which I might employ it (building up an error response to a service call).

Dustin said...

jakob,

Thanks for pointing that out. As discussed in this other blog, I have had trouble getting syntax highlighter to work correctly with my blog. Fortunately, I have tried FaziBear's Blogger Widget and it seems to do the trick.