[Spring] AOP 기반 API 요청별 쿼리 횟수 / 실행 시간 측정 카운터 구현

구현 계기

이전에 진행한 "모두의 뉴스"라는 프로젝트에 페이지네이션 등 조회 API 구현을 담당한 적이 있습니다.

촉박한 일정 탓에 "일단 돌아가게 하자"라는 생각으로 효율적인 쿼리 설계는 깊게 고민하지 않고 구현했습니다.

그 후 리팩토링 작업에서 지나치게 복잡한 쿼리를 개선하고, N+1 문제를 해결하는 것에 집중했습니다.

 

 

당시 저는 N+1 문제를 해결하여 호출되는 쿼리 횟수를 줄인다면 'DB 부하가 줄어드니 당연히 성능 개선이 되겠지'라고 막연히 생각했습니다.

물론 틀린 말은 아닙니다만, "그래서 실제로 성능이 얼마나 개선됐는데?"라는 질문이 따라올 수 있습니다.

 

마침 코드 리뷰 과정에서 팀원분이 “실행 시간을 직접 측정해보면 개선 효과를 수치로 확인할 수 있을 것 같다”는 피드백을 주셨습니다.

 

그때까지 저는 ‘N+1 문제’라는 개념 자체에만 집중해서 실행 시간은 고려하지 않고, 단순히 쿼리 횟수만 세고 있던 상황이었습니다.

그것도 일일이... 로그에서 하나 하나 셌습니다..

spring:
  jpa:
    show-sql: false # SQL 로그 출력 설정 -> logging 레벨 설정 때문에 off
    properties:
      hibernate:
        format_sql: true # SQL 포맷팅
        dialect: org.hibernate.dialect.PostgreSQLDialect
        
logging:
  level:
    root: info
    org.hibernate.SQL: debug # SQL 쿼리 로그 표시
    org.hibernate.orm.jdbc.bind: trace # 바인딩값도 함께 표시

 

제가 맡은 페이지네이션 API가 한두 개가 아니라 로그를 보며 쿼리를 일일이 세는 건 매우 비효율적이었습니다.

 

그래서 간단하게 쿼리 횟수 셀 방법 없나 + 실행 시간도 측정할 방법 없나하는 생각이 들었습니다.

---

왜 AOP를 선택했는가?

쿼리 실행 수와 실행 시간을 자동으로 기록하려면,

API 요청이 들어올 때마다 쿼리 실행 정보를 수집하고, 요청이 끝나면 이를 로그로 남기는 구조가 필요합니다.

 

단순히 서비스 로직 안에

`요청 시작 시간 기록 → 비즈니스 로직 수행 → 종료 후 로그 출력` 코드를 추가하는 방식은

이런 문제가 있습니다.

• 모든 API 메서드에 중복적인 코드가 들어간다
• 성능 측정이라는 부가적인 목적의 코드가 비즈니스 로직 코드와 섞인다

이러한 생각에서 횡단 관심사 개념을 떠올리게 됐습니다.

쿼리 실행 횟수와 시간을 재는 것은 여러 메서드에 공통적으로 적용되지만 핵심 비즈니스 로직과 무관한 관심사이기 때문에

Spring에서는 이를 AOP(Aspect Oriented Programming)으로 분리해 처리할 수 있습니다.

 

즉,

• 비즈니스 로직을 수정하지 않아도 되고
• 여러 API에 일관되게 적용하기 위해

Spring AOP로 구현하기로 결정했습니다.

 

---

설계 과정

핵심 목표는 다음 세 가지입니다.

1. 비즈니스 로직을 수정하지 않고 자동 측정할 것
2. API 요청 단위마다 독립적으로 측정할 것
3. 하나의 API가 실행되는 동안 호출된 쿼리 횟수와 쿼리의 총 실행 시간을 구할 것 + 쉽게 구분하기 위해 API 경로도 함께 출력

📌 @RequestScope: API 요청 단위마다 독립적인 통계 객체 생성하기

API 요청 한 번이 들어올 때마다 그 요청 안에서 실행된 모든 쿼리들의 통계를 독립적으로 관리해야 합니다.

예를 들어 `/articles` API가 실행되면 해당 요청에서 발생한 쿼리만 추적하고,

다음 요청 `/users`가 들어오면 새로운 통계 객체로 측정을 시작해야 합니다.

 

이런 요구를 만족시키기 위해 `@RequestScope`를 사용하겠습니다. 

`@RequestScope`는 Spring이 각 HTTP 요청마다 새로운 빈(bean) 인스턴스를 생성해주는 방법입니다.

 

스코프(Scope)란 빈이 얼마나 오래, 어떤 범위에서 유지되는가를 말합니다.

