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.
