Logging and Timing Aspect

@Aspect
@Component
@Slf4j
public class PerformanceAspect {

    @Around("execution(* com.shopease.service..*(..))")
    public Object time(ProceedingJoinPoint pjp) throws Throwable {
        long start = System.nanoTime();
        String method = pjp.getSignature().toShortString();
        try {
            return pjp.proceed();                       // call the real method
        } finally {
            long ms = (System.nanoTime() - start) / 1_000_000;
            if (ms > 500) log.warn("SLOW {} took {} ms", method, ms);
            else log.info("{} took {} ms", method, ms);
        }
    }
}

Example

Calling the API now produces timing logs without touching the services:

curl -s "localhost:8080/api/products?category=mobiles"

Example output

INFO  c.s.aop.PerformanceAspect : ProductService.findByCategory(..) took 18 ms
INFO  c.s.aop.PerformanceAspect : PricingService.applyOffers(..) took 3 ms

Example

Spring creates a proxy that wraps your bean. java.lang.reflect.Proxy does the same for interfaces, so we can build a working "around advice" ourselves:

import java.lang.reflect.*;
import java.util.*;

public class Main {
    public static void main(String[] args) throws Throwable {
        OrderService real = new OrderServiceImpl();
        OrderService proxy = (OrderService) Proxy.newProxyInstance(
            OrderService.class.getClassLoader(),
            new Class<?>[] { OrderService.class },
            new LoggingAdvice(real));

        System.out.println("Result: " + proxy.placeOrder("asha", 2499.0));
        try {
            proxy.cancel(-1);
        } catch (IllegalArgumentException e) {
            System.out.println("Caller saw: " + e.getMessage());
        }
    }
}

interface OrderService {
    String placeOrder(String user, double amount);
    void cancel(long orderId);
}

class OrderServiceImpl implements OrderService {
    public String placeOrder(String user, double amount) { return "ORD-1001 for " + user; }
    public void cancel(long orderId) {
        if (orderId < 0) throw new IllegalArgumentException("invalid order id");
    }
}

class LoggingAdvice implements InvocationHandler {
    private final Object target;
    LoggingAdvice(Object target) { this.target = target; }

    public Object invoke(Object proxy, Method m, Object[] args) throws Throwable {
        System.out.println("@Before  " + m.getName() + Arrays.toString(args));
        try {
            Object result = m.invoke(target, args);
            System.out.println("@AfterReturning " + m.getName() + " -> " + result);
            return result;
        } catch (InvocationTargetException e) {
            System.out.println("@AfterThrowing " + m.getName() + " -> " + e.getCause().getMessage());
            throw e.getCause();
        } finally {
            System.out.println("@After   " + m.getName());
        }
    }
}

Output

@Before  placeOrder[asha, 2499.0]
@AfterReturning placeOrder -> ORD-1001 for asha
@After   placeOrder
Result: ORD-1001 for asha
@Before  cancel[-1]
@AfterThrowing cancel -> invalid order id
@After   cancel
Caller saw: invalid order id

The Aspect

Example

The Same Idea in Plain Java

Example