How Java logging frameworks determine caller class and method name

This post describes how java logging frameworks (log4j, for example) know the exact place in code (class and method name), where the logging statement was invoked.

I decided to write this post because often I meet developers who do not understant what is the cost of writing caller information to logs, or why the cost is so high.

Brief log4j configuration and usage overview

A logger is identified by its name (a.k.a. category). Common myth here, is that the logger is somehow connected with the class it is declared in. The myth is based on the signature of the factory method:

private static final Logger log = LogManager.getLogger(MyService.class);

but that’s just a shortcut for

LogManager.getLogger(MyService.class.getName());

Category vs Caller class name

Consider the following example

package my.pkg;

public class MyService {

  private static final Logger log1 = LogManager.getLogger(MyService.class);
  private static final Logger log2 = LogManager.getLogger("a-logger");

  public void f() {
    log1.debug("I got MyService.class as parameter");
    log2.debug("I'm a walrus");
  }
}

If we configure both loggers with the pattern %c - %m%n‎[1], the call to f() will result in the following logs

my.pkg.MyService - I got MyService.class as parameter
a-logger - I'm a walrus

But if we use capital %C in the pattern, then the call to f() will yield

my.pkg.MyService - I got MyService.class as parameter
my.pkg.MyService - I'm a walrus

Notice how the second logger figured the caller class name, having no prior knowledge about the MyService class.

JVM Stacktraces

Before JVM enters any method, it records the point from which this method is invoked to be able to return to that same point later, after the method returns. Let’s look at simple example

public class Example {
  public static void main(String[] args) { a(); }
  static void a() { getCallerInfo(); }
  static void getCallerInfo() { b(); }
  static void b() { throw new RuntimeException(); }
}

Method b() throws an exception. Exception reaches the very top without being caught and its stacktrace gets printed to System.err:

Exception in thread "main" java.lang.RuntimeException
 at Example.b(Example.java:7)
 at Example.getCallerInfo(Example.java:6)
 at Example.a(Example.java:5)
 at Example.main(Example.java:4)

Having that stacktrace it is easy to say, that method getCallerInfo() has been called from method a(). So if we could get that stacktrace in runtime somehow and analyze it, we could find an invocation point for any method in our application.

Obtaining stacktrace

There are few ways to get stacktrace in Java: Thread.getStackTrace and Throwable.getStackTrace(). Both methods return array of StackTraceElement.

Throwable.getStackTrace()

Usage is as simple as

new Throwable().getStackTrace();

Stacktrace gets filled in when Throwable is created, so no need to throw it. Moreover, it is possible to reuse the same Throwable instance calling fillInStacktrace() to refresh stacktrace when needed (of course, keeping in mind possible race conditions if shared across threads). Under the hood native method Throwable.fillInStackTrace(int dummy) is invoked eventually.

Thread.getStackTrace()

Usage is

Thread.currentThread().getStackTrace();

Although a bit cleaner, this method does not give other benefits and is a bit slower (it has to check, whether stack trace is obtained for current thread of for some other thread, doing necessary security checks if required). And in the end stacktrace is obtained from new Exception instance in a way described above.

Working example

So we learned how to obtain an array of StackTraceElement. We need to iterate through that array and find an elelement belonging to our logger:

"debug".equals(methodName) & "my.pkg.Logger".equals(declaringClass)

Here is very simple straightforward implementation of a logger, which knows everything about its caller.

public class Logger {

  /**
   * Log message to stderr along with the caller class and method name.
   * @param msg message to log
   */
  public final void log(String msg) {
    StackTraceElement[] stackTrace = new Throwable().getStackTrace();
    // Index of StackTraceElement in stacktrace, where our logger appears.
    int i = getSelfElementIndex(stackTrace));
    // Caller is the next item down the stack.
    StackTraceElement caller = stackTrace[i + 1];
    System.err.println(caller.getClassName() + "." + caller.getMethodName() + ": "
       + msg);
  }

  private int getSelfElementIndex(StackTraceElement[] stackTrace) {
    for (int i = 0; i < stackTrace.length; i++) {
      StackTraceElement el = stackTrace[i];
      // We don't need to check method name, our logger has only one method.
      if (el.getClassName().equals(this.getClass().getName())) {
        return i;
      }
    }
    throw new IllegalStateException("Logger doesn't appear in stacktrace");
  }
}

So what about log4j?

Of course, it’s a bit more complicated than that, but the basic principle remains the same. If you are interested in the specifics, see

org.apache.log4j.spi.LocationInfo
org.apache.log4j.helpers.PatternParser.LocationPatternConverter

%c (category), %m (message), %n (new line). See PatternLayout ↩