Spring AOP timing aspect

At some point or another everyone writes a timing aspect. It’s simple yet fun. Here’s mine. This is a timing aspect with a small difference. There exists an annotation called @Timed and you can apply that annotation at a class level or method level and accordingly the invocations shall be timed and the output printed to stdout. Although it is intended to be illustrative to a degree it hopefully offers some utility value also.

Summary

The following aspect acts on annotated classes and methods and times invocations producing output to stdout (which can be changed easily to a logger). In the background it uses Spring AOP driven by jdk proxies or cglib proxies depending on what the attribute proxy-target-class is set to in the spring xml.

The @Timed annotation

package a;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Inherited;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Inherited
@Documented
@Target( { ElementType.TYPE, ElementType.METHOD })
@Retention(RetentionPolicy.RUNTIME)
public @interface Timed {
}

The timing aspect

The @Around advice makes use of combined pointcut expressions. A crucial feature of this aspect is that it captures the annotation instance itself and provides it to the advice method which means that you are able to pass back metadata from the annotated element to the advice. Although the ‘timed’ variable is not actually being used it can be used should you want to.

package a;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.util.Assert;

@Aspect
public class TimingAspect {

    @Around(value = "@annotation(a.Timed) && @annotation(timed)", argNames = "timed")
    static Object timeMethod(final ProceedingJoinPoint pjp, final Timed timed) throws Throwable {
        return time(pjp, timed);
    }

    @Around("within(@a.Timed *) && @target(timed)")
    static Object timeClass(final ProceedingJoinPoint pjp, final Timed timed) throws Throwable {
        return time(pjp, timed);
    }

    private static Object time(final ProceedingJoinPoint pjp, final Timed timed) throws Throwable {

        Assert.notNull(pjp);
        Assert.notNull(timed);

        final Signature signature = pjp.getSignature();
        final String longString = "[" + signature.toLongString() + "]";

        System.out.println();
        System.out.println(">>>> started " + longString);

        final long startTimeMs = System.currentTimeMillis();

        try {
            return pjp.proceed();
        } finally {

            final long timeTakenMs = System.currentTimeMillis() - startTimeMs;
            System.out.println("<<<< completed " + longString + " (took " + timeTakenMs + "ms)");
            System.out.println();

        }
    }

}

Sample service class

Note here that the annotation can be applied at class level (as below) or at method level but do not apply to both.

package a;

@Timed
public class SampleService {

