Zarar Siddiqi's Blog

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 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.

Comments

• You can also call Thread.currentThread().getStackTrace().

  Posted by: keithkml on November 14, 2005 at 02:02 PM

• 
  It seems like the pain of typing out the method name when logging is unavoidable.

  
  Not if you're using IntelliJ IDEA.
  All I have to do is type 'entry', hit Tab, and my entry template, which looks like this:

  log.entry("$METHOD$()");
  automatically expands to include the name of the current method.

  Posted by: grlea on November 14, 2005 at 03:13 PM

• 
  IntelliJ is a great tool. However, I was referring to the programming aspects of returning the method name. Does IntelliJ also print out the line number?

  
  As for calling Thread.currentThread().getStackTrace(), I think the performance hit is the same as creating a Throwable instance. I could be wrong.

  Posted by: zarar on November 14, 2005 at 03:26 PM

• I got burned by this using a Weblogic JVM, which didn't create stack traces in the same format as a Sun JVM, thereby creating a lot of garbage in detailed log files. As of Java 1.4, use java.lang.StackTraceElement instead, which lets you discover the line number using a method call. This information may or may not be present depending on the options passed to your compiler (usually javac), in particular the options for debugging.

  Posted by: chris_e_brown on November 15, 2005 at 01:23 AM

• Did you run any benchmark/profiler about this?
  From a very simple benchmark I found no differences with or without %M%L in the log4j pattern.
  How much do you expect it to cost in a real app with database access, log file writing, ecc.? I think hard drive access and network times are much much higer than this.

  Posted by: trz on November 15, 2005 at 03:35 AM

• I always have a link to the doc in my log4j.properties for other developers and myself to refer to:
  http://logging.apache.org/log4j/docs/api/org/apache/log4j/PatternLayout.html

  And also have one version of the conversion pattern that includes line numbers, class name, etc with a big warning that it is not to be used in production because its slow. But that is usually commented out and only used when needed in development, and the production version of the conversion pattern is in place by default.

  Posted by: ucg2 on November 15, 2005 at 06:59 AM

• I'm not an expert, but I thought log4j logging was done asynchronously. Could be wrong of course, but if all that is happening it it's own thread, what difference does it make if it takes a few milliseconds for that line number to show up in the log file. It won't effect your application.

  Posted by: mikemaruffi on November 16, 2005 at 04:48 AM

• "Keep in mind that constructing stack traces is a fairly expensive operation.": Yes.

  "This is the only way to retrieve the logging information requested via the PatternLayout class.": No.

  See "Logging with whereabouts using open source and freeware" at http://www.acelet.com/whitepaper/loggingWithWhereabouts.html and
  SuperLogging at http://www.acelet.com/super/SuperLogging/.

  You can get whereabouts and with a single click you can see the line of code.
  

  Posted by: wei_jiang on November 16, 2005 at 05:07 AM

• 
  Mike, the performance benefits of not specifying method level information is significant (atleast in Log4J). Try running a profiler with and without the options.

  
  I checked out SuperLogging. Seems interesting but you have to pay for it. Any ideas on how it retrieves this information? I find that in most cases, I don't need to see a line number in the logs as long as the log message is verbose and contains the method name. The best option seems to be to use a good IDE which does the work for you - like IDEA.
  

  Posted by: aferrell on November 16, 2005 at 06:47 AM

• SuperLogging is free: you can download standard license from http://www.acelet.com/super. The license is perpetual with full functionality.
  

  Posted by: wei_jiang on November 16, 2005 at 07:31 AM

• In the case of java.util.logging (which i think is better purer approach, since customisation is achieved by extending default classes and overriding behaviour, rather via configuration in a config file, but thats just my opinion innit), its the same mechanism, and happens in the inferCaller() method of LogFormat. So it creates intsance of Throwable, does getStackElements(), and iterates back until the class is not Logger, ie. it is the class that invoked the log method. There is a bug in this tho when you extend Logger, and in this case you should implement inferCaller() yourself and set the class and method name on the LogRecord. There is a problem with that, that you can't set the line number tho.

  Posted by: evanx on November 16, 2005 at 10:23 AM

• I think Sun should solve this problem for us. Having to take a snapshot of the stack hardly seems acceptable (that's how I usually do it in my code though). A better solution may be to do what others suggested: let an automated tool insert the line number in your source code (a macro).

  Posted by: dog on November 16, 2005 at 06:05 PM

• Judging by some of the complaints raised here, many people don't know about Just4Log. It provides automatic method logging. There is also this technique for speeding up Log4J.

  Posted by: coxcu on November 18, 2005 at 07:15 AM

• Hi,

  The Java/J*EE Performance Management Insight Article series on our website (http://www.jinspired.com) discusses the cost of this call and compares it with JXInsight's Tracer implementation.

  http://www.jinspired.com/products/jdbinsight/callstackbenchmark.html

  Regards,

  William Louth
  JXInsight Product Architect
  JInspired

  "J*EE tuning, testing and tracing with JXInsight"
  http://www.jinspired.com
  

  Posted by: wlouth on November 19, 2005 at 10:19 AM

This work is licensed under a Creative Commons License.