[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
[aspectj-users] Logger guard with aspectj

Hi!

In my project, there are nearly 5000+ log.* calls, and they have lots
of string concatenations in they argument.
As you know, these arguments are processed, no mather, the current log
level is applicable for a specific log call, or not.

For Example:

_log.info("This " + "is " + "an " + "info " + "level" + " log" + " call");

The arguments are processed by java at ERROR log level.

Based on profiler info, i found out, that this is a major performance
issue, so i need a solution.
You probably know, that log4j has a solution to that, what is called
"logger guard".

You applicate logger guard to performance critical log statements like this:

if(_log.isInfoEnabled())
       _log.info("This " + "is " + "an " + "info " + "level" + " log"
+ " call");

To insert these statements 5000+ places is no option for me, so i
wrote an aspectj aspect, to weave these into the code at compile time:


@Aspect
public class LoggerGuardAspect {

       public static String TRACE = "trace";
       public static String DEBUG = "debug";
       public static String INFO = "info";
       public static String WARN = "warn";
       public static String ERROR = "error";
       public static String FATAL = "fatal";

       private static Log _log = LogFactory.getLog(LoggerGuardAspect.class);

       @Pointcut("call(* org.apache.commons.logging.Log.*(..)) &&
!within(org.aspect.LoggerGuardAspect)")
       void loggerCall() {
       }

       @Around("loggerCall()")
       public Object guardLogger(ProceedingJoinPoint thisJoinPoint) {
               String methodName = thisJoinPoint.getSignature().getName();
               if (methodName.equals(TRACE))
                       return guardLogger(thisJoinPoint, _log.isTraceEnabled());
               else if (methodName.equals(DEBUG))
                       return guardLogger(thisJoinPoint, _log.isDebugEnabled());
               else if (methodName.equals(INFO))
                       return guardLogger(thisJoinPoint, _log.isInfoEnabled());
               else if (methodName.equals(WARN))
                       return guardLogger(thisJoinPoint, _log.isWarnEnabled());
               else if (methodName.equals(ERROR))
                       return guardLogger(thisJoinPoint, _log.isErrorEnabled());
               else if (methodName.equals(FATAL))
                       return guardLogger(thisJoinPoint, _log.isFatalEnabled());
               return null;
       }

       private Object guardLogger(ProceedingJoinPoint thisJoinPoint, boolean
isLevelEnabled) {
               try {
                       if (isLevelEnabled) {
                               return thisJoinPoint.proceed();
                       }
               } catch (Throwable e) {
                       // never happen
               }
               return null;
       }

}

I haven't experienced any performance boost with that aspect, so i
decompiled the weaven class to figure out what stuff aspectj exactly
inserted:

This is the original Test.java, before weave:

public class Test {

       private static Log _log = LogFactory.getLog(Main.class);

       public void loggedCall() {
               _log.info("hello");
       }

       public static void main(String[] args) {

               Main main = new Main();
               main.loggedCall();
       }

}

And this is the decompiled weaven version:

public class Main
{

   public Main()
   {
   }

   public void loggedCall()
   {
       String s = "hello";
       Log log = _log;
       JoinPoint joinpoint = Factory.makeJP(ajc$tjp_0, this, log, s);
       Object aobj[] = new Object[4];
       aobj[0] = this;
       aobj[1] = log;
       aobj[2] = s;
       aobj[3] = joinpoint;
       LoggerGuardAspect.aspectOf().guardLogger((new
AjcClosure1(aobj)).linkClosureAndJoinPoint(4112));
   }

   public static void main(String args[])
   {
       Main main = new Main();
       main.loggedCall();
   }

   static final void info_aroundBody0(Main main1, Log log, Object
obj, JoinPoint joinpoint)
   {
       log.info(obj);
   }

   private static Log _log = LogFactory.getLog(org/test/Main);
   private static final org.aspectj.lang.JoinPoint.StaticPart
ajc$tjp_0; /* synthetic field */

   static
   {
       Factory factory = new Factory("Main.java",
Class.forName("org.test.Main"));
       ajc$tjp_0 = factory.makeSJP("method-call",
factory.makeMethodSig("601", "info", "org.apache.commons.logging.Log",
"java.lang.Object:", "arg0:", "", "void"), 11);
   }

   private class AjcClosure1 extends AroundClosure
   {

       public Object run(Object aobj[])
       {
           Object aobj1[] = super.state;
           Main.info_aroundBody0((Main)aobj1[0], (Log)aobj1[1],
aobj1[2], (JoinPoint)aobj1[3]);
           return null;
       }

       public AjcClosure1(Object aobj[])
       {
           super(aobj);
       }
   }

}


Its not suprising that this code is not as fast as i expected. I can
see aspectj runtime calles, and other tricks.

Is there a way to get rid of these, or aspectj is simply not the
perfect solution to my problem?

Thanks