JPA 성능 개선기 1. 쿼리 개수 및 시간 로깅

서론

Spring Data JPA를 사용하면 메소드 이름만으로도 쿼리문을 자동으로 만들어준다.
덕분에 쿼리문을 작성하지 않고도 빠르게 개발이 가능하다.

 

그러나 잘못사용할 경우 N+1 문제와 같이 쓸데없이 많은 쿼리가 날라가 성능저하가 발생할 수 있다.
JPA 성능을 개선하기 전 각각의 요청마다 얼마나 많은 쿼리가 발생하는지 눈으로 확인하기 위해 쿼리 개수 및 시간을 로그로 찍어보려고 한다.

JPA에서 쿼리 개수 및 시간을 측정하는 방법

StatementInspector

하이버네이트에서 제공하는 기능 중 StatementInspector이라는 것이 있다.
StatementInspector를 이용하면 JPA가 자동으로 생성하는 SQL문을 중간에 조회하거나 수정할 수 있다.

hibernate 공식 문서 

 

공식 문서 설명에 따르면 이렇게 적혀있다.

Inspect the given SQL, possibly returning a different SQL to be used instead.
Note that returning null is interpreted as returning the same SQL as was passed.

주어진 SQL을 검사하거나, 다른 SQL문을 대신 반환할 수 있다.
null을 반환하는 것은 동일한 SQL문을 전달하는 것을 의미한다.

StatementInspector 작동원리

StatementInspector를 이용하면 JPA가 자동으로 생성하는 SQL문을 중간에 조회하거나 수정할 수 있다.
StatementInspector에는 inspect라는 추상메서드가 존재한다.
inspect() 메서드는 하이버네이트에서 실행하려고 하는 SQL 문을 가져와서 수정한 뒤 하이버네이트 StatementPreparer에 반환하는 기능을 한다.

 

우리는 StatementInspector 인터페이스를 구현해 하이버네이트에서 자동으로 생성하는 SQL문의 개수를 셀 것이다.

StatementInspector 구현체 코드

@Component
public class QueryCountInspector implements StatementInspector {

    private final ThreadLocal<Counter> queryCount = new ThreadLocal<>();

    public void startCounter() {
        queryCount.set(new Counter(0L, System.currentTimeMillis()));
    }

    public Counter getQueryCount() {
        return queryCount.get();
    }

    public void clearCounter() {
        queryCount.remove();
    }

    @Override
    public String inspect(String sql) {
        Counter counter = queryCount.get();
        if (counter != null) {
            counter.increaseCount();
        }
        return sql;
    }

    @Getter
    class Counter {
        private Long count;
        private Long time;

        public Counter(Long count, Long time) {
            this.count = count;
            this.time = time;
        }

        public void increaseCount() {
            count++;
        }
    }
}

StatementInspector를 구현한 QueryCountInspector라는 빈을 생성했다.
각 메서드가 의미하는 바를 알아보자.

 

먼저, startCounter()는 클라이언트로부터 요청이 들어오면 실행하는 메서드로 쿼리수는 0으로 초기화하고 현재시간을 기록한 Counter 객체를 생성한다.
하이버네이트에서 SQL문이 생성될 때마다 inspect() 메서드를 통과하게 되는데, 이때 쿼리수를 1씩 증가시킨다. 그리고 요청이 모두 처리되어 응답한 뒤에는 remove() 메서드를 통해 생성한 Counter를 제거한다.

 

여기서 눈여겨볼 점은 ThreadLocal에 Counter를 저장한다는 것이다.

ThreadLocal 이란 ThreadLocal은 한 thread 안에서 파라미터 또는 리턴 값으로 정보를 제공하는 것이 아닌 다른 방법으로 thread 안에서의 값을 공유하는 방법을 제공한다.
ThreadLocal의 내부는 thread 정보를 key로 하여 값을 저장해두는 Map 구조를 가지고 있다.
*출처 : https://sabarada.tistory.com/163

요청이 들어오면 서블릿 컨테이너가 스레드로 각 요청을 실행한다.

그래서 각각의 스레드와 Counter를 1대1 저장하도록 ThreadLocal을 사용했다.

ThreadLocal을 이용해 각각의 요청과 생성한 Counter의 생명주기를 동일하게 맞출 수 있다.

 

HibernateProperties 등록

StatementInspector을 구현했다고해서 끝이 아니다.
방금 작성한 구현체를 HibernateProperties에 등록해야 한다.

레퍼런스를 찾아보면 JPA의 persistence.xml에 등록해야한다고 나와있다. stackoverflow 

// 우리는 이 방법으로 하이버네이트 프로퍼티에 등록할 수 없다.
<property
    name="hibernate.session_factory.statement_inspector"
    value="com.woowacourse.teatime.teatime.aspect.LoggingInterceptor"
/>

우리는 스프링부트를 사용하고 있기 때문에 application.yml파일에 원래는 등록했어야 한다.

// 우리는 이 방법으로 하이버네이트 프로퍼티에 등록할 수 없다.
spring:
  jpa:
    hibernate:
    properties:
      hibernate:
        session_factory:
          statement_inspector: com.woowacourse.teatime.teatime.aspect.LoggingInterceptor

하지만 이 방법을 사용할 수 없었다.
StatementInspector 구현체가 우리가 직접 만든 커스텀 빈을 주입받고 있기 때문이다.
그래서 빈이 모두 초기화 된 뒤에 HibernateProperties에 등록하는 방법을 택했다.

@RequiredArgsConstructor
@Configuration
public class HibernateConfig {

    private final QueryCountInspector queryCountInspector;

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

인터셉터 또는 필터에서 사용

요청이 들어오면 startCounter()로 초기화를 진행하고, 응답 후 쿼리수와 시간을 로깅하는 코드를 인터셉터 또는 필터에 작성해주면 된다.

@Slf4j
@RequiredArgsConstructor
@Component
public class LoggingInterceptor implements HandlerInterceptor {

    private static final String QUERY_COUNT_LOG_FORMAT = "STATUS_CODE: {}, METHOD: {}, URL: {}, TIME: {}초, QUERY_COUNT: {}";
    private static final String QUERY_COUNT_WARNING_LOG_FORMAT = "하나의 요청에 쿼리가 10번 이상 날라갔습니다.  쿼리 횟수 : {} ";
    private static final int QUERY_COUNT_WARNING_STANDARD = 10;

    private final QueryCountInspector queryCountInspector;

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        queryCountInspector.startCounter();
        return true;
    }

    @Override
    public void afterCompletion(final HttpServletRequest request, final HttpServletResponse response,
                                final Object handler, final Exception ex) {
        Counter counter = queryCountInspector.getQueryCount();
        final double duration = (System.currentTimeMillis() - counter.getTime()) / 1000.0;
        final long queryCount = counter.getCount();

        log.info(QUERY_COUNT_LOG_FORMAT, response.getStatus(), request.getMethod(), request.getRequestURI(),
                duration, queryCount);
        if (queryCount >= QUERY_COUNT_WARNING_STANDARD) {
            log.warn(QUERY_COUNT_WARNING_LOG_FORMAT, queryCount);
        }
        queryCountInspector.clearCounter();
    }
}

쿼리시간을 직관적으로 확인하기 위해 ms 단위가 아닌 초단위로 변환했다.

최종 로그

콘솔에는 다음과 같이 로그가 기록된다.

확인해보니 코치메인뷰 조회 요청을 비롯한 여러 요청에서 N+1 문제가 발생한 것을 눈으로 확인할 수 있었다.
이것들을 하나씩 개선해나갈 예정이다.

 

출처

• https://docs.jboss.org/hibernate/orm/5.2/javadocs/
• API의 쿼리 개수 세기 - (1) 하이버네이트를 이용한 카운팅
• How to intercept and modify SQL queries with the Hibernate StatementInspector
• https://stackoverflow.com/questions/39112308/how-i-can-configure-statementinspector-in-hibernate
• https://likispot.tistory.com/73