Sneaky, sneaky Log4J
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
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.