063Revisiting Stack Trace Decoding

Author: Dr. Heinz M. KabutzDate: 2003-01-28Java Version: 1.4Category: Language

Abstract: Stack traces give us a clue of which method called us, giving us a form of caller ID.

Welcome to the 63rd edition of The Java(tm) Specialists' Newsletter sent to 5726 Java Specialists in 93 countries.

Someone has pressed the fast-play button in my life. It seems like it was last week that I published newsletter #62, yet it is almost a whole month since you last heard from me. At least I know that you appreciate me, by the "How did I get unsubscribed???" messages that appear in my Inbox ;-) This was supposed to be a weekly newsletter, but we are the victims of our own success.

I started this newsletter whilst sitting in a Fish & Chips shop in London, on my way to Estonia. In case your geography is as bad as mine, Estonia is one of the states that was occupied by Russia for a few decades, and became independent in 1991. They revolted against Russia by singing! In my next newsletter I will write a travel report about my experiences in Estonia. I am also thrilled to be able to meet my readers in Estonia, so please send me an email if you are in Tallinn.

When I mentioned Estonia to my friends in South Africa, I got lots of responses of "where's that?". Once I had explained where Estonia was, they usually followed with: "What on earth are you going to be doing there?" The answer is that I will be teaching Design Patterns at an Estonian Bank.

javaspecialists.teachable.com: Please visit our new self-study course catalog to see how you can upskill your Java knowledge.

Revisiting Stack Trace Decoding

In our fourth newsletter, I mentioned that you could decode the stack trace to find out where the method call that caused your problem came from. At that time already, some readers mentioned that JDK 1.4.x would make this problem easier to solve.

Just to remind you - in the previous newsletter we pushed the stack trace to a StringWriter and then stepped through the String counting the lines until we arrived at the desired line. In JDK 1.4.x Sun Microsystems changed the Throwable class a little bit, making it more useful. One of the things Sun did was keep the elements of the call stack in an array of StackTraceElement objects. This way we can more easily determine what line some method is being called from. One of my readers sent me an example of how this information could be used to enforce security. Perhaps one day I will publish that idea.

In some of my newsletters I have berated the exceptions. Just to clear the air - I do not have anything against exceptions. I also do not have a problem with sensible comments. I just do not like it when Exceptions are ignored. I believe that every Java program should have a central exception mechanism that can receive exceptions that could not be properly handled and that the administrator should know immediately when something went wrong.

I present a new interface called CallDetective that can find out who called us. An interesting twist is that the interface CallDetective contains a static class called Factory that constructs the correct type of CallDetective, depending on the Java Version. For any JVM prior to JDK 1.4, we use the old StackTrace approach discussed in newsletter #4. The idea of having a class inside an interface is not new, we already saw it in newsletter #6.

Here is the CallDetective Interface:

/**
 * This interface is used to determine who called us.
 * The implementation does not have to be thread-safe.
 */
public interface CallDetective {
  /**
   * Returns a String representation of who called us,
   * going back depth levels.
   * @param depth must be greater than 0 and may not
   * exceed the call stack depth.
   */
  public String findCaller(int depth);
  public class Factory {
    public static CallDetective makeCallDetective() {
      if ("1.4".compareTo(System.getProperty("java.version")) > 0) {
        return new CallDetective1_3();
      } else {
        return new CallDetective1_4();
      }
    }
  }
}

You can use the CallDetective Factory like this:

// ...
CallDetective cd = CallDetective.Factory.makeCallDetective();
System.out.println(cd.findCaller(0));

