Injecting timing aspect into JUnit test in Eclipse using AspectJ, AJDT
Introduction
This blog describes my experience with using AOP, namely AspectJ, to measure the individual execution times and their average of a particular low-level method invoked many times during a JUnit test run from within Eclipse. It concentrates on creating the aspect and integrating (weaving) it into the JUnit test execution in the Eclipse environment.Of course it would be easier to use e.g. profiler but I wanted to play with AOP/AspectJ to learn it better because it's an incredibly useful tool for a number of problems and you can use it even if you don't have access to the application's source code and/or cannot control the runtime environment (such as running it in a profiler).
Why AspectJ?
There are also other AOP tools for Java but it seems that AspectJ is the most wide-spread one, especially since its merge with AspectWerkz. I used to dislike it because it required a special extended Java syntax and compiler but this isn't true anymnore (more on that later).Disclaimer
I'm only learning AspectJ, so the solution may be not and likely isn't the best one. I appreciate improvement suggestions.Preparing the environment
I use Pulse to set up my Eclipse environment. For this I'll use:- Eclipse 3.4 for Java EE (Pulse doesn't yet support 3.5)
- AJDT 2.0.0
- AspectJ 1.6.5
- JUnit 4
- JDK 1.5.0.18 (the test fails with 1.6 due to xml libs incompatibility) and Java 5.0 syntax
Implementing the timing aspect
My goal is to create an aspect invoked around the method in question that will measure the time it takes for the method to execute, log it, and compute and log the average execution time.Since AspectJ 5 we have two options - either using the older custom AspectJ syntax with AspectJ compiler or using annotations. I'll explore both possibilities.
Project structure
First, we have a Java project with the junit test that we want to run with the timing aspect. It depends on another project with the actual class and method whose performance we want to measure.MyLibraryProject
- /src/main/java/com/tonbeller/jpivot/xmla/XMLA_SOAP.java
- /src/main/java/
- eu/ibacz/studna/jpivot/OLAPModelStructure.java - calls (indirectly) XMLA_SOAP.discoverMem during its execution
- /src/test/java/
- eu/ibacz/studna/jpivot/OLAPModelStructurePerformanceTest.java - standard JUnit4 test case
MyAspectProject
- /src/
- eu/ibacz/pbns/util/aspect/TimingAspect.aj (solution 1)
- eu/ibacz/pbns/util/aspect/TimingAnnotatedAspect.java (solution 2)
Solution 1: using custom ApectJ syntax
Before AspectJ 5 this was the only option and it is still more powerful and has better support of AJDT (according to the FAQ). Basically you write the aspect in an extended Java syntax in an .aj file and compile it with a special AspectJ compiler - though this is done behind the scene for you thanks to having created an AspectJ project, which also provides you with a special AspectJ/Java editor for .aj and .java aspect files.Enough talking, let's see the aspect:
File eu/ibacz/pbns/util/aspect/TimingAspect.aj:
package eu.ibacz.pbns.util.aspect;
import ...
public aspect TimingAspect {
// instance/class field ...
public TimingAspect() {
formatter = NumberFormat.getIntegerInstance();
formatter.setMinimumIntegerDigits(3);
System.out.println(getClass() + " instantiated!");
}
// before(): execution(public * com.tonbeller.jpivot..XMLA_SOAP.*(..) ) {
// System.err.println("About to call " + thisJoinPoint.getSignature().toShortString() + ", args:" + Arrays.toString(thisJoinPoint.getArgs()) );
// }
Object around() : execution( * com.tonbeller.jpivot..XMLA_SOAP.discoverMem(..) ) {
final long startTimeCpuMs = getCurrentTimeMs();
final long startTimeMs = System.currentTimeMillis();
Object result = proceed();
final long endTimeMs = System.currentTimeMillis();
final long endTimeCpuMs = getCurrentTimeMs();
final long execTimeMs = endTimeMs - startTimeMs;
final long execTimeCpuMs = endTimeCpuMs - startTimeCpuMs;
++totalExecutionCount;
totalExecutionTimeMs += execTimeMs;
totalCpuExecutionTimeMs += execTimeCpuMs;
final String msg = "executing discoverMem #" + formatter.format(totalExecutionCount) +
" took " + execTimeCpuMs + "ms of CPU, " +
execTimeMs + "ms real; current average is [ms/call]: " +
totalCpuExecutionTimeMs / totalExecutionCount + " for CPU, " +
totalExecutionTimeMs / totalExecutionCount + " real time.";
System.out.println(getClass().getName() + ": " + msg);
return result;
}
}
(I've ommited the fields and some methods for brevity.)
PS: You can use the commented-out before adivce to print all methods called on XMLA_SOAP including their name and arguments. This is useful to find out whether the method you're trying to measure is actually called at all.
Solution 2: using annotation (@AspectJ)
Since AspectJ 5 we can use a normal Java class with special annotations to define an aspect. It's less powerful (see above) but more familiar to a Java developer and more comfortable to use since it doesn't need any special compiler (the annotations are processed by AspectJ during weaving).File eu/ibacz/pbns/util/aspect/TimingAnnotatedAspect.java:
package eu.ibacz.pbns.util.aspect;
import ...
public class TimingAnnotatedAspect {
// instance/class field ...
public TimingAspect() {
formatter = NumberFormat.getIntegerInstance();
formatter.setMinimumIntegerDigits(3);
System.out.println(getClass() + " instantiated!");
}
@Around("execution( * com.tonbeller.jpivot..XMLA_SOAP.discoverMem(..) )")
public Object around(ProceedingJointPoint pjp) {
final long startTimeCpuMs = getCurrentTimeMs();
final long startTimeMs = System.currentTimeMillis();
Object result = pjp.proceed();
final long endTimeMs = System.currentTimeMillis();
final long endTimeCpuMs = getCurrentTimeMs();
final long execTimeMs = endTimeMs - startTimeMs;
final long execTimeCpuMs = endTimeCpuMs - startTimeCpuMs;
++totalExecutionCount;
totalExecutionTimeMs += execTimeMs;
totalCpuExecutionTimeMs += execTimeCpuMs;
final String msg = "executing discoverMem #" + formatter.format(totalExecutionCount) +
" took " + execTimeCpuMs + "ms of CPU, " +
execTimeMs + "ms real; current average is [ms/call]: " +
totalCpuExecutionTimeMs / totalExecutionCount + " for CPU, " +
totalExecutionTimeMs / totalExecutionCount + " real time.";
System.out.println(getClass().getName() + ": " + msg);
return result;
}
}As you can see, we've replaced the special AspectJ syntactical elements with annotationes @Aspect and @Around (there is also @Pointcut and others).
(I've ommited the fields and some methods for brevity.)
Conclusion: Annotations vs. custom syntax
When deciding whether to use the the old custom AspectJ syntax and .aj files with an AspectJ compiler or the new annotation-based aspects in standard .java files you have to take into account that the annotation-based aspects are less powerful (regarding what all can be weaved) and have weaker support of the AJDT tooling so that your aspects may not display in its views etc.Common project info
For both projects we need to have the class to modify with the aspect, in our case XMLA_SOAP, on the classpath, to get some special support from AJDT (see below).The good thing when using AJDT is that if a pointcut definition (such as the execution(...) above) doesn't match an existing class/method, you will be warned about it - in Eclipse there will be the standard warning marker with text like "no match for this type name: XMLA_SOAP [Xlint:invalidAbsoluteTypeName]". This works both for .aj and .java files though it may not discover all issues.
The common code, if you're interested:
private ThreadMXBean threadMxb;
/**
* Return the current time in miliseconds, if possible, return only the current thread's CPU time, if not,
* return system time.
* <p>
* thread's CPU time is usually few times less than the absolute time between
* its start and end due to the fact that it has to share the CPU with other processes/threads.
*/
private long getCurrentTimeMs() {
return getThreadMxBean().isCurrentThreadCpuTimeSupported()?
threadMxb.getCurrentThreadCpuTime() / 1000000 : System.currentTimeMillis();
}
/** Lazy-init getter. */
private ThreadMXBean getThreadMxBean() {
if (threadMxb == null) {
threadMxb = ManagementFactory.getThreadMXBean();
if (threadMxb.isThreadCpuTimeSupported()) {
LOG.info("Thread user/cpu time monitoring supported.");
if (threadMxb.isThreadCpuTimeSupported() && threadMxb.isThreadCpuTimeEnabled()) {
LOG.info("Thread user/cpu time monitoring supported&enabled."); // TODO do only once
} else {
LOG.warn("Thread user/cpu time monitoring supported but disabled.");
}
} else {
LOG.warn("Thread user/cpu time monitoring NOT supported.");
} // supported thr. time
}
return threadMxb;
} /* getThreadMxBean */
Integrating the aspect into the JUnit test
Our tracing aspect is ready and we want to apply it to XMLA_SOAP.discoverMem when running our JUnit test OLAPModelStructurePerformanceTest. Unfortunately AJDT doesn't provide any support for running JUnit tests with AspectJ support though it does that for normal java programs via the additional Run As... > AspectJ/Java Application menu item therefore we will need to do it manually. Maybe there is a better way but this is what I did:- Get aspectjweaver.jar - it includes complete AspectJ runtime plus Java 5 agent lib.
- Modify the Run configuration of the JUnit test (Run > Run Configurations) as follows:
- On the tab Arguments, add the VM argument -javaagent:/path/to/aspectjweaver.jar
- On the tab Classpath, click on User Entries and add there the project MyAspectProject so that it can see the aspect.
- In the project MyTestProject create under /src/test/java/ (or any other source folder) META-INF/aop.xml with the content shown below.
<aspectj>
<aspects>
<!-- aspect name="eu.ibacz.pbns.util.aspect.TimingAspect"/--> <!-- fails if not found -->
<aspect name="eu.ibacz.pbns.util.aspect.TimingAnnotatedAspect"/>
</aspects>
</aspectj>
This file tells AspectJ's Load-Time Weaver what aspects to introduce into the existing classes. Without it no instrumentation would occur. You can configure here which of the 2 aspects to use. You can also "specify the set of types that should be woven. If no include elements are specified then all types visible to the weaver will be woven". See the documentation on aop.xml and Load-Time Weaving configuration for more info.
Troubleshooting load-time weaving
If you need to learn more about what AspectJ does during the weaving and whether it does modify the target class or not (e.g. due to wrong pointcut match pattern or classpath order) you may enable some logging using either some properties on the command-line or by specifying this in the aop.xml:
<aspectj>
<aspects>
<!-- aspect name="eu.ibacz.pbns.util.aspect.TimingAspect"/--> <!-- fails if not found -->
<aspect name="eu.ibacz.pbns.util.aspect.TimingAnnotatedAspect"/>
</aspects>
<weaver options="-verbose -showWeaveInfo "> <!-- add -debug to print every class [not] woven -->
<include within="com.tonbeller.jpivot.xmla..*"/> <!-- Notice the 2 dots to include also subpackages -->
<include within="eu.ibacz..*"/>
</weaver>
</aspectj>
If the weaving proceeds as expected, this should produce an output similar to the one below:
[AppClassLoader@1858610] info AspectJ Weaver Version DEVELOPMENT built on Friday Aug 29, 2008 at 00:25:33 GMT [AppClassLoader@1858610] info register classloader sun.misc.Launcher$AppClassLoader@1858610 [AppClassLoader@1858610] info using configuration /home/jholy/devel/MyTestProject/target/classes/META-INF/aop.xml [AppClassLoader@1858610] info register aspect eu.ibacz.pbns.util.aspect.TimingAspect [AppClassLoader@1858610] info processing reweavable type com.tonbeller.jpivot.xmla.XMLA_Model: com/tonbeller/jpivot/xmla/XMLA_Model.java [AppClassLoader@1858610] info successfully verified type eu.ibacz.pbns.util.aspect.TimingAspect exists. Originates from eu/ibacz/pbns/util/aspect//home/jholy/devel/MyAspectProject/src/eu/ibacz/pbns/util/aspect/TimingAspect.aj [AppClassLoader@1858610] weaveinfo Join point 'method-execution(void com.tonbeller.jpivot.xmla.XMLA_Model.retrieveMemberChildren(com.tonbeller.jpivot.xmla.XMLA_Member))' in Type 'com.tonbeller.jpivot.xmla.XMLA_Model' (XMLA_Model.java:1094) advised by around advice from 'eu.ibacz.pbns.util.aspect.TimingAspect' (TimingAspect.aj:56)The line 'info register aspect eu.ibacz.pbns.util.aspect.TimingAspect' tells us that AspectJ has found the aspect referenced from aop.xml. If the aspect class didn't exist then it would print an error message. The information about registered aspects, configuration aop.xml and AspectJ version is displayed thanks to the option -verbose.
The line 'weaveinfo Join point ...' tells us that AspectJ has actually found and modified the target and is enabled with the -showWeaveInfo flag.
If you enabled -debug in aop.xml, AspectJ would print the list of classes that it has processed (whether there was an aspect to apply or not) - this can help you to verify that it doesn't ignore your target class.
Note: all weaver messages are prefixed with the classloader the weaver instance is attached to, e.g. in a web server you'd have multiple instances.
Conclusion
It works! :-)Limitations of aop.xml
AspectJ is extremely powerful, especially because it isn't limited to "advicing" or intercepting method calls but can also intercept field access, add fields, inject interface implementation into classes and much more.What I find quite limiting is that in aop.xml you cannot specify very much what should or should not be woven, only the classes to include in/exclude from the process. If you want to limit to what methods etc. your apect applies, you have to change that in its source code and recompile it :-)
Resources and links
- AspectJ Quick Reference - pdf, 4 pages.
- AspectJ: Semantics of pointcuts - we need the Type patterns described close to the very end
- AdviceTracer - JUnit extension for testing that advices get applied where they're expected to. An introductory presentation.