I started working with AspectJ and Perf4J recently. I did not have any prior AOP experience. I was looking for an example which did not use Spring AOP but I did not find a good sample which I could use to get my work done. Therefore, once I completed my project, thought of writing this sample up. There are a lot of tutorials out there which describes what AOP is. Therefore, I’m not going to introduce it here. You can do a Google search and find it out.
What I wanted was to measure the method runtimes without doing any modifications to the existing source. AspectJ helped me to achieve that.
Following are my sample source code.
Following is my test class which I'm using to measure method runtimes.
import org.apache.log4j.Logger;
public class TestTarget {
static Logger logger = Logger.getLogger(TestTarget.class);
public static void main(String[] args) throws Exception {
// Test case 01
testCountFast(1000);
// Test case 02
testCountSlow(1000);
}
public static void testCountSlow(int value) {
count(value,5);
}
public static void testCountFast(int value) {
count(value,0);
}
private static void count(int value, int delay) {
for (int i=0;i<value;i++) {
try {
Thread.sleep(delay);
} catch (Exception e) {
logger.error("Error occurred while sleeping", e);
}
}
}
}
Following is my Aspect class which uses AspectJ and Perf4J.
import org.apache.log4j.Logger;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.perf4j.StopWatch;
import org.perf4j.log4j.Log4JStopWatch;
@Aspect
public class Perf4JAspect {
static Logger logger = Logger.getLogger(Perf4JAspect.class);
@Around("execution (* com.company.molva.aspectj.TestTarget.test*(..))")
public Object measureExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
logger.info(MolvaLoggingUtil.getCurrentDateTime()
+ " MainAspect.measureExecutionTime() called on " + joinPoint.getSignature());
long startNanoTime = System.nanoTime();
StopWatch stopWatch = new Log4JStopWatch();
Object proceed = joinPoint.proceed();
stopWatch.stop(joinPoint.getSignature().toLongString());
long endNanoTime = System.nanoTime();
long executionNanoTime = endNanoTime - startNanoTime;
logger.info(MolvaLoggingUtil.getCurrentDateTime() + " "
+ joinPoint.getSignature()+" took "+ executionNanoTime/1000000.0 +"ms");
return proceed;
}
}
My aop.xml configuration is as follows.
<aspectj>
<aspects>
<aspect name="com.company.molva.aspectj.MainAspect"/>
<aspect name="com.company.molva.aspectj.Perf4JAspect"/>
</aspects>
<weaver options="-verbose">
<include within="com.aspectj.*"/>
</weaver>
</aspectj>
My log4j.xml looks as follows.
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration debug="false" xmlns:log4j="http://jakarta.apache.org/log4j/">
<appender name="aspectjFileAppender" class="org.apache.log4j.FileAppender">
<param name="File" value="aspectj_stats.log"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%m%n"/>
</layout>
</appender>
<appender name="CoalescingStatistics"
class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
<param name="TimeSlice" value="10000"/>
<appender-ref ref="fileAppender"/>
</appender>
<appender name="fileAppender" class="org.apache.log4j.FileAppender">
<param name="File" value="perf_stats.log"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%m%n"/>
</layout>
</appender>
<logger name="org.perf4j.TimingLogger" additivity="false">
<level value="INFO"/>
<appender-ref ref="CoalescingStatistics"/>
</logger>
<root>
<level value="INFO"/>
<appender-ref ref="aspectjFileAppender"/>
</root>
</log4j:configuration>
Once the sample completes running, I get the following logs at my log files.
aspectj_stats.log:
2014-01-30 13:19:25 MainAspect.measureExecutionTime() called on void com.company.molva.aspectj.TestTarget.testCountFast(int)
2014-01-30 13:19:25 void com.company.molva.aspectj.TestTarget.testCountFast(int) took 0.904ms
2014-01-30 13:19:25 MainAspect.measureExecutionTime() called on void com.company.molva.aspectj.TestTarget.testCountSlow(int)
2014-01-30 13:19:31 void com.company.molva.aspectj.TestTarget.testCountSlow(int) took 5608.996ms
perf_stats.log:
Performance Statistics 2014-01-30 13:19:20 - 2014-01-30 13:19:30
Tag Avg(ms) Min Max Std Dev Count
public static void com.company.molva.aspectj.TestTarget.testCountFast(int) 0.0 0 0 0.0 1
public static void com.company.molva.aspectj.TestTarget.testCountSlow(int) 5608.0 5608 5608 0.0 1
As you can see, we can use AspectJ and Perf4J to generate some nice statistics.
