AOP를 활용해서 메서드 실행시간 측정하기

개발을 하다보면, 간단하게 메서드의 실행시간을 측정해보고자 할 일 이 많습니다.

그동안 저는 이럴 때 보통 아래처럼 System.currentMillis()를 측정하고자 하는 메서드의 위아래로 찍어 시간을 측정했습니다.

public class MyClass {
    public void MyMethod() {
        long startTime = System.currentMillis();

        // .. 로직

        long endTime = System.currentMillis();
        long resultTime = endTime - startTime;
        System.out.println("resultTime = " + resultTime + "ms");
    }
}

 

근데 매번 이런식으로 시간을 측정해보는 일은 굉장히 귀찮습니다. 특히 API의 병목구간이 어딘지 알아보기 위하여 Controller, Service, Repository, 또 그 안의 협력 객체들의 메서드까지 전부 시간측정을 해야한다고 했을 때 모든 메서드의 위아래로 측정 로직을 추가해야합니다.

 

파이팅있게 전부 프린트를 찍어놓고 측정까지 완료했다고 하더라도, 저 로직들은 프로덕션 코드에 올라가면 안되기에 한번 더 파이팅있게 곳곳에 흔적들을 지워주어야 합니다..

아무래도 이런 작업은 수동으로 하는 것이다보니 가끔씩 프로덕션 코드에 미처 지워지지 못하고 올라간 것을 몇번 봐서 뒤늦게 지운 경험이 있습니다.(ㅠㅠ)

 

마이크로미터의 @Timed를 통해 메서드의 시간측정을 하고, 그라파나를 통하여 시각화를 하여 보는 방법도 있겠지만 스타트업 대부분 이런 모니터링 시스템이 구축이 되어 있지 않은 경우가 많고, 간단하게 로컬에서만 시간 측정을 해보고 싶은 니즈가 더 많을 것이기에 오늘은 이런 상황에 알맞은 시간측정 어노테이션을 직접 AOP를 통하여 개발해보겠습니다.

 

예제에 사용된 코드는 https://github.com/DevCHW/example-code/tree/main/aop-timetrace/timetrace 에서 확인하실 수 있습니다.

※ 개발에 사용된 프로젝트 버전입니다.

Spring Boot 3.x

Java 17

 

시간측정 어노테이션 개발

먼저 AOP를 사용하기 위하여 build.gradle에 AOP 의존성을 추가해줍니다.

implementation "org.springframework.boot:spring-boot-starter-aop"

 

 

그리고 아래의 어노테이션을 추가해줍니다.

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

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

}

 

타겟은 메소드, 어노테이션 정책은 런타임까지 유지될 수 있도록 해주었습니다.

 

 

 

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.context.annotation.Profile;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;

@Component
@Aspect
@Slf4j
@Profile({"local", "local-dev"})
public class TimeTraceAspect {

    @Pointcut("@annotation(com.devchw.timetrace.TimeTrace)")
    private void timeTracePointcut() {

    }

    @Around("timeTracePointcut()")
    public Object traceTime(ProceedingJoinPoint joinPoint) throws Throwable {
        StopWatch stopWatch = new StopWatch();
        try {
            stopWatch.start();
            return joinPoint.proceed(); // 타겟 호출
        } finally {
            stopWatch.stop();
            log.info("{} - Total time = {}s",
                    joinPoint.getSignature().toShortString(),
                    stopWatch.getTotalTimeSeconds());
        }
    }

}

 

AOP에 대한 개념을 잘 모르시는 분들은 먼저 인프런의 CTO를 하고 계신 이동욱님의 AOP정리 를 읽어보고 오시는 것을 추천드립니다.

 

위의 시간측정은 로컬에서 확인용이니, 로컬 환경에서만 동작을 해야겠죠?

저의 경우 환경이 외부 의존 없이 개발을 할 수 있는 local, 개발 환경에 직접 붙어볼 수 있는 local-dev 환경이 있습니다.

그래서 `@Profile`을 통해 local, local-dev에서만 해당 AOP가 동작하도록 해주었습니다.

 

Pointcut은 만들어둔 TimeTrace 어노테이션의 경로를 지정해주어 TimeTrace 어노테이션이 달려있는 메소드에서 동작하도록 해주었습니다.

 

다음 `@Around`를 통해 시간이 측정될 메서드의 위아래로 동작할 로직을 추가해줍니다.

원래는 간단하게 직접 측정할 땐 System.currentMillis()를 사용했지만 시간측정에 좀 더 특화되어있는 해당 로직에서는 StopWatch를 이용해 측정하도록 하였습니다. StopWatch에 대한 자세한 내용은 Java StopWatch 실행 시간 측정방법 3가지 글을 참고하시면 좋습니다.

 

@TimeTrace 동작 테스트

잘 동작하는지 테스트를 해보기 위하여 시간이 1초정도 소요되는 임의의 헬로 API (테스트할 때 국룰)을 만들어주었습니다.

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class HelloController {

    @TimeTrace
    @GetMapping("/hello")
    public String hello() throws InterruptedException {
        Thread.sleep(1000);
        return "hello";
    }
}

 

스프링 컨테이너를 띄우고 브라우저에서 해당 API 로 요청을 보내본다면?

 

위 처럼 의도한대로 측정 시간이 로그로 잘 찍히는 것을 확인할 수 있습니다.

 

 

 주의사항

AOP의 동작원리를 알고 계신 분은 아시겠지만, 해당 어노테이션은 Inner 메소드에서는 동작하지 않습니다.

이게 무슨소리인가.. 위 예제에 기반하여 동작하지 않는 코드를 먼저 작성해보겠습니다.

package com.devchw.timetrace;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class HelloController {

    @GetMapping("/hello")
    public String hello() throws InterruptedException {
        Thread.sleep(1000);
        innerMethod();
        return "hello";
    }

    @TimeTrace
    public void innerMethod() {
        System.out.println("innerMethod 호출입니다요");
    }
}

 

헬로 API를 호출하면 아래의 innerMethod()를 호출하도록 했고, innerMethod 위에 `@TimeTrace` 어노테이션을 붙여 시간이 측정되도록 했습니다.

과연 이 내부 호출 메서드의 시간이 측정될까요? 다시 한번 API를 호출해보겠습니다.

 

분명 메서드는 호출이 되었는데, 무슨 일인지 AOP가 동작하지 않았습니다.

이러한 문제의 원인은 AOP의 동작 원리를 알면 쉽게 알 수 있는데요, 

AOP가 적용된 클래스는 해당 메소드가 호출될 때 실제 객체가 호출되는것이 아닌 Proxy가 먼저 호출되어 AOP가 수행될 수 있도록 합니다.

그런데 innerMethod가 호출될 때는 프록시가 아닌 실제 객체의 메소드가 호출되는 것이기에, AOP가 동작할 수 없습니다.

이러한 문제도 자기 자신을 주입받아 내부 메소드를 호출하는 등, 방법은 있지만 단순히 로컬에서 시간 측정을 위해 이렇게 로직을 변경하는 것은 오버엔지니어링 이라고 생각하기에, 이러한 한계점에 대하여 잘 인지하며 사용해야 합니다.

 

 

참고 레퍼런스

https://velog.io/@dhk22/Spring-Spring-AOP-%EB%82%B4%EB%B6%80-%EB%A9%94%EC%84%9C%EB%93%9C-%ED%98%B8%EC%B6%9C%EC%8B%9C-%EB%AC%B8%EC%A0%9C%ED%95%B4%EA%B2%B0