Alois Reitbauer About the Author

The Cost of an Exception

Recently there was a bigger discussion at dynaTrace around the cost of exceptions. When working with customers we very often find a lot of exceptions they are not aware of. After removing these exceptions, the code runs significantly faster than before. This creates the assumption that using exceptions in your code comes with a significant performance overhead. The implication would be that you better avoid using exceptions. As exceptions are an important construct for handling error situation, avoiding exceptions completely does not seem to be good solution. All in all this was reason enough to have a closer look at the costs of throwing exceptions.

The Experiment

I based my experiment on a simple piece of code that randomly throws an exception. This is not a really scientifically-profound measurement and we also don’t know what the HotSpot compiler does with the code as it runs. Nevertheless it should provide us with some basic insights.

public class ExceptionTest {
 
  public long maxLevel = 20;
 
  public static void main (String ... args){
 
    ExceptionTest test = new ExceptionTest();
 
    long start = System.currentTimeMillis();
    int count = 10000;
    for (int i= 0; i < count; i++){
      try { 
        test.doTest(2, 0);
      }catch (Exception ex){
//        ex.getStackTrace();
      }
    }
    long diff = System.currentTimeMillis() - start;
    System.out.println(String.format("Average time for invocation: %1$.5f",((double) diff)/count));
  }
 
  public void doTest (int i, int level){
      if (level < maxLevel){
        try {
          doTest (i, ++level);
        }
        catch (Exception ex){
//        ex.getStackTrace();
          throw new RuntimeException ("UUUPS", ex);
        }
      }
      else {
        if (i > 1) {
          throw new RuntimeException("Ups".substring(0, 3));
        }
      }
  }
}

The Result

The result was very interesting. The cost of throwing and catching an exception seems to be rather low. In my sample it was about 0.002ms per Exception. This can more or less be neglected unless you really throw too many exceptions – and too many means we are talking about 100.000 or more.

While these results show that exception handling itself is not affecting code performance, it leaves open the question: what is responsible for the huge performance impact of exceptions? So obviously I was missing something – something important.

After thinking about it again, I realized that I was missing an important part of exception handling. I missed out the part on what you do when exceptions occur. In most cases you – hopefully – do not just catch the exception and that’s it. Normally you try to compensate for the problem and keep the application functioning for your end users. So the point I was missing was the compensation code that is executed for handling an exception. Depending on what this code is doing the performance penalty can become quite significant. In some cases this might mean retrying to connect to a server in other cases it might mean using a default fallback solution that is providing a far less-performing solution.

While this seemed to be a good explanation for the behavior we saw in many scenarios, I thought I am not done yet with the analysis. I had the feeling that there is something else that I was missing here.

Stack Traces

Still curious about this problem I looked into how the situation changes when I collect stack traces. This is what very often happens. You log an exception and its stack trace to try to figure out what the problem is.

I therefore modified my code to now get the stack trace of an exception as well. This changed the situation dramatically. Getting the stack trace of an exception had a 10x higher impact on the performance than just catching and throwing them. So while stack traces help to understand where and possibly also why a problem occurred, they come with a performance penalty.

The impact here is often very high as we are not talking about a single stack trace. In most cases exceptions are thrown – and caught – at multiple levels. Let us look at a simple example of a Web Service client connecting to a server. First there is an exception at the Java library level for the failed connection. Then there is a framework exception for the failed client and then there might be an application-level exception that some business logic invocation failed. This now sums up to three stack traces being collected.

In most cases you should see them in your log files or application output. Writing these potentially long stack traces again comes with some performance impact. At least you normally see and you can react to them if you look at your log files regularly – which is something you do, don’t you? ;-)

In some cases I have seen even worse behavior due to some incorrect logging code. Instead of checking whether a certain log level is enabled by calling log.isxxEnabled () first, developers just call logging methods. When this happens, logging code is always executed including getting stack traces of exceptions. As the log level however is set too low they never show up anywhere you might not even be aware of them. Checking for log levels first should be a general rule as it also avoids unnecessary object creation.

Conclusion

Not using exceptions because of their potential performance impact is a bad idea. Exceptions help to provide a uniform way to cope with runtime problems and they help to write clean code. You however need to trace the number of exceptions that are thrown in your code. Although they might be caught they can still have a significant performance impact. In dynaTrace we, by default, track thrown exceptions – and in many cases people are surprised by what is going on in their code and what the performance impact is in resolving them.

While exception usage is good you should avoid capturing too many stack traces. In many cases they are not even necessary to understand the problem – especially if they cover a problem you already expect. The exception message therefore might prove as being enough information. I get enough out of a Connection refused message so I do not need the full stack trace into the internal of the java.net call stack.

Comments

  1. Mirko Novakovic says:

    Hi Alois,

    nice article.

    Heinz has written about this and how actual JVMs optmize in these situations: http://www.javaspecialists.eu/archive/Issue187.html

    Some years ago exceptions ally have been a problem and I have seen lot’s of problems. So I think that it really depends on JVM version, vendor, etc.

    Also the impact on memory and GC could be interestjng.

    See you at JAX.

    Mirko

  2. Robert Saulnier says:

    Getting the stack trace doesn’t cost much, it’s just cloning the stack (Throwable.getStackTrace()).

    Also, all Throwables have their stack trace filled no matter if it’s accessed or not. All Throwable constructors call fillInStackTrace().

    The real cost difference is more likely in logging the stack traces.

  3. @Mirko
    Good article by Heinz – as always :-) . The point i found especially interesting is how the JVM even stops creating stack traces.

    See you in May

  4. @Robert

    My test results show that calling getStackTrace() creates a massive overhead. As you can see in the code sample I am not logging it somewhere.

    Constructors as far as I know use fillInStackTrace(). I assume that there is some transformation from native to Java format that causes the overhead.

  5. Robert Saulnier says:

    I’ve run your code with the getStackTrace() commented and uncommented. The results I get are:

    commented: ~102 microseconds
    uncommented: ~108 microseconds

    This gives around 6 microseconds to clone the stack trace which seems reasonable, but no where near a magnitude of x10.

  6. Which JVM did you use?

  7. Scott Vercuski says:

    Great article. I’ve often wondered about this myself and I appreciate the answer here. Exception handling is a must in any program. Doesn’t matter how good a developer is .. there is no such thing as 100% bug free code and based on that assumption … good exception handling is a must and as proven here doesn’t cause a strain on the system.

  8. Robert Saulnier says:

    I’m not at my computer right now, but it’s the Sun JVM 6 build 23 running on Windows XP.

  9. Alex Kutovoy says:

    I ran the code and my results were similar to those of Robert Saulnier. The difference between commented and uncommented getStackTrace() was ~1.5 microseconds (0.04060-0.03910). I am using 1.6.0-13 JVM.

  10. Checked the code and saw I forgot one getStackTrace call in the doTest method. So now for every exception there is a stack trace.

  11. It varies somewhat per-platform, I think. We hit issues a few months back where exception handling (filling in of stack traces) was having a huge impact on application performance on an HP-UX JVM.

    Now, many of those exceptions shouldn’t have been occurring anyway (stuff like closing a JDBC connection twice), but it’s something that had never shown up as a problem on any other platform (IBM’s JVM on AIX, JRockit on Linux, etc)

  12. Johannes Bauer says:

    Hi,

    not sure what logging framework you’re talking about, but at least for commons-logging you really shouldn’t check whether logging is enabled before every log statement.

    Typically, what you do is something like

    }catch (Exception e) {
    log.warn(“Oops.”, e);
    }
    What happens inside log.warn() is that the framework checks whether logging is enabled for the level WARN and, if not, simply discards e and the message.

    Checking the log level before the log statement thus doesn’t save you anything if logging is not enabled, and incurs the cost of checking the level twice in case it is.

    Worse still, it clutters your code.

    My 2ct. Cheers,
    Johannes

  13. Anders Lundén says:

    @Johannes Bauer

    I would say that it sometimes is reasonable to check the log level before performing the log using any log framework (commons logging for example).
    Perhaps not on warning logs since they are always enabled anyway in the systems I work with. But for debug I check the log level before logging. The reason is that I usually want to provide information regarding related object(s) used when logging and creating a string representation out those related object(s) may be complex.


    log.debug("Some debug output with related object " + myRelatedObject.toString());

    If I don’t check the loglevel first, the toString() will be evaluated and the two strings will be concatinated. If myRelatedObject is an object with lots of members and perhaps using a reflection framwork to create the string the penalty is more likely to be measurable.

    It clutters the code, agreed. But it might be worth the clutter in some cases.

  14. Johannes Bauer says:

    Hi Anders,

    you’re absolutely right; in that case checking the log level is good practice.

    The check should only be omitted when logging exceptions and, optionally, a simple message.

  15. @Anders’ situation is a common optimization problem with logging, and often trips up even the most experienced programmers. This turns out to be a case in which a language capability for closures — http://en.wikipedia.org/wiki/Closure_(computer_science) — could be a huge advantage.

    This issue report for Groovy: http://jira.codehaus.org/browse/GROOVY-973 — which I chose because Groovy has closures and yet has syntax very similar to Java’s — shows how encapsulating the desired debugging string in a closure could make it simple to defer expensive toString(), concatenation, and other operations until after the log level check.

  16. This article makes an interesting point about exception handling. However, all the experiments must be monitored and measured with large data in a scientific way to verify.

    Generally speaking, there are 2 types of Exceptions: Recoverable exceptions and Unrecoverable exceptions.

    When a Recoverable exception happens, ideally, the developer should catch it and try to recover from the exception, for example retry several times, try different routes ….etc…

    On the other hand, developers can do nothing with Unrecoverable exception, except log it to the log file, and announce to the user that an error happens.

    Overtime, a recoverable exception can become unrecoverable. By that time, your code should re-throw the exception, instead of swallow it.

    The way Java divides exceptions into Checked exception and Unchecked exceptions are sometimes not logic, in the sense that some time it make an Unrecoverable exception be a Checked exception, therefore it forces developers to catch it, but can do nothing about it => Waste of time, code, resource …etc..

    My strategy is:
    - Always handle recoverable exceptions. Deal with it, or if all things fail, re-throw it.

    - Let all unrecoverable exceptions fall over until the last layer, where I must announce/return results of a request to the user. At this layer, I will log the exception with stack trace, send error message to the user.

    Doing this way, the code is consistent, and doesn’t have unnecessary catch clauses which waste my time and my computing resource.

  17. As Robert Saulnier already pointed out, getStackTrace is slow because it clones the stack trace. But not only that – it is simply wrong to compare not handling exceptions to handling them by calling getStackTrace because normally you never clone stack traces!

    You typically handle the exceptions by:

    1. not evaluating them at all,
    2. printing the stack trace to a file, or
    3. printing the stack trace to the standard output.

    In all of these cases, the stack trace is never cloned and the comparison is thus semantically wrong.

    Your ultimate conclusion is not wrong, ironically, it is typically much, much worse than what you report! I took your code and heavily extended it with different exception handling strategies. Here’s what I have to report:

    $ java ExceptionTest >/dev/null
    Ignore – The exception is completely ignored.
    0,0479ms

    GetMessage – The exception message is evaluated.
    0,0506ms

    GetStackTrace – The stack trace is evaluated (effectively cloned).
    0,2480ms

    PrintNull – The stack trace is printed to a stream that ignores input.
    1,8384ms

    PrintByteArray – The stack trace is printed to a byte array in memory.
    1,9451ms

    PrintStdout – The stack trace is printed to the standard output.
    3,8076ms

    PrintFile – The stack trace is printed to a file.
    12,5949ms

    PrintFile strategy is 263 times (!) slower than Ignore strategy on my Core 2 Duo with a 5300 RPM hard drive. A test with a Quad-core Xeon yielded generally little improvement except in PrintFile, where superior storage hardware lowers this to about 7 seconds (‘only’ 168x times slower than Ignore strategy).

    Note that standard output in production is either redirected to a file (so PrintFile measurements apply) or to /dev/null. So even when redirecting it to /dev/null the performance is horrible (80x slower than Ignore strategy).

    You can check out my code from github with git (git://github.com/Irfy/ExceptionTest.git) or preview it in your browser (https://github.com/Irfy/ExceptionTest/blob/master/src/ExceptionHandler.java and https://github.com/Irfy/ExceptionTest/blob/master/src/ExceptionTest.java). Feel free to extend/reuse.

  18. Btw, you should provide some sort of markup for comments like Textile or Markdown (I’m not seeing any such support by skimming over the page).

  19. @Johannes

    In the case you are just logging what you get not checking is ok. As Anders pointed out as soon as you construct objects the impact is way bigger. I see we agree on this point ;-) . In many cases people do more than just simple writing a message, there checking the log level makes sense.

    @Irfan

    Nice code sample. Thanks. I will look into the code markup for comments. For some posts it seemed to work.

  20. As many have already pointed out, you should only throw exceptions in exceptional cases (ie. not use them to replace return codes), and in these cases their performance impact should be ignorable.

    Also, an other important thing to note is that under some circumstances the stack traces might be missing (the JVM optimizes them away if it sees you throwing too many exceptions): http://hype-free.blogspot.com/2009/07/why-cant-i-see-stacktrace-under-java.html

Comments

*


4 − = three