views:

114

answers:

3

Like many log4j users, we often have debug level logging that is expensive to evaluate. So we guard those cases with code like:

if( _logger.isDebugEnabled )
  _logger.debug("Interesting, my foojes are goofed up: " + getFullDetails())

However, that is uglier than a plain _logger.debug call, and sometimes the programmer doesn't realize the evaluation could be expensive.

It seems like it should be fairly simple to write a program that takes a compiled jar and guards all the _logger.debug calls with the isDebugEnabled check. We would likely be willing to accept the extra overhead of checking isDebugEnabled in all cases.

Has anyone tried this approach, or done similar post-processing of a jar?

+4  A: 

Rather than looking at modifying the jar, I'd search for a solution using Bytecode Instrumentation. The problem will be to identify those parts of the code you want to wrap inside a .isDebugEnabled() - you will have to identify objects that are only used for log4j invocations.

sfussenegger
I guess you could backtrack from the `ivokevirtual` on `debug` to find the `getfield` instruction that got the logger. There might be cases where it is ambiguous where the logging call begins and ends, though. It is worth investigating.
McDowell
+1  A: 

I believe a good solution would be that the code would be efficient as is.

Consider that log4j is deprecated. Its author itself left it as is, to avoid breaking compatibility, but he created a new one, SLF4J (http://www.slf4j.org/ ). He provides both a facade and an implementation, according to the distinction commons-logging/log4j, but without the flaws of each...

I believe that, in this new logging facility, you can send Object parameters to the logging, and that the level is evaluated before converting the Objects (to String or otherwise). The idea is to use a format string, and parameters.


Our code doesn't use slf4j, but we have utility methods that do exactly that. It is coded roughly as follow (from memory):

    public enum LogLevel {
       FATAL, ERROR, WARNING, INFO, DEBUG;

       public void log(Logger logger, String format, Object... parameters) {
         if (isEnabled(logger)) {
            logImpl(logger, String.format(format, parameters));
         }
       }
       public boolean isEnabled(Logger logger) {
         switch(this) {
           case WARNING : return logger.isWarningEnabled();
           case INFO : return logger.isInfoEnabled();
           case DEBUG : return logger.isDebugEnabled();
           default: return true;
         }
       }
       private void logImpl(Logger logger, String message) {
         switch(this) {
           case WARNING : logger.warn(message);
           // other cases
         }
       }
    }

It is used as:

     public void myMethod(Object param) {
       LogLevel.WARNING.log(LOGGER, "What is my message ....", "myMethod", param);
     }


UPDATE : If you need to call a method in the log...

  • One possibility is to use toString method. This is appropriate if your logging is 'technical', and will be used also when debugging.

  • If your logging is more functional (not targeted to the developper), I suggest to define an interface (it is functionally sound in that case, so it is useful to provide meaning) :

    public interface Detailable { // the name could also suggest logging?
      String getFullDetails();
    }
    

    Implement that interface in any object that need to be passed as logging object, with a complex calculation to build the log.

KLE
Passing objects into logging call does not help. The cost is in evaluating getFullDetails.
Ted Graham
@Ted, if you change getFullDetails to provide an object that does the evaluation in its toString method that would effectively delay the work. That would help all cases except where "the programmer doesn't realize the evaluation could be expensive."
Yishai
You could to something like this: `log.debug("Interesting, my foojes are goofed up: {}", new Object() { String toString() {return getFullDetails());` - but is this prettier than the original? :)
sfussenegger
I support Yishai's proposal. I incorporated it in my answer, along with the other possibility I see, and the criteria to use to choose between them.
KLE
+2  A: 

Have you looked at AspectJ ? This supports aspects using bytecode weaving, and can interceptions into a previously compiled .jar file.

Brian Agnew
Very helpful, this is closest to what I was looking for.
Ted Graham
I don't see how this helps with the test example. Even if you set a pointcut on `Logger.debug(String)` with `around` advice to prevent it being invoked, `getFullDetails()` will still be called.
McDowell