The Holy Java

Building the right thing, building it right, fast

Archive for July, 2009

Injecting timing aspect into JUnit test in Eclipse using AspectJ, AJDT

Posted by Jakub Holý on July 10, 2009

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

MyTestProject

  • /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

We create another project to hold our new shiny aspect: File > New > Other… > AspectJ > AspectJ Project =>

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() &amp;&amp; threadMxb.isThreadCpuTimeEnabled()) {
                        LOG.info("Thread user/cpu time monitoring supported&amp;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:

  1. Get aspectjweaver.jar – it includes complete AspectJ runtime plus Java 5 agent lib.
  2. Modify the Run configuration of the JUnit test (Run > Run Configurations) as follows:
    1. On the tab Arguments, add the VM argument
      -javaagent:/path/to/aspectjweaver.jar
    2. On the tab Classpath, click on User Entries and add there the project MyAspectProject so that it can see the aspect.
  3. In the project MyTestProject create under /src/test/java/ (or any other source folder) META-INF/aop.xml with the content shown below.

File 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>
</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

Other

Posted in Languages | Tagged: , , , , , | 2 Comments »

See how Test Driven Development is done in practice

Posted by Jakub Holý on July 5, 2009

On the Manning site you can read the 2nd chapter of the book Test Driven – Practical TDD and Acceptance TDD for Java Developers by Lasse Koskela from 2007. The chapter 2: Beginning TDD let’s you follow the mental process of a programmer practicing TDD to implement a set of user stories. You’ve probably heard a lot about TDD on the theoretical level but this sample chapter gives you the unique opportunity to see the basic, practical level of TDD in action. I’m very glad to have read it.

The interesting thing is how he really always does the simplest possible solution (read ‘dummy and 0% generic’) to make the test pass and continuously adds tests and refactors the implementation to get the final code.

Posted in Testing | Tagged: , , | Comments Off

The quest for a portal web framework is over and the winner is: Spring Portlet MVC

Posted by Jakub Holý on July 4, 2009

For a long time I’ve been looking for a web framework that would ease the development of web UI in portlets. Pure JSP is too old-fashioned and the abstraction it provides is just too low-level. There are many good web frameworks for standard web applications (JSF/Seam, GWT, Struts 2, Wicket, you name it…) but if they include portlet support than only as an after-thought and it’s usually far behind the quality and features of the standard web framework. Nobody was able to recommend me a decent portlet web framework – until recently.

 First I’ve learned about an upcoming book Portlets in Action (preview) by Ashish Sarin, which teaches not only Portlets 2.0 (JSR 286) but also other must-haves for a real world development like a portlet web framework and Ajax (DWR in this case). You’ve surely already guessed that Ashish uses Spring Portlet MVC, which indicates that it must be indeed good.

Than I’ve been surprised to learn that my good and trustworthy collegue, Vlado, is using Spring Portlet MVC on his project. He had but positive words about the framework: "It’s excellent, I wouldn’t make portlets with anything else. It’s enough lightweight, it helps where it should and doesn’t limit you anyhow."

The only issue is that the current stable release doesn’t support JSR286 yet (events, resource serving…). Fortunately the upcoming release of Spring 3.0 will support it. Spring 3.0 M3 have been released in May 2009 (more about Portlet 2.0 support on M2 release page), RC1 should have been released in June. You can learn about details in the corresponding Jira issue.

Update 2/2010:  Liferay uses quite a lot Struts to build its portlets, for instance when developing a portlet as an EXT plugin (not recommanded), you can only use Struts, so Struts is surely a viable alternative. There is a discussion of Spring vs. Struts at Liferay forums (6/2009).

Resources

Posted in Portlets | 1 Comment »