Spring Boot – Native AspectJ demo – Log time taken for private and static method executions using annotations.

In this short tutorial we are going to see how to intercept private and static methods to log the time taken using AspectJ and annotations. Spring AOP is proxy based and will not intercept private or static methods. Hence we are using the very powerful AspectJ framework to intercept them.

Consider we have a Spring Boot rest api with Lombok to auto generate getters and setters of its model. We need to find out the execution time of some of its methods. Instead of writing the time measurement logic in all those methods we can use AspectJ to address that concern and separate that logic into an Aspect and an annotation to trigger that.

Code for the annotation is provided below.

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Timed {
}

Now create the aspect in a file with .aj extension. Note that the Type is “aspect”. It is not a class or interface. If you use .java extension for this aspect you get the error class, interface, enum, or record expected.

public aspect TimedAspect {
        pointcut timedAnnotation() : @annotation(com.example.demo.annotation.Timed) && execution(* *(..));

        Object around() : timedAnnotation() {
        long start = System.currentTimeMillis();
        Object ret = proceed();
        long end = System.currentTimeMillis();
        System.out.println("The method :" + thisJoinPointStaticPart.getSignature()
        + " took " + (end-start) + " ms");
        return ret;
        }
}

Then add aspectj-maven-plugin to compile the aspect and to weave the class files with the aspect. The dependency org.aspectj.aspectjrt should also be added.

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

aspectj-maven-plugin: To compile the aspect and to weave the class files with the aspect. We specify the weaveDirectories as class files mainly to avoid issues with unavailability of getters and setters as Lombok will generate them only during the compilation time.

<plugin>
   <groupId>org.codehaus.mojo</groupId>
   <artifactId>aspectj-maven-plugin</artifactId>
   <version>1.14.0</version>
   <configuration>
      <verbose>true</verbose>
      <showWeaveInfo>true</showWeaveInfo>
      <source>16.0</source>
      <target>16.0</target>
      <complianceLevel>16.0</complianceLevel>
      <Xlint>ignore</Xlint>
      <outxml>true</outxml>
      <forceAjcCompile>true</forceAjcCompile>
<!-- The below sources tag mentions the aspect file to be compiled -->
      <sources>
         <source>
            <basedir>src/main/java</basedir>
            <includes>
               <include>**/TimedAspect.aj</include>
            </includes>
         </source>
      </sources>
<!-- To weave the above aspect with the generated class files -->
      <weaveDirectories>
         <weaveDirectory>${project.build.directory}/classes</weaveDirectory>
      </weaveDirectories>
   </configuration>
   <executions>
      <execution>
         <phase>process-classes</phase>
         <goals>
            <goal>compile</goal> <!-- Weave after compilation --> 
         </goals>
      </execution>
   </executions>
</plugin>

Now adding the @Timed annotation to all methods that should be time measured. Just to prove AspectJ ability i have created some fictious private and private static methods and have added Timed annotations to it.

@Timed
public Message sayHello(){
    return Message.builder().messageBody("Message: Hello !! How are you ? ".concat(offerHelp())).build();
}

@Timed
private String offerHelp(){
    return "How can i help you ? " + HelloService.getCurrentTimeInMillis();
}

@Timed
private static long getCurrentTimeInMillis(){
    return System.currentTimeMillis();
}

Then do a mvn clean install. And start the application from the generated jar file: spring-boot-aspectj-demo-0.0.1-SNAPSHOT.jar. This is due to the fact that AJC (AspectJ compiler) will weave the generated class files and the updated classes will be available in the jar file.

java -jar spring-boot-aspectj-demo-0.0.1-SNAPSHOT.jar

Then when we invoke the rest endpoint with localhost:8080/hello we can see the time log for all the @Timed annotated methods irrespective of Public / private / protected / static methods. AspectJ is really powerful.

The method :long com.example.demo.service.HelloService.getCurrentTimeInMillis() took 0 ms
The method :String com.example.demo.service.HelloService.offerHelp() took 6 ms
The method :Message com.example.demo.service.HelloService.sayHello() took 9 ms
The method :String com.example.demo.controller.HelloController.sayHelloInController() took 9 ms

The full code of this tutorial is available in Github.