Spring에서는 기본적으로 싱글톤 스코프라고 하여, 하나의 빈 정의 당 애플리케이션 전체에서 하나의 빈 인스턴스만 생성하고

IoC 컨테이너 내에서 이 하나의 빈 인스턴스가 공유되어 사용됩니다.

 

또한 웹 환경에서 사용할 수 있는 특별한 스코프를 추가로 제공하는데, 이를 웹 스코프라고 합니다.

이 중 리퀘스트 스코프는 빈의 생명주기가 HTTP 요청 1회 동안만으로 제한되어 요청이 들어올 때 생성되고, 응답 후에 소멸됩니다.

HTTP 요청 단위로 독립적인 객체를 관리하고 싶을 때 사용하는 스코프입니다.

 

`@ReauestScope` 어노테이션으로 리퀘스트 스코프 빈을 쉽게 선언할 수 있습니다.

HTTP 요청이 들어올 때마다 `QueryStatistics`라는 새로운 인스턴스를 생성하여 해당 요청에 대한 쿼리 실행 정보를 저장하겠습니다.

@Component
@RequestScope
public class QueryStatistics { ... }

 

+ 자료를 찾아보면서 `@RequestScope` 외에 ThreadLocal을 사용하는 방법도 봤습니다.

 

ThreadLocal은 현재 스레드 내부에서만 접근 가능한 데이터를 이용하는 방법으로,

일반적으로 하나의 요청은 하나의 스레드에서 처리되기 때문에 각 요청(=각 스레드) 단위로 쿼리 실행 횟수를 셀 수 있는 방법입니다.

 

하지만 만약 비동기 API가 있다면 요청 처리 중 다른 스레드로 넘어갈 수도 있고,

Spring이 알아서 객체 소멸과 메모리 정리를 해주는 `@RequestScope`와 달리 명시적으로 메모리 정리를 해줘야하는 불편함 때문에 저는 `@RequestScope`를 선택했습니다.

 

📌 쿼리 호출 가로채기

 

이 `QueryStatistics` 객체에 값을 채워넣기 위해서는 쿼리 실행 시점을 가로채야 합니다.

어떤 요청마다 DB 쿼리가 몇 번 실행되었고, 각각 얼마나 걸렸는가를 알아내기 위해

쿼리 실행 메서드가 호출될 때마다 이를 감지해야 하기 때문입니다.

 

Spring 애플리케이션이 DB와 통신하여 쿼리를 실행할 때 과정을

다음과 같이 요약할 수 있습니다.

1. `DataSource` 객체에서 `Connection` 객체를 가져온다
2. `Connection` 객체에서 `PreparedStatement` 객체를 생성한다
3. `PreparedStatement`에서 `executeQuery()` 등 쿼리 실행 메서드를 호출해 실제 쿼리를 DB에 보낸다

객체	역할
DataSource	DB 연결을 관리 `getConnection()` 메서드로 Connection 객체를 얻음 ex) DB URL, 비밀번호 등의 정보를 관리
Connection	실제 DB와의 연결 담당 Connection을 통해 SQL 쿼리 실행 준비 / 트랜잭션 관리
PreparedStatement	SQL 쿼리를 실제로 실행하는 객체

 

이 중 `PreparedStatement`에서 쿼리가 실행되므로 해당 시점을 가로채면 될 것 같습니다.

 

그러나 Spring AOP를 적용하기 위해서는 가로채려는 메서드가 정의된 클래스가 스프링 빈으로 등록되어 있어야 합니다.

하지만 `Connection`과 `PreparedStatement` 모두 스프링 빈으로 등록되어 있지 않고,

`DataSource` 인터페이스만 스프링 빈으로 등록되어 있습니다.

 

따라서 우리는 `DataSource`에서 `getConnection()` 메서드로 `Connection` 객체를 얻을 때 끼어들어 AOP를 적용하고

우리가 바꾼 `Connection`, `PreparedStatement` 프록시 객체를 사용하도록 합니다.

 

AOP로 `DataSource.getConnection()`을 가로챕니다.

`getConnection()`으로 Connection 객체를 부를 때 프록시 객체인 `ConnectionProxyHandler`를 반환하도록 합니다.

// AOP 정의 클래스
@Aspect
@Component
@RequiredArgsConstructor
public class QueryStatisticsAop {

