To enable Performance Profiling log with Guice AOP and Logback

I always want my methods to be profiled, so that I can learn about how fast/slow it is from a high level perspective at first. Then break it down to make it even faster.

I am using WebDriver to do automation testing, so i want to trace certain end user experience from performance perspective as well.

For example, if I want to measure Login action's response time, my intention is to enable my profiling log by just add @Profiled annotation in front of corresponding "Login" method:

 
@Profiled
public void clickLoginBtn() throws InterruptedException{  
           driver.findElement(By.id("login")).click();  
           if(!myWaiter.waitForMe(By.cssSelector("div.starcite-hyperlink"), 25, timeout)) return ;  
      }  

To make @Profiled work, i chose Guice as it is so called light weight and easy of use:

Step1: Create an annotation called Profiled:

 import java.lang.annotation.ElementType;  
 import java.lang.annotation.Retention;  
 import java.lang.annotation.RetentionPolicy;  
 import java.lang.annotation.Target;  
 @Retention(RetentionPolicy.RUNTIME)  
 @Target(ElementType.METHOD)  
 public @interface Profiled {  
 }  

Step2:Create matchers for the classes and methods to be intercepted：

 import com.google.inject.AbstractModule;  
 import com.google.inject.matcher.Matchers;  
 public class ProfiledModule extends AbstractModule {  
      @Override  
      public void configure() {  
           // TODO Auto-generated method stub  
           PerfTracing perftracing = new PerfTracing();  
           requestInjection(perftracing);  
           bindInterceptor(  
                     Matchers.any(),  
            Matchers.annotatedWith(Profiled.class),  
            perftracing);  
        }  
      }  

Step3: Write your own MethodInterceptor to do profiling using Logback

 import java.util.Arrays;  
 import org.aopalliance.intercept.MethodInterceptor;  
 import org.aopalliance.intercept.MethodInvocation;  
 import org.slf4j.Logger;  
 import org.slf4j.LoggerFactory;  
 public class PerfTracing implements MethodInterceptor{  
      private Logger logger = LoggerFactory.getLogger("PerfLog");  
      @Override  
      public Object invoke( MethodInvocation invocation) throws Throwable {  
           // TODO Auto-generated method stub  
           long start = System.nanoTime();  
     try {  
       return invocation.proceed();  
     }   
     finally {  
          if(logger.isDebugEnabled()){  
               Object[] paramArray = {     invocation.getMethod().getName(),   
                                             Arrays.toString(invocation.getArguments()),   
                                             (System.nanoTime() - start) / 1000000};  
            logger.debug("Invocation of method: {} with parameters: {} took: {} ms." , paramArray);  
          }  
     }  
      }  
 }  

Why I choose Logback for logging? please refer to this post :)

For Logback configuration, here is my sample:

 <?xml version="1.0" encoding="UTF-8"?>  
 <!-- Reference Manual http://logback.qos.ch/manual/index.html -->  
 <configuration>  
   <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">   
     <encoder charset="UTF-8">  
       <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>  
     </encoder>  
   </appender>   
   <appender name="PerfLog" class="ch.qos.logback.core.rolling.RollingFileAppender">  
     <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">  
       <fileNamePattern>PerfLog-%d{yyyy-MM-dd}.log</fileNamePattern>  
       <maxHistory>30</maxHistory>  
     </rollingPolicy>   
     <encoder>  
       <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>  
     </encoder>  
   </appender>  
   <logger name="PerfLog" additivity="false">  
        <level value="DEBUG"/>  
        <appender-ref ref="PerfLog" />  
   </logger>  
   <root level="ERROR">  
     <appender-ref ref="stdout" />  
   </root>  
 </configuration>  

The output in your log file should be like this:

 15:02:49.351 [main] DEBUG PerfLog - Invocation of method: clickLoginBtn with parameters: [] took: 3027 ms.  

Please notice Guice AOP's Limitations:

* Classes must be public or package-private.
* Classes must be non-final
* Methods must be public, package-private or protected
* Methods must be non-final
* Instances must be created by Guice by an @Inject-annotated or no-argument constructor

So You may have to change your source code to make Guice AOP work properly.