AOP로 메서드 실행 시간을 측정하고 해석하기
성능을 개선하려면 먼저 어디에서 시간이 쓰이는지 측정해야 한다. 서비스 메서드마다 시작 시각과 종료 시각을 직접 기록하면 코드가 반복되고 예외가 발생했을 때 종료 로그가 빠질 수 있다. AOP의 Around 조언은 공통 측정 로직을 대상 메서드 바깥에 분리하는 데 적합하다.
실행 전후를 감싸는 Aspect
@Aspect
@Component
@Slf4j
public class ExecutionTimeAspect {
@Around("execution(* com.wooseok.blog..service..*(..))")
public Object measure(ProceedingJoinPoint joinPoint) throws Throwable {
long started = System.nanoTime();
try {
return joinPoint.proceed();
} finally {
long elapsedNanos = System.nanoTime() - started;
log.info("method={} elapsedMs={}",
joinPoint.getSignature().toShortString(),
elapsedNanos / 1_000_000.0);
}
}
}
실행 시간 측정에는 경과 시간 측정에 적합한 System.nanoTime()을 사용한다. currentTimeMillis()는 시스템 시간이 조정될 수 있어 짧은 구간 측정에는 덜 적합하다. finally에서 로그를 남기면 대상 메서드가 예외를 던져도 측정값이 기록된다.
포인트컷 범위를 좁히기
애플리케이션의 모든 메서드를 감싸면 로그 양과 프록시 비용이 빠르게 커진다. 처음에는 외부 요청이 들어오는 컨트롤러나 서비스의 핵심 메서드처럼 범위를 좁힌다. 패키지 표현식이 실제 패키지 구조와 맞는지 테스트로 확인하고, 헬퍼 메서드까지 모두 측정할 필요가 있는지 판단한다.
특정 메서드에만 측정이 필요하면 애너테이션 포인트컷을 사용할 수 있다. Spring AOP는 프록시 기반이므로 같은 객체 안에서 this.someMethod()로 호출한 내부 메서드는 프록시를 통과하지 않을 수 있다. 측정값이 빠진다면 호출 구조를 별도 빈으로 분리하거나, 애너테이션이 붙은 메서드를 외부 빈에서 호출하는지 확인한다.
로그 한 줄을 지표로 만들기
실행 시간 로그를 남기는 것만으로는 병목이 해결되지 않는다. 메서드명, HTTP 경로, 상태 코드, trace ID, 결과 크기 같은 차원을 함께 기록하고 로그 수집 시스템에서 p50·p95·p99를 계산해야 한다. 평균값만 보면 일부 요청의 긴 지연을 놓친다.
민감한 파라미터와 응답 본문은 로그에 넣지 않는다. 호출 횟수가 많은 메서드는 모든 요청을 로그로 남기지 않고 샘플링하거나 Micrometer Timer로 집계하는 편이 비용이 낮다. 로그 레벨도 운영 환경에서는 INFO와 DEBUG를 구분한다.
측정값을 비교할 때의 조건
변경 전후의 수치를 비교하려면 같은 데이터, 캐시 상태, 동시 요청 수, JVM 워밍업 조건을 맞춰야 한다. 첫 요청의 클래스 로딩 시간과 반복 요청의 처리 시간을 한 표에 섞으면 잘못된 결론을 낼 수 있다. 실행 시간은 DB와 외부 API 대기 시간을 포함하므로 메서드 안쪽의 SQL 시간도 별도로 확인한다.
AOP 측정은 성능을 자동으로 개선하는 기능이 아니다. 어디에서 시간이 지연되는지 일관된 방식으로 기록해 다음 실험의 기준을 만드는 도구다. 측정 범위를 제한하고, 통계와 요청 맥락을 함께 남기면 로그가 단순한 숫자가 아니라 개선 의사결정 자료가 된다.
함께 읽기: