[FIXED] Spring AOP/AspectJ logging the execution time of a method but how to pass arguments to it? (Spring boot API)

Issue

I am using Spring AOP/AspectJ in my Spring Boot API to make an annotation in Java like @TrackExecutionTime, that I can slap on any method and it logs the total time it took the method to run. This is working currently in my Spring boot up. My issue is, my API is getting hit thousands of times a day, and I want log some other unique info with this execution time, so I can track/trace each request through my logs. Some of the data that I can use is sent with the POST request body from the JSON, but I can't see how to pass these arguments into the definition of this annotation - can anyone help?

I want to pass some arguments (customer firstname, lastname, etc..) from this Customer object that is the requestBody the client will POST as JSON to my API to my annotation logger:

@RestController
public class CustomersController implements CustomersApi {

    @Autowired
    private CustomerService customerService;

      return ResponseEntity.ok(offersService.fetchCustomer(Customer, clientId));
    }

I defined the concrete class and the interface for annotation like this. This is where I want to pass the Customer object so I can log the firstname or lastname:

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

    @Around("@annotation(com.mailshine.springboot.aop.aspectj.advise.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;
    }
}

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

Solution

This is very easy to do; I was a dum-dum when I originally posted this, but here's the answer for anyone looking to do the same:

When you create your interface that defines you annotation using Spring AOP/AspectJ, in your concrete class like I listed above, it has access to all the arguments passed to your method from the ProceedingJoinPoint object. So you can call getArgs() on this object to get all the arguments passed to the method in-question when its runs. It will return an Object[] so you will just need to have some conditional checks to cast it down to the type of your choice and make sure its not empty, so you don't get any exceptions at runtime. This is helpful if clients are POSTing to your API and you want to track the execution time of methods, but maybe you have hundreds/thousands of requests and need to specifically trace down exactly which calls follow which paths and what may be slowing your API down... so posting additional data from the requestBody maybe helpful in your logs...

e.g. I'll pretend I am tracking some method, that takes in a "Student" data type, which holds a bunch of data on a student (name, dob, gpa, etc...). This way, if I have different methods that query the Database with different SQL queries based on the requestBody the client POST to the API with, I can log this, to track down exactly which requests are slowing my API down and their flow within my codebase and which SQL queries they are calling. i.e.

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

    @Around("@annotation(com.mailshine.springboot.aop.aspectj.advise.TrackExecutionTime)")
    public Object executionTime(ProceedingJoinPoint point) throws Throwable {
        MyCustomStudentType student; // Class to hold Student data
        String studentName = "";
        Object[] argsArray = point.getArgs();
        
        if (argsArray.length > 0 && argsArray[0] instanceof MyCustomStudentType) {
             student = (MyCustomStudentType) argsArray[0];
             studentName = student.getName();
        }

        long startTime = System.currentTimeMillis();
        Object object = point.proceed();
        long endtime = System.currentTimeMillis();

        // add the student name to your logs or any info you want to add with your
        // execution time of your method, to make tracking your logs easier
        log.info("Class Name: "+ point.getSignature().getDeclaringTypeName() +". Method Name: "+ point.getSignature().getName() + ". Time taken for Execution is : " + (endtime-startTime) +"ms" + ", for student name: " + studentName);

        return object;
    }
}

Answered By - ennth
Answer Checked By - Marie Seifert (JavaFixing Admin)