Use of Exception to log execution stack trace

Question

I've been back and forth with a colleague over the use of Throwable.fillInStackTrace. This Log class is meant to wrap the Simple Logging Facade for Java.

public class Log {
    private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(Log.class);

    private String stackTrace(Exception cause) {
        if (cause == null)
            return "";
        StringWriter sw = new StringWriter(1024);
        final PrintWriter pw = new PrintWriter(sw);
        cause.printStackTrace(pw);
        pw.flush();
        return sw.toString();
    }

    public void warn(Exception cause, String message) {
        String output = message + "\n" + stackTrace(cause);
        log.warn(output);
    }

    // debug(...), info(...), etc.
}

But it is being used thusly:

new Log()
    .warn((Exception)new RuntimeException().fillInStackTrace(), "I'm warning you.");

When reviewing this, my comments included things like the "Exceptions are exceptional" idiom.

But when I mentioned that creating a stack trace is an expensive operation and should be avoided, I was told that this used to be true in the past [e.g. with JVM implementations] but is now longer true [i.e. This has been fixed/optimized].

I was not aware of this development, so I checked around and most of the SO questions seem to indicate that making a stack trace is expensive.

Does this code seem reasonable? Would you consider this bad practice?

Answer 1

It seems like you're working harder than you need to. Instead of this:

public void warn(Exception cause, String message) {
    String output = message + "\n" + stackTrace(cause);
    log.warn(output);
}

I think you could do this, and no need for the stackTrace method:

public void warn(Exception cause, String message) {
    log.error(cause.getMessage() + " " + message, cause);
}

Moreover, notice how common libraries use a String as the first parameter of logging methods, and a Throwable as the second. I suggest to follow that example and reorder your parameters.

Answer 2

In your wrapper, I would reverse the order of the parameters of warn to be consistent with SLF4J, and maybe check isWarnEnabled() before doing any processing.

This:

new Log()
    .warn((Exception)new RuntimeException().fillInStackTrace(), "I'm warning you.");

could be:

Log.warn("I'm warning you.", new Exception());

or you could just use SLF4J directly:

log.warn("I'm warning you.", new Exception());

If you don't want to use exceptions, you can create a stacktrace yourself:

private static String stackTrace() {
    StringBuilder trace = new StringBuilder();
    for(StackTraceElement element:Thread.currentThread().getStackTrace()) {
        trace.append("  ").append(element).append("\n");
    }
    return trace.toString();
}

Performance

On my computer, I can call the method above 254,000 times a second, and your one 190,000 times a second.

Getting a stacktrace is relativly slow with any method, but that doesn't mean it'll be a bottleneck. Yes, it takes a few microseconds but how much total time is that going to be and how does it compare with everything else your program needs to do? If your program's producing thousands of warnings a second, then the logs would become unmanageable before there's a performance issue. Profile the full program with realistic inputs to find if there is an issue. You can always disable the stacktrace later if needed.

Besides performance, are stacktraces useful?

Stacktraces are useful for actual exceptions because otherwise you wouldn't even know where the error is. There can be many lines where the exception could have been thrown from, and multiple layers of callers that could be the source of the error so the stacktrace is essential in that case.

For warnings, I've never felt the need for stacktraces. They don't have the same usefulness. They might be useful for cases that border on errors. In which case, keep the exception as an optional parameter, and only use it in a few cases.

The drawbacks would be that it makes the code slightly more complex, and people could see the stacktrace and think that there was an exception when there wasn't.

Exception or currentThread().getStackTrace()?

Exceptions are slightly slower but if they're nowhere near a bottleneck then I would at least consider them over currentThread().getStackTrace(). The code is simpler, you can remove your wrapper completely, and the stacktrace is kept separately from the message. This allows, for example, logging to a database with the stacktraces in separate tables.

Conclusion

There are enough layers of facades when logging so I'm reluctant to add any more. I'd just keep it simple and use SLF4J directly with log.warn("Message") etc. If you want a stacktrace, just use log.warn("Message", new Exception()). This keeps it to a few specific messages because it's unlikely you'd want every warning to have a stacktrace. With only a few messages, there's unlikely to be any performance issue and the program shouldn't really have that many active warnings anyway.

Answer 3

Creating a stack trace is expensive. More expensive than you may realize. It also has synchronization impacts, so it may affect more than you realize.

Consider this code in Throwable. It shows that, if the trace is already populated, it will not be populated again (it is in a synchronized method):

public synchronized Throwable  fillInStackTrace() {
     if (stackTrace != null ||
         backtrace != null /* Out of protocol state */ ) {
         fillInStackTrace(0);
         stackTrace = UNASSIGNED_STACK;
     }
     return this;
}

Note that

Now, your warn method is creating a new RuntimeException, just to print the trace. Moreover, it fills in the trace, even though that is not needed.

Let's compare the performance here. I built three methods in to this ideone here:

private static final long countReuse() {
    final long until = System.currentTimeMillis() + 500;
    long len = 0;
    long count = 0;
    RuntimeException except = new RuntimeException("Static");
    do {
        len += stackTrace(except).length();
        count++;
    } while (System.currentTimeMillis() < until);
    System.out.println("Reuse " + len);
    return count;
}

private static final long countRecreate() {
    final long until = System.currentTimeMillis() + 500;
    long count = 0;
    long len = 0;
    do {
        len += stackTrace(new RuntimeException("Static")).length();
        count++;
    } while (System.currentTimeMillis() < until);
    System.out.println("Recreate " + len);
    return count;
}

The first method counts how many times it can 'build' the stack trace message using the same exception each time. The second method creates a new exception each time. The third method is the same as the second, but it fills in the stack trace. Finally, I added a fourth method that just does some String concatenation.....

How much does the new exception slow down the process?

Real: Reuse 86512 Recreate 48545 Filled 43361 String 512596

So, about 40,000 exceptions per half-second, 45000 exceptions if you include the unnecessary fillInStackTrace(). But, the actual printing of the stack trace? Well, that's 450,000 times...

In other words, printing the stack trace is about 10 times slower than creating the exception. Creating the exception is not fast either.

Bottom line is that, if you don't have an exception, then there's no real reason to create one. If you want to create a trace just to create a warning message, well, that's an indication that the warning should be more severe....

Once you know where the costly parts are you can make a better decision as to what's important.

Finally, I have seen significant improvements in performance when people make better use of exceptions..... but my experience goes back to the Java 1.3 times, when things were different.