쿼리 병목 확인을 위한 쿼리 로깅 하기

HYEON·2024년 5월 10일

Hibernate JPA Spring 지구미

문제 상황

요즘 다시 지구미를 디벨롭 해나가는 상황에서 성능에 대한 관심이 높아져서 쿼리가 몇 번 나가는지 체크하고 실제 WAS에서 요청이 나가기 까지 얼마나 걸리는지 측정하고자 했다.

이전에는 SQL 로그와 포스트맨을 통해서 쿼리를 세고, 실행 시간을 측정했는데 보다 효율적인 방법을 생각하게 되었다.

Hibernate StatementInspector

하이버네이트는 StatementInspector를 제공한다. 이것을 이용하면 JPA가 생성하는 SQL문을 검사하고 대신 사용할 다른 SQL을 반환할 수도 있다.

공식 문서에 따르면 null을 반환하면 전달된 것과 동일한 SQL을 반환하는 것으로 해석된다고 한다.

이 인터페이스를 활용해서 쿼리를 셀 수 있다.

인터페이스는 inspect라는 메서드를 가지는데 하이버네이트가 생성한 SQL문을 가져와 조작할 수 있게 하고 반환하는 메서드이다.

구현 코드

@Component
@RequiredArgsConstructor
public class QueryInspector implements StatementInspector {

    private final QueryCounter queryCounter;

    @Override
    public String inspect(String sql) {
        if (isInRequestScope()) {
            queryCounter.increase();
        }

        return sql;
    }

    private boolean isInRequestScope() {
        return Objects.nonNull(RequestContextHolder.getRequestAttributes());
    }

    public int getQueryCount() {
        return queryCounter.getCount();
    }
}

@Component
@RequestScope
public class QueryCounter {

    private int count = 0;

    public void increase() {
        count++;
    }

    public int getCount() {
        return count;
    }
}

QueryCounter

RequestScope는 HTTP 요청이 들어오면 나갈 때 까지 유지되는 빈 스코프이다. 이것을 사용해서 HTTP request 별로 쿼리 실행을 센다.
StatementInspector 구현체에 @RequestScope를 하면 안될까 생각할 수 있는데, StatementInspector는 HibernateProperty로 하나만 등록해서 공유해서 사용하기 때문에 안된다.
또한 Thread-Safe 하게 구현해야 한다.

RequestContextHolder

RequestContextHolder는 스프링 웹 애플리케이션에서 현재 요청과 관련된 정보를 저장하고 있는 스태틱(정적) 메소드와 필드를 제공하는 유틸리티 클래스이다. 공식문서
이 클래스는 현재 실행 중인 스레드(Thread)에 바인딩된 RequestAttributes 객체에 접근할 수 있게 해준다.
RequestContextHolder.getRequestAttributes()이 true면 HTTP 요청 주기 안에 있다는 것이다.
따라서 Hibernate가 SQL을 보낼 때 QueryInspector를 거치게 되어 있는데 이 때 이 요청이 HTTP 요청인지 확인 후에 쿼리를 센다.
예를 들면 테스트 코드를 실행할 때 실행되는 SQL은 체크하지 않는다.

근데 StatementInspector를 구현만 한다고 사용하는 것이 아니다.
구성 속성 "hibernate.session_factory.statement_inspector"를 통해 구현을 지정해야만 동작한다.
이는 yml, properties로 옵션을 사용해서 지정할 수도 있는데 QueryCount라는 우리가 직접 만든 빈을 사용해야 해서 빈이 초기화 된 후에 사용해야 한다.

HibernatePropertiesCustomizer

해결 방법으로는 다양한 방법이 있지만 Spring에서 지원하는 HibernatePropertiesCustomizer를 이용했다.

공식 문서에는 다음과 같이 설명 되어 있다.

Callback interface that can be implemented by beans wishing to customize the Hibernate properties before it is used by an auto-configured EntityManagerFactory.

해석해보면 자동 구성된 EntityManagerFactory에서 사용하기 전에 Hibernate 속성을 사용자 지정하려는 Bean에서 구현할 수 있는 콜백 인터페이스이다.

이것을 이용해서 스프링 빈이 초기화 되고 난 후 설정을 등록하도록 구현했다.

함수형 인터페이스이므로 다음과 같이 사용했다.

@Configuration
@RequiredArgsConstructor
public class HibernateConfig {

    private final QueryInspector queryInspector;

    @Bean
    public HibernatePropertiesCustomizer hibernatePropertyConfig() {
        return hibernateProperties ->
                hibernateProperties.put(AvailableSettings.STATEMENT_INSPECTOR, queryInspector);
    }
}

Interceptor로 등록

@Configuration
@RequiredArgsConstructor
public class InterceptorConfig implements WebMvcConfigurer {

    private final PerformanceLoggingInterceptor performanceLogging;

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(performanceLogging);
    }
}

위 쿼리가 날아간 횟수를 측정하는 코드 말고도 실행 시간을 쓰레드 로컬을 활용해 측정하는 클래스도 작성해서 두 클래스를 하나 묶어 PerformanceLoggingInterceptor를 만들어서 Interceptor로 등록했다.

잘 작동하는 모습이다.

느낀점

최근 깊이가 부족한 느낌으로 학습을 통해 알고 있던 것들을 다시 다지고 새로운 내용을 배웠다.
그러고 나서 다시 프로젝트를 리팩토링 하는 과정을 통해 부족했던 점, 돌아 가기만 하는 코드를 만든 부분들이 눈에 들어왔다.
일단 로깅을 제대로 해야 내가 잘하고 있는지에 대해 눈으로 볼 수 있다고 생각해서 로깅을 가장 처음 구현했다.
구현하면서도 스프링 부트, MVC Interceptor과 같은 기본적 내용과 그리고 위에 언급한 RequestHolder나 빈 등록 시점에 설정 등록 하는 법과 같은 많은 것들이 편리하게 지원되는구나 느꼈다.
API 로깅을 하나씩 확인하는데 N+1 문제가 발생하는 부분들이 보였다.
하나 하나 이제부터 고쳐야 할 생각에 너무 신나는 것 같다 !