A slightly adapted version of our old StackTrace class is shown here (See Issue #4 for more information):

/**
 * This is a pre-JDK 1.4 version of the CallDetective.
 * See TJSN 4th edition.
 */
import java.io.*;

public class CallDetective1_3 implements CallDetective {
  private final Throwable tracer = new Throwable();
  private final StringWriter sw = new StringWriter(1024);
  private final PrintWriter out = new PrintWriter(sw, false);

  public String findCaller(int depth) {
    if(depth < 0) {
      throw new IllegalArgumentException();
    }

    int lineOfInterest = depth + 3;
    sw.getBuffer().setLength(0); // set the buffer back to zero
    tracer.fillInStackTrace();
    tracer.printStackTrace(out);

    LineNumberReader in = new LineNumberReader(
      new StringReader(sw.toString()));

    try {
      String result;
      while((result = in.readLine()) != null) {
        if (in.getLineNumber() == lineOfInterest) {
          return beautify(result);
        }
      }
    } catch(IOException ex) {
      // this should REALLY never happen
      throw new RuntimeException(ex.toString());
    }
    throw new IllegalArgumentException();
  }

  private static String beautify(String raw) {
    raw = raw.trim();
    if (raw.startsWith("at ")) {
      return raw.substring(3);
    }
    return raw;
  }
}

The version of JDK 1.4.x onwards is much easier:

/**
 * This class is used to determine who called us.
 * It is deliberately not thread-safe.
 */
public class CallDetective1_4 implements CallDetective {
  private final Throwable tracer = new Throwable();

  public String findCaller(int depth) {
    if (depth < 0) {
      throw new IllegalArgumentException();
    }
    tracer.fillInStackTrace();
    return tracer.getStackTrace()[depth+1].toString();
  }
}

This could be used as part of a Log class, but I must warn you that it will obviously impact the performance of your application if you overdo it...

public class Log {
  private static CallDetective detective = 
    CallDetective.Factory.makeCallDetective();
  public static void it(String msg) {
    String source = detective.findCaller(1); //caller of it()
    System.out.println(source + " : " + msg);
  }
}

Let's look at some test code:

public class Test {
  private CallDetective saps = 
    CallDetective.Factory.makeCallDetective();
  {
    System.out.println("Using " + saps.getClass().getName());
  }
  public void f() {
    g();
  }
  public void g() {
    Log.it("where am I now?");
    System.out.println(saps.findCaller(0));
    System.out.println(saps.findCaller(1));
    System.out.println(saps.findCaller(2));
    System.out.println();
    System.out.println();
  }
  public static void main(String[] args) {
    new Test().f();
  }
}

I ran this with the three versions of Java that are installed on my notebook:

java version "1.3.1_06"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.1_06-b01)
Java HotSpot(TM) Client VM (build 1.3.1_06-b01, mixed mode)

Using CallDetective1_3
Test.g(Test.java:11) : where am I now?
Test.g(Test.java:12)
Test.f(Test.java:8)
Test.main(Test.java:20)


java version "1.4.0_01"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.0_01-b03)
Java HotSpot(TM) Client VM (build 1.4.0_01-b03, mixed mode)

Using CallDetective1_4
Test.g(Test.java:11) : where am I now?
Test.g(Test.java:12)
Test.f(Test.java:8)
Test.main(Test.java:20)


java version "1.4.1_01"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_01-b01)
Java HotSpot(TM) Client VM (build 1.4.1_01-b01, mixed mode)

Using CallDetective1_4
Test.g(Test.java:11) : where am I now?
Test.g(Test.java:12)
Test.f(Test.java:8)
Test.main(Test.java:20)

And Now for the Real Reason Why You Should Use This...

My grandfather kept on repeating himself: "It's all about the money. It's all about the money. Money makes the world go round. Money is everything. It's all about the money. It's all about the money." At age sixteen, I was not going to listen to anyone anyway, so his efforts were wasted on me, I still don't agree with him ;-)

However, in the Java world, it is all about the money. The money here is the currency of performance. By the time I publish the next newsletter, I hope to meet in person one of the authorities on Java Performance Tuning, Jack Shirazi. I want to review his book Java Performance Tuning, 2nd Edition, so stay tuned ... In the meantime, let us look at the performance of the two approaches:

public class PerfTest {
  private final CallDetective cd;
  public PerfTest(CallDetective cd) {
    this.cd = cd;
  }
  public void test() {
    f(5);
    f(10);
    f(20);
  }
  public void f(int depth) {
    // build up a big call stack...
    if (depth > 0) {
      f(depth-1);
    } else {
      long time = -System.currentTimeMillis();
      for (int i=0; i<10000; i++) {
        cd.findCaller(0);
      }
      time += System.currentTimeMillis();
      System.out.println(time + "ms");
    }
  }
  public static void main(String[] args) {
    System.out.println("JDK 1.3 approach to find caller:");
    new PerfTest(new CallDetective1_3()).test();
    System.out.println("JDK 1.4 approach to find caller:");
    new PerfTest(new CallDetective1_4()).test();
    // now let's do it again...
    System.out.println("JDK 1.3 approach to find caller:");
    new PerfTest(new CallDetective1_3()).test();
    System.out.println("JDK 1.4 approach to find caller:");
    new PerfTest(new CallDetective1_4()).test();
  }
}

From the results, we can see that the new JDK 1.4 approach is on average 2.7 times faster than the old way of tracing through the stack trace. Please see that in perspective - the biggest speedup will be achieved if you don't dig through the stack trace at all!

JDK 1.3 approach to find caller:
1502ms
1923ms
3215ms
JDK 1.4 approach to find caller:
501ms
711ms
1101ms
JDK 1.3 approach to find caller:
1442ms
1903ms
2934ms
JDK 1.4 approach to find caller:
501ms
711ms
1102ms

That's it for this week. I have to run downstairs now to send this newsletter off to you so that you have something to think about until the review of the book Java Performance Tuning...

Heinz

Comments

We are always happy to receive comments from our readers. Feel free to send me a comment via email or discuss the newsletter in our JavaSpecialists Slack Channel (Get an invite here)

Related Articles

Browse the Newsletter Archive