So I found myself wanting to know if I could print the enclosing method of the current line of code being executed. A quick look at the reflection API didn't yield much. A little reflective thinking later, I came to the conclusion that it's impossible for the reflection API to tell me this since it explores binary files at the class level.

Thats when it struck me that Log4J does exactly what I want to do. It can print out the method and line number of the code for each log.debug(..) call. So of I went digging into Log4J code looking for an answer. I found it.

What Log4J ends up doing is that for each debug(..) call, it creates an instance of Throwable which takes a snapshot of the runtime stack. It then proceeds to parse the stack to yield the current line of code being executed along with class and method information.

Keep in mind that constructing stack traces is a fairly expensive operation. When an Exception is created, the JVM needs to literally pause the processing and so it can get a good glimpse of the entire runtime stack - this includes classes, methods, line numbers etc - starting from Thread.run() all the way till the creation of Throwable. From the runtime's point of view, this is acceptable since it's not designed for great Exception handling but to run as fast as possible.

However, in the logging scenario, the culprit is the call to the Throwable.fillInStackTrace() method in the Throwable constructor which gets invoked on each debug(..), info(..) and other logging calls. This is the only way to retrieve the logging information requested via the PatternLayout class. Give Log4J credit since they only create the Throwable instance when the specific PatternLayout is specified; plus they have the decency to warn you about using the l, L and other expensive options.

Although descriptive logging can provide good roll-back mechanisms in production code, the cost incurred by specifying method and line numbers when logging is simply too high. It seems like the pain of typing out the method name when logging is unavoidable.

To some, this might come as old news but to many it'll make them change their log4j.properties.