    public void sampleServiceMethod1() {
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    public void sampleServiceMethod2() {
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

}

Test for sample service class

package a;

import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(locations = { "classpath:spring-aop.xml" })
public class TestSampleService {

    @Autowired
    private SampleService sampleService;

    @Test
    public final void testSampleServiceMethod1() {
        sampleService.sampleServiceMethod1();
    }

    @Test
    public final void testSampleServiceMethod2() {
        sampleService.sampleServiceMethod2();
    }

}

Spring beans

<beans xmlns="http://www.springframework.org/schema/beans" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xmlns:aop="http://www.springframework.org/schema/aop"
    xsi:schemaLocation="
http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.5.xsd">

    <aop:aspectj-autoproxy proxy-target-class="false" />

    <bean class="a.TimingAspect" />

    <bean class="a.SampleService" />

</beans>

Maven dependencies

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>a</groupId>
    <artifactId>a</artifactId>
    <name>a</name>
    <version>1.0</version>
    <description>a</description>

    <dependencies>

        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring</artifactId>
            <version>2.5.6</version>
        </dependency>

        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-test</artifactId>
            <version>2.5.6</version>
            <scope>test</scope>
        </dependency>

        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-context</artifactId>
            <version>2.5.6</version>
        </dependency>

        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjrt</artifactId>
            <version>1.5.4</version>
        </dependency>

        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjweaver</artifactId>
            <version>1.6.2</version>
        </dependency>

        <dependency>
            <groupId>cglib</groupId>
            <artifactId>cglib-nodep</artifactId>
            <version>2.2</version>
        </dependency>

        <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>4.5</version>
            <scope>test</scope>
        </dependency>

    </dependencies>

</project>

Example output

>>>> started [public void a.SampleService.sampleServiceMethod1()]
<<<>>> started [public void a.SampleService.sampleServiceMethod1()]
<<<< completed [public void a.SampleService.sampleServiceMethod1()] (took 500ms)

Discussion

An esteemed colleague of mine having seen such an idea from myself asked “What’s wrong with System.currentTimeMillis?” and essentially conveyed that writing such an aspect was needless when classes like StopWatch or System.currentTimeMillis() exist especially given that proxies are hard to debug. I respond to that by providing the following benefits of having and using such an aspect.

  1. It is non-intrusive. Since it is applied externally it stays out of real code.
  2. It does not go into production like timing code within methods themselves. The aspect needs two snippets of xml in order to be enabled. One is the aspectj auto proxying tag and the other is that the aspect itself must be declared as a spring bean. If you do not wish for it to go into production simply enable these two things for tests only and not for deployed mode.
  3. It is quick to apply and quick to remove. What if you had a class with 35 public methods that you want to time? Will you add timing code to all of them individually? Will you abstract the timing code into one method and add manual hooks into all of them? Isn’t that essentially a cross-cut and aren’t cross-cuts a classic case for AOP? Once you’ve finished timing won’t you have to remove all that timing code before you go into production?
  4. It is far more readable, maintainable and neater than having timing code all over the place.
  5. If doing timing code yourself how are you going to obtain reflection metadata such as method arguments to uniquely identify methods being timed and with what arguments (in case particular arguments are causing slowness)? Sysout the method name and arguments in string? No – it should be dynamic (pjp.getArgs()).
  6. It is cool. Nuff sed?

I hope that my argument for having such an aspect has been convincing although I fear not convincing enough for the old fashioned amongst us. Either way let me know if this helps and most of all enjoy.

Constraints

  • Cannot be applied on interface.
  • Cannot be applied on abstract class.
  • Cannot be applied on spring controller.

The annotation @Timed will not work on interfaces or abstract classes because it is not inherited and this is not supported by Spring AOP. Also it will not work on Spring controllers because controllers invocations are internal to the spring controller hierarchy and for proxies to take effect invocations must originate externally. See manual for more details.

Further work

It would be interesting to use one of many reflection libraries to do the same but for classes not using Spring. Also it would be quite cool to play around with aspectj to achieve the same effect but perhaps that should be with a different use case in mind.

What aspect or cross cut use-cases have you encountered in your work?

6 thoughts on “Spring AOP timing aspect

  1. George – I haven’t tried it but it is very likely that it does work with annotated controllers for the simple reason that with annotated controllers all calls are public so go through the proxy whereas with the form controller hierarchy some calls were internal. Try it and see!

  2. hi

    I found your blog and i really enjoy reading it.
    I played with your aspect and it seems it can rewritten in a shorter form:

    @Around(value = @annotation(timed))
    static Object timeMethod(final ProceedingJoinPoint pjp, final Timed timed) throws Throwable {
    return time(pjp, timed);
    }

    @Around(@target(timed))
    static Object timeClass(final ProceedingJoinPoint pjp, final Timed timed) throws Throwable {
    return time(pjp, timed);
    }
    The next thing:
    testSampleServiceMethod2 method tests sampleServiceMethod1 but i suspect your intention was to test sampleServiceMethod2 instead.

    I wish Spring had a way to define pointcuts that could match annotations on superclasses and interfaces, but since annotations themselves are not inheritable …

  3. From http://static.springframework.org/spring/docs/2.5.x/reference/aop.html

    6.3. Schema-based AOP support

    “Warning

    The style of configuration makes heavy use of Spring’s auto-proxying mechanism. This can cause issues (such as advice not being woven) if you are already using explicit auto-proxying via the use of BeanNameAutoProxyCreator or suchlike. The recommended usage pattern is to use either just the style, or just the AutoProxyCreator style.”

    So if you’re already using style, you’ll have to add this advice the same way:

  4. Just a note – since Java does not allow the @Inherited annotation, to actually meta data for methods, the aspect will not work on sub class beans. I dont know of a way to make that work (dont think its possible)

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s