    @Around("execution(* javax.sql.DataSource.getConnection())")
    public Object getConnection(ProceedingJoinPoint joinPoint) throws Throwable {
        Object connection = joinPoint.proceed();
        return Proxy.newProxyInstance(
            connection.getClass().getClassLoader(),
            connection.getClass().getInterfaces(),
            new ConnectionProxyHandler(connection, queryStatistics)
        );
    }

 

프록시 객체인 `ConnectonProxyHandler`에서는 `preparedStatement()` 호출을 감지해서

그 결과로 반환되는 객체를 다시 한 번 프록시로 감쌉니다.

`PreparedStatement` 대신 프록시 객체 `PreparedStatementProxyHandler`를 반환합니다.

return Proxy.newProxyInstance(
                invokeResult.getClass().getClassLoader(),
                invokeResult.getClass().getInterfaces(),
                new PreparedStatementProxyHandler(invokeResult, queryStatistics)
            );

 

`PreparedStatementProxyHandler`에서는 쿼리를 실제로 실행하는 메서드를 감지합니다.

참고로 `PreparedStatement`에서 쿼리 실행하는 메서드로는 `executeQuery()`/`execute()`/`executeUpdate()`가 있으며

executeQuery는 SELECT, executeUpdate는 INSERT/UPDATE/DELETE, execute는 모든 SQL 실행 가능한 대표 메서드들입니다.

@RequiredArgsConstructor
public class PreparedStatementProxyHandler implements InvocationHandler {

    private final Object preparedStatement;
    private final QueryStatistics queryStatistics;

    private boolean isExecuteQuery(final Method method) {
        // TODO:현재 호출된 Method가 execute, executeUpdate 등 쿼리를 실행하는 메소드인지 확인함
    }
    
    @Override
    public Object invoke(final Object proxy, final Method method, final Object[] args)
        throws Throwable {
        // true면 쿼리를 실제로 실행하는 시점
        if (isExecuteQuery(method)) {
            
            // TODO: 쿼리 실행 횟수와 시간을 카운트하는 로직 구현

        }
        return method.invoke(preparedStatement, args); // 원래 PreparedStatement 동작 수행
    }
}

 

 

지금까지의 계층을 정리해보면 다음과 같습니다.

클라이언트 요청
   ↓
AOP (DataSource.getConnection)
   ↓
ConnectionProxyHandler
   ↓
PreparedStatementProxyHandler
   ↓
executeQuery / executeUpdate 호출 → QueryStatistics 기록

📌 쿼리 실행 시간 & 실행 횟수 측정하기

`PreparedStatementProxyHandler`에서 쿼리를 실제로 실행하는 메서드를 감지했다면

그 안에서 쿼리 실행 횟수와 쿼리 실행 시간을 측정해야 합니다.

 

`QueryStatistics` 객체에 관련 필드와 메서드를 만들고 쿼리가 실행될 때마다 더하면 됩니다.

@Component
@RequestScope
public class QueryStatistics {

    private String apiUrl; // API 경로
    private long queryCounts = 0L;	// 쿼리 실행 횟수
    private long queryTime = 0L; // 쿼리 실행 시간

    public void setApiUrl(String url) {
        this.apiUrl = url;
    }

    public void addQueryTime(long queryTime) {
        this.queryTime += queryTime;
    }

    public void addQueryCount() {
        this.queryCounts++;
    }

}

@Override
public Object invoke(final Object proxy, final Method method, final Object[] args)
    throws Throwable {
    if (isExecuteQuery(method)) { // 한 번의 쿼리가 실행될 때마다
    	
        // 이번에 실행된 쿼리의 실행 시간 구하기
        final long beforeTime = System.currentTimeMillis();
        final Object result = method.invoke(preparedStatement, args);
        final long afterTime = System.currentTimeMillis();
        
        // 카운터 증가
        queryStatistics.addQueryCount();
        queryStatistics.addQueryTime(afterTime - beforeTime);

        return result;
    }
    return method.invoke(preparedStatement, args);
}

📌 API 단위에 공통 적용하기

 

이제는 AOP를 정의하는 클래스 `QueryStatisticsAop` 클래스에서
각 API 요청마다 가로채서 수집한 쿼리 통계를 로그로 출력하도록 해봅니다.

@RequestScope로 생성된 QueryStatistics를 사용하기 때문에 한 요청 단위마다 독립적으로 기록됩니다.

// RestController 내 모든 메서드 전체를 대상으로 적용 (within)
@Around("within(@org.springframework.web.bind.annotation.RestController *)")
public Object calculateExecutionTime(final ProceedingJoinPoint joinPoint) throws Throwable {
    ServletRequestAttributes attributes =
        (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
    if (attributes != null) {
    	// QueryStatistics 객체에 API 경로 설정
        queryStatistics.setApiUrl(
            attributes.getRequest().getMethod() + " " + attributes.getRequest()
                .getRequestURI());
    }
	
    Object result = joinPoint.proceed();

	// 통계 결과 로그로 출력
    log.info("Query Statistics: URL = {},  Query Count = {}, Query Time = {}(ms)",
        queryStatistics.getApiUrl(), queryStatistics.getQueryCounts(),
        queryStatistics.getQueryTime());
        
    return result;
}

---

실행 결과

이렇게 API별로 경로, 실행되는 쿼리 횟수와 쿼리들의 실행 시간이 로그로 출력됐습니다.

이제는 더 이상 일일이 세지 않아도 됩니다!

또한 N+1 문제 해결 전후 쿼리 실행 시간을 비교하면 성능이 빨라졌는지를 확실하게 비교할 수 있습니다.

 

 

---

전체 구현 코드

실제로 올린 Github PR: 🔗

@Component
@RequestScope
@Getter
@Profile("dev")
public class QueryStatistics {

    private String apiUrl;
    private Long queryCounts = 0L;
    private Long queryTime = 0L;

    public void setApiUrl(String url) {
        this.apiUrl = url;
    }

    public void addQueryTime(Long queryTime) {
        this.queryTime += queryTime;
    }

    public void addQueryCount() {
        this.queryCounts++;
    }

}

 

@Aspect
@Component
@Profile("dev")
@Slf4j
@RequiredArgsConstructor
public class QueryStatisticsAop {

    private final QueryStatistics queryStatistics;

    @Around("execution(* javax.sql.DataSource.getConnection())")
    public Object getConnection(ProceedingJoinPoint joinPoint) throws Throwable {
        if (RequestContextHolder.getRequestAttributes() == null) {
            // HTTP 요청이 아닌 경우 AOP를 건너뛰고 원래대로 실행
            return joinPoint.proceed();
        }
        Object connection = joinPoint.proceed();
        return Proxy.newProxyInstance(
            connection.getClass().getClassLoader(),
            connection.getClass().getInterfaces(),
            new ConnectionProxyHandler(connection, queryStatistics)
        );
    }

    @Around("within(@org.springframework.web.bind.annotation.RestController *)")
    public Object calculateExecutionTime(final ProceedingJoinPoint joinPoint) throws Throwable {
        ServletRequestAttributes attributes =
            (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        if (attributes != null) {
            queryStatistics.setApiUrl(
                attributes.getRequest().getMethod() + " " + attributes.getRequest()
                    .getRequestURI());
        }

        Object result = joinPoint.proceed();

        log.info("Query Statistics: URL = {},  Query Count = {}, Query Time = {}(ms)",
            queryStatistics.getApiUrl(), queryStatistics.getQueryCounts(),
            queryStatistics.getQueryTime());
        return result;
    }
}

 

@Profile("dev")
@RequiredArgsConstructor
public class ConnectionProxyHandler implements InvocationHandler {

    private final Object connection;
    private final QueryStatistics queryStatistics;

    @Override
    public Object invoke(final Object proxy, final Method method, final Object[] args)
        throws Throwable {
        Object invokeResult = method.invoke(connection, args);
        if (isGeneratePrepareStatement(method)) {
            return Proxy.newProxyInstance(
                invokeResult.getClass().getClassLoader(),
                invokeResult.getClass().getInterfaces(),
                new PreparedStatementProxyHandler(invokeResult, queryStatistics)
            );
        }
        return invokeResult;
    }

    private boolean isGeneratePrepareStatement(final Method method) {
        return method.getName().contains("prepareStatement");
    }
}

 

@Profile("dev")
@Slf4j
@RequiredArgsConstructor
public class PreparedStatementProxyHandler implements InvocationHandler {

    private final Object preparedStatement;
    private final QueryStatistics queryStatistics;

    @Override
    public Object invoke(final Object proxy, final Method method, final Object[] args)
        throws Throwable {
        if (isExecuteQuery(method)) {
            final Long beforeTime = System.currentTimeMillis();
            final Object result = method.invoke(preparedStatement, args);
            final Long afterTime = System.currentTimeMillis();
            queryStatistics.addQueryCount();
            queryStatistics.addQueryTime(afterTime - beforeTime);

            return result;
        }
        return method.invoke(preparedStatement, args);
    }

    /**
     * @param method
     * @return 이 메소드가 execute, executeUpdate 등 쿼리를 실행하는 메소드인지 확인함
     */
    private boolean isExecuteQuery(final Method method) {
        List<String> JDBC_QUERY_METHOD = List.of("executeQuery", "execute", "executeUpdate");
        return JDBC_QUERY_METHOD.contains(method.getName());
    }
}

---

참고자료

스프링의 웹 스코프(Web Scope) 이해하기: Request Scope

[Spring]Request Scope를 사용해서 깔끔하게 로그남기기
[AOP] 쿼리 카운터 제작기

AOP 활용 - 쿼리 카운터 만들기

하나의 요청에 나가는 쿼리 개수를 효율적으로 세어보자 (Hibernate StatementInspector, Spring AOP)