Custom Annotation to calculate execution time

Published On: 29 June 2022.By vishal bothra.

General

Custom Annotation to calculate execution time

Introduction

Annotations are Java types that are preceded by an “@” symbol.

Java has had annotations ever since the 1.5 release. Since then, they’ve shaped the way we’ve designed our applications. Spring and Hibernate are great examples of frameworks that rely heavily on annotations to enable various design techniques.

Basically, an annotation assigns extra metadata to the source code it’s bound to.

Java Annotation is a tag that represents the metadata i.e. attached with class, interface, methods or fields to indicate some additional information which can be used by java compiler and JVM.

There are several built-in annotations in Java. Some annotations are applied to Java code and some to other annotations.

Built-In Java Annotations used in Java code

@Override
@SuppressWarnings

Built-In Java Annotations used in other annotations

@Target
@Retention

and many other annotations.

We can also create custom annotations as per our requirement.

In this blog, I would like to document the steps followed to solve the Concern surrounding logging execution time in a Spring Boot Application.

First let’s look at the traditional method that comes in everyone’s mind:

Controller:

@Slf4j
@Controller
@RequestMapping("/org")
public class OrgController extends _BaseController {

    @Autowired
    private OrganizationService organizationService;

    @GetMapping(value = "/get/org/name/{id}")
    public String getOrganizationName(@PathVariable String id){
        if (StringUtils.isBlank(id)){
            return null;
        }
        return organizationService.getOrganizationNameFromId(id);
    }
}

@Slf4j

@Controller

@RequestMapping("/org")

public class OrgController extends _BaseController {

@Autowired

private OrganizationService organizationService;

@GetMapping(value = "/get/org/name/{id}")

public String getOrganizationName(@PathVariable String id){

if (StringUtils.isBlank(id)){

return null;

}

return organizationService.getOrganizationNameFromId(id);

}

Service:

@Service
@Slf4j
public class organizationService {

    public String getOrganizationNameFromId(String id){
        return "Test Name From Service";
    }
}

@Service

@Slf4j

public class organizationService {

public String getOrganizationNameFromId(String id){

return "Test Name From Service";

}

Now, we would think to find current time in milliseconds prior to method start, and subtract with current time post method execution. May be create a Util, and still we will end up with several boilerplate code within our class/methods.

To simplify this task we can create our own custom annotation. We just have to write code for a class and an interface.

ExecutionTimeAdvice.java:

@Aspect
@Component
@Slf4j
@ConditionalOnExpression("${aspect.enabled:true}")
public class ExecutionTimeAdvice {

    @Around("@annotation(com.clear360.executionTimeTester.TrackExecutionTime)")
    public Object executionTime(ProceedingJoinPoint point) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object object = point.proceed();
        long endtime = System.currentTimeMillis();
        log.info("Class Name: "+ point.getSignature().getDeclaringTypeName() +". Method Name: "+ point.getSignature().getName() + ". Time taken for Execution is : " + (endtime-startTime) +"ms");
        return object;
    }
}

@Aspect

@Component

@Slf4j

@ConditionalOnExpression("${aspect.enabled:true}")

public class ExecutionTimeAdvice {

@Around("@annotation(com.clear360.executionTimeTester.TrackExecutionTime)")

public Object executionTime(ProceedingJoinPoint point) throws Throwable {

long startTime = System.currentTimeMillis();

Object object = point.proceed();

long endtime = System.currentTimeMillis();

log.info("Class Name: "+ point.getSignature().getDeclaringTypeName() +". Method Name: "+ point.getSignature().getName() + ". Time taken for Execution is : " + (endtime-startTime) +"ms");

return object;

}

TrackExecutionTime.java:

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

@Target(ElementType.METHOD)

@Retention(RetentionPolicy.RUNTIME)

public @interface TrackExecutionTime {

}

Now we only need to add “@TrackExecutionTime” annotation to your desired Methods in any of your class.

Adding to our Controller & Service:

Controller:

@Slf4j
@Controller
@RequestMapping("/org")
public class OrgController {

    @Autowired
    private OrganizationService organizationService;

    @GetMapping(value = "/get/org/name/{id}")
    @TrackExecutionTime
    public String getOrganizationName(@PathVariable String id){
        if (StringUtils.isBlank(id)){
            return null;
        }
        return organizationService.getOrganizationNameFromId(id);
    }
}

@Slf4j

@Controller

@RequestMapping("/org")

public class OrgController {

@Autowired

private OrganizationService organizationService;

@GetMapping(value = "/get/org/name/{id}")

@TrackExecutionTime

public String getOrganizationName(@PathVariable String id){

if (StringUtils.isBlank(id)){

return null;

}

return organizationService.getOrganizationNameFromId(id);

}

Service:

@Service
@Slf4j
public class OrganizationService {

    @TrackExecutionTime
    public String getOrganizationNameFromId(String id){
        return "Test Name From Service";
    }
}

@Service

@Slf4j

public class OrganizationService {

@TrackExecutionTime

public String getOrganizationNameFromId(String id){

return "Test Name From Service";

}

Logs:

INFO com.clear360.executionTimeTester.ExecutionTimeAdvice.executionTime – Class Name: com.exmaple.service.OrganizationService. Method Name: getOrganizationNameFromId. Time taken for Execution is : 645ms

INFO com.clear360.executionTimeTester.ExecutionTimeAdvice.executionTime – Class Name: com.example.controller.OrgController. Method Name: getOrganizationName. Time taken for Execution is : 803ms