spring jpa (Hibernate) 요청당 쿼리 count

회사 프로젝트가 거의 막바지로 이르면서 성능과 관련된 코드들을 리팩토링 하는중이다. 거의 대부분 jpa와 관련 있을 듯해서 jpa 튜닝(?) 이라고 해야 되나? 아무튼 그러고 있다. orm이 아닌 mapper 같은 경우에는 개발하면서 대충 몇번의 쿼리를 날리는지 감으로 알 수 있지만 jpa같은 경우에는 언제 어디서 쿼리들이 n+1이 될지 모르니 계속 모니터링을 하기 귀찮아서 로컬에서 테스트하거나 테스트 서버에 올릴때 요청당 쿼리를 count하는 것을 만들었다. 설명보다는 코드를 보자.

@Slf4j
@RequiredArgsConstructor
public class RequestCountInterceptor extends HandlerInterceptorAdapter {

  private final HibernateInterceptor hibernateInterceptor;

  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
    hibernateInterceptor.start();
    return true;
  }

  @Override
  public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
    Counter counter = hibernateInterceptor.getCount();
    long duration = System.currentTimeMillis() - counter.getTime();
    Long count = counter.getCount().get();
    log.info("time : {}, count : {} , url : {}", duration, count,  request.getRequestURI());
    if(count >= 10){
      log.error("한 request 에 쿼리가 10번 이상 날라갔습니다.  날라간 횟수 : {} ", count);
    }
    hibernateInterceptor.clear();
  }
}

spring 의 기본적으로 제공해주는 Interceptor를 상속받아 구현하였다. 여기서는 preHandle에 시작을 알리고 afterCompletion메서드에서는 시간과 count를 출력하고 마무리 짓는 클래스이다. 흔한 Interceptor이다. 다음으로는 하이버네이트 인터셉터이다.

public class HibernateInterceptor implements StatementInspector {

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

  void start() {
    queryCount.set(new Counter(new AtomicLong(0), System.currentTimeMillis()));
  }

  Counter getCount() {
    return queryCount.get();
  }

  void clear() {
    queryCount.remove();
  }

  @Override
  public String inspect(String sql) {
    Counter counter = queryCount.get();
    if(counter != null){
      AtomicLong count = counter.getCount();
      count.addAndGet(1);
    }
    return sql;
  }
}

@Data
public class Counter {
  private final AtomicLong count;
  private final Long time;
}

여기서는 실제 쿼리를 날릴때 캐치해서 count를 올려주는 그런 클래스이다. 시작을 알리는 메서드와 끝을 알리는 메서드 그리고 데이터를 가져오는 메서드가 존재한다. 최초에는 count에 0과 현재시간을 넣어 주기만 하면된다. 그리고 하이버네이트가 쿼리를 날릴 때 count를 올려주기만 하면 끝이다. 필요하다면 여기서 sql을 조작 할 수 도 있다.

@Configuration
public class HibernateConfig extends HibernateJpaAutoConfiguration {

  public HibernateConfig(DataSource dataSource, JpaProperties jpaProperties, ObjectProvider<JtaTransactionManager> jtaTransactionManagerProvider) {
    super(dataSource, jpaProperties, jtaTransactionManagerProvider);
  }

  @Override
  protected void customizeVendorProperties(Map<String, Object> vendorProperties) {
    vendorProperties.put("hibernate.session_factory.statement_inspector", hibernateInterceptor());
    super.customizeVendorProperties(vendorProperties);
  }

  @Bean
  public HibernateInterceptor hibernateInterceptor() {
    return new HibernateInterceptor();
  }

  @Bean
  public RequestCountInterceptor requestCountInterceptor() {
    return new RequestCountInterceptor(hibernateInterceptor());
  }
}

필자는 거의 대부분 Spring boot 로 개발을 해서 설정도 Spring boot 기준으로 한다. 또한 jpa구현체도 하이버네이트다. 구현체를 다른거를 쓴다면 아마도 다른거를 상속 받아야 겠지만 필자는 거의 하이버네이트만 쓰기에 다른거는 모르겠다. RequestCountInterceptor 클래스랑 HibernateInterceptor클래스를 빈으로 등록해주고 HibernateJpaAutoConfiguration를 상속받아 customizeVendorProperties를 오버라이딩 받으면 된다. 그리고 속성중 hibernate.session_factory.statement_inspector에 우리가 만든 하이버네이트 인터셉터를 넣으면된다. Spring boot를 쓰지 않는다면 xml이나 java config에 hibernate.session_factory.statement_inspector을 추가 하면 될 거 같다. 마지막으로 spring 인터셉터를 등록하자.

@Configuration
@RequiredArgsConstructor
public class WebConfig extends WebMvcConfigurerAdapter {

  private final RequestCountInterceptor requestCountInterceptor;

  @Override
  public void addInterceptors(InterceptorRegistry registry) {
    registry.addInterceptor(requestCountInterceptor).addPathPatterns("/**");

  }
}

RequestCountInterceptor를 빈으로 등록하는 거는 WebConfig에 있는게 더 어울린다. 뭐 그게 중요한게 아니니.. 중요한건 실서버에는 올리지 말자.... 혹시나 이코드로 인해 실서버가 죽으면 안되니.. 정말로 테스트를 위한 코드이니 테스트로만 사용하고 운영서버에서는 빼자! 테스트를 해보면 아래와 같이 로그가 남겨진다.

2016-09-03 00:00:42.482  INFO 885 --- [nio-8080-exec-4] m.w.testing.RequestCountInterceptor      : time : 51, count : 4 , url : /

근데 뭔데 4번이나 날라갔지? 흠 아 참고로 Spring boot 1.4 와 hibernate 5.0.9 기준이다.