Spring에서 실행 시간 측정하기

이번 글에서는 Spring 프로젝트에서 실행 시간을 측정하는 두 가지 방법과 경험을 공유한다.

---

두 가지 측정 방식

1. AOP 기반 자동 측정: @MeasureExecutionTime 어노테이션만 붙이면 자동으로 측정된다
2. 유틸리티 기반 수동 측정: ExecutionTimeLogger 클래스로 원하는 코드 블록만 측정한다

두 방식 모두 장단점이 있었고, 상황에 따라 적절히 선택해서 사용하면 된다.

필요한 의존성

먼저 Spring AOP 의존성이 필요하다. Spring Boot 프로젝트라면 다음과 같이 추가한다.

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

---

AOP 기반 자동 측정

기본 사용법

가장 간단한 방법은 메서드에 어노테이션을 붙이는 것이다.

package com.cytur.cloud.iti.service;

import com.cytur.cloud.iti.aop.MeasureExecutionTime;
import org.springframework.stereotype.Service;

@Service
public class ReportService {

    @MeasureExecutionTime
    public Report generateReport(Long reportId) {
        // 비즈니스 로직
        Report report = createReport(reportId);
        return report;
    }
}

 

이렇게만 해두면 메서드가 실행될 때마다 자동으로 로그가 찍힌다.

[실행 시간 측정] ReportService.generateReport 실행 시간: 1234ms

전체 레이어 자동 측정

특정 레이어의 모든 메서드를 한 번에 측정하고 싶을 때가 있다.
이럴 때는 ExecutionTimeAspect 클래스에서 Pointcut을 설정하면 된다.

Controller 레이어 전체 측정

@Around("execution(* com.cytur.cloud.iti.controller..*(..))")
public Object measureControllerExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
    return measureExecutionTimeInternal(joinPoint, "Controller");
}

Service 레이어 전체 측정

@Around("execution(* com.cytur.cloud.iti.service..*(..))")
public Object measureServiceExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
    return measureExecutionTimeInternal(joinPoint, "Service");
}

이렇게 설정하면 해당 패키지의 모든 메서드 실행 시간이 자동으로 측정된다.

[Controller] ReportController.getReport 실행 시간: 234ms
[Service] ReportService.generateReport 실행 시간: 1234ms

AOP 방식의 장점

• 비즈니스 코드와 측정 코드의 분리: Service 코드가 측정 로직으로 오염되지 않는다
• 간편한 적용: 어노테이션만 추가하면 되니 코드 변경이 최소화된다
• 일관성: 여러 메서드에 동일한 방식으로 적용할 수 있다

주의할 점

• 운영 환경에서는 선별적으로 적용: 모든 메서드에 적용하면 로그가 폭증한다
• 성능 영향 고려: 전체 레이어 측정은 개발 환경에서만 활성화하는 것을 권장한다

 

 

 

---

유틸리티 클래스를 통한 수동 측정

AOP가 편리하긴 하지만, 가끔은 특정 코드 블록만 빠르게 측정하고 싶을 때가 있다.
이럴 때는 유틸리티 클래스를 사용한다.

기본 사용 예시

반환값이 없는 경우

import com.cytur.cloud.iti.util.ExecutionTimeLogger;

@Service
public class ReportService {

    public void saveReport(Report report) {
        ExecutionTimeLogger.logExecutionTime("리포트 저장", () -> {
            reportRepository.save(report);
            sendNotification(report);
        });
    }
}

[실행 시간] 리포트 저장 완료: 156ms

반환값이 있는 경우

@Service
public class ReportService {

    public List<Report> getReports(Long userId) {
        return ExecutionTimeLogger.logExecutionTime(
            "사용자 리포트 조회",
            () -> reportRepository.findByUserId(userId)
        );
    }
}

[실행 시간] 사용자 리포트 조회 완료: 89ms

상세 정보와 함께 측정

디버깅할 때는 파라미터 정보도 함께 보고 싶을 때가 많다.

@Service
public class ReportService {

    public Report generateReport(Long reportId) {
        return ExecutionTimeLogger.logExecutionTimeWithDetails(
            "리포트 생성",
            "reportId: " + reportId,
            () -> {
                Report report = createReport(reportId);
                processReport(report);
                return report;
            }
        );
    }
}

[실행 시간] 리포트 생성 시작 - reportId: 12345
[실행 시간] 리포트 생성 완료: 1234ms - reportId: 12345

다단계 프로세스 측정

복잡한 비즈니스 로직의 병목 지점을 찾을 때 유용한 방법이다.

import org.springframework.util.StopWatch;
import com.cytur.cloud.iti.util.ExecutionTimeLogger;

@Service
public class ReportService {

    public Report generateComplexReport(Long reportId) {
        StopWatch stopWatch = ExecutionTimeLogger.createStopWatch("복합 리포트 생성");

        stopWatch.start("데이터 조회");
        List<Data> rawData = fetchRawData(reportId);
        stopWatch.stop();

        stopWatch.start("데이터 가공");
        ProcessedData processedData = processData(rawData);
        stopWatch.stop();

        stopWatch.start("차트 생성");
        Chart chart = generateChart(processedData);
        stopWatch.stop();

        stopWatch.start("리포트 저장");
        Report report = saveReport(processedData, chart);
        stopWatch.stop();

        ExecutionTimeLogger.logStopWatch(stopWatch);
        return report;
    }
}

 

이렇게 하면 각 단계별로 얼마나 시간이 걸리는지 한눈에 볼 수 있다.

[실행 시간] 복합 리포트 생성 전체 소요 시간: 2500ms
[실행 시간] 복합 리포트 생성 상세:
-----------------------------------------
ms     %     Task name
-----------------------------------------
00500  020%  데이터 조회
01200  048%  데이터 가공
00600  024%  차트 생성
00200  008%  리포트 저장

이 로그를 보면 “데이터 가공” 단계가 전체 시간의 절반 가까이 차지한다는 것을 바로 알 수 있다. 최적화가 필요한 지점이 명확해진다.

느린 실행 감지

외부 API를 호출하거나 DB 쿼리를 실행할 때, 특정 임계값을 넘는 경우만 로그로 남기고 싶을 때가 있다.

@Service
public class ReportService {

    public Report generateReport(Long reportId) {
        // 1000ms(1초)를 초과하면 WARN 레벨로 로깅
        return ExecutionTimeLogger.logSlowExecution(
            "리포트 생성",
            1000,
            () -> createReport(reportId)
        );
    }
}

임계값을 초과했을 때:

[느린 실행 감지] 리포트 생성 실행 시간: 1456ms (임계값: 1000ms)

정상적인 경우:

[실행 시간] 리포트 생성 완료: 789ms

유틸리티 방식의 장점

직접 사용해보니 이런 장점들이 있었다.

• 세밀한 제어: 특정 코드 블록만 선택적으로 측정할 수 있다
• 빠른 적용: 어노테이션 없이 바로 사용 가능하다
• 단계별 분석: 복잡한 로직의 병목 지점을 쉽게 찾을 수 있다
• 임시 디버깅: 개발 중 빠르게 추가했다가 제거하기 편하다

---

언제 어떤 방식을 사용할까?

상황	추천 방법	이유
특정 서비스 메서드의 성능 모니터링	AOP (@MeasureExecutionTime)	비침투적이고 코드 변경 최소화
임시 성능 디버깅	유틸리티 (ExecutionTimeLogger)	빠르게 추가/제거 가능
다단계 프로세스의 병목 지점 분석	유틸리티 (StopWatch)	각 단계별 시간 상세 측정 가능
전체 Controller/Service 레이어 모니터링	AOP (전역 설정)	일관된 측정 방식
특정 임계값 초과 시만 알림	유틸리티 (logSlowExecution)	조건부 로깅 가능

개발 환경과 운영 환경 분리

로그 레벨을 환경별로 다르게 설정하는 것이 중요하다.

application-local.yml (개발 환경)

logging:
  level:
    com.cytur.cloud.iti.aop: DEBUG
    com.cytur.cloud.iti.util: DEBUG

application-product.yml (운영 환경)

logging:
  level:
    com.cytur.cloud.iti.aop: INFO
    com.cytur.cloud.iti.util: WARN

 

운영 환경에서는 INFO나 WARN 레벨로 설정해서 필요한 로그만 남기도록 했다. 로그가 너무 많으면 정작 중요한 정보를 놓치기 쉽다.

 

 

 

---

정리

• AOP 방식은 지속적인 모니터링이 필요한 핵심 비즈니스 로직에 적합하다
• 유틸리티 방식은 임시 디버깅이나 세밀한 분석이 필요할 때 유용하다
• 두 방식을 상황에 맞게 조합해서 사용하면 효과적이다
• 운영 환경에서는 로그 레벨을 적절히 관리하는 것이 중요하다

 

 

 

---

참고 자료

• Spring AOP 공식 문서