N+1 발생을 쉽게 파악할 수 없을까?

들어가며...

진지한 글씨체로 글을 시작해 보자. 얼마 전 나는 "서버 성능 병목은 어디서 발생할까?" 라는 글을 작성한 적이 있다.

 

그리고 1차 부하 테스트에서 엄청난 성능을 검증한 바가 있는데, 이때까지 나는 단순히 "데이터베이스 리전이 해외고, 서버 자원이 부족해서 그런가 보다." 하고 넘어갔다. 그리고 앱을 사용하면서도 초반 로딩 속도가 조금 느린 것이 단순히 서버 자원이 부족하구나 생각했는데, 오늘 개발하면서 쿼리 로그를 보던 중 N+1이 발생하는 것을 발견했다.

무엇이 문제였는가?

Arggregation root가 포함하는 데이터는 풍부한 것이 좋겠지?!

 

처음 개발을 하면서 코드 컨벤션을 정할 때, 몇 가지 정한 규칙이 있었다. 도메인 객체는 서비스 외부로 퍼지지 않는다. 서비스는 서비스끼리 직접 참조하지 않는다. 등 이런 조건에서 이번에 문제가 된 부분은 도메인 객체의 범위를 제어하는 규칙에서 발생했다.

 

도메인 객체가 서비스 외부로 노출될 경우 반드시 DTO 객체로 변환하는 작업이 있다. 이 작업에 Lazy loading으로 연결된 하위 객체가 있었는데, 이 객체는 부모 객체와 매우 연관이 있어서 DTO에 포함시켰다. 코르를 보면 다음과 같았다.

public record EntityDetail(...) {

  public static EntityDetail from(@NotNull final Entity entity) {
    return new JournalDetail(
    	...
        entity.getSubEntities(), // LAZY LOADING!
        ...
    );
  }
}

 

이런 상황에서 목록을 조회하는 부분에서 N+1이 발생한 것이다. 이전 회사에서도 ORM을 사용하고, N+1 문제는 워낙 유명한 문제라 방심하다 당한 기분이었다.

해결책은?

이번 일로 아무리 익숙한 개념이라도, 사람은 실수를 할 수 있으니 이런 문제는 시스템적으로 예방하는 것이 좋을 것 같아 N+1 detector라는 키워드로 조사했다. 구글에 검색해 보면 멋진 분들의 블로그들이 나오는데 그중 두 곳이 가장 마음에 들었다.

• [kerdy] AOP, ThreadLocal을 사용하여 N+1 detector 만들어보기
• How to detect the Hibernate N+1 query problem during testing

두 블로그 모두 방식은 비슷하다. 하지만 후자가 좀 더 기능적으로 풍부 + 어떻게 구현했는지 궁금해서 코드를 읽고 있는 중이라 좀 더 애착이 가 이 방식을 소개해보려고 한다.

Datasource-proxy

datasource-proxy는 datasource를 proxy로 감싸 다양한 통계 데이터를 수집 + 로그 개선 등 다양한 방법으로 사용할 수 있다.

@Configuration
public class DataSourceProxyBeanPostProcessor implements BeanPostProcessor {

  @Override
  public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
    if (bean instanceof DataSource dataSource) {
      ChainListener listener = new ChainListener();
      SLF4JQueryLoggingListener loggingListener = new SLF4JQueryLoggingListener();
      listener.addListener(loggingListener);
      listener.addListener(new DataSourceQueryCountListener());
      return ProxyDataSourceBuilder.create(dataSource)
          .name("datasource-proxy")
          .listener(listener)
          .build();
    }
    return bean;
  }

  @Override
  public Object postProcessBeforeInitialization(Object bean, String beanName)
      throws BeansException {
    return bean;
  }
}

 

사용하는 방법도 굉장히 간단한데, 등록된 Datasource bean을 ProxyDataSourceBuilder로 만들어 등록만 해주면 끝난다. 특히 addListener로 추가 기능을 등록해 주면 더 풍부한 활용성을 가질 수 있어서 읽으면 좋은 라이브러리다.

 

이렇게 등록하면 ThreadLocal에 각 수행한 쿼리에 대한 통계 정보가 쌓이는데, 이 내용을 요청 완료 시 로그로 찍어주면 해당 요청에서 발생한 쿼리 통계치를 알 수 있다.

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

  @Override
  public void afterCompletion(
      HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) {
    final String LOG_FORMAT = "Method: {}, URI: {}, Status: {}, QueryCount: {}";
    log.info(
        LOG_FORMAT,
        request.getMethod(),
        request.getRequestURI(),
        response.getStatus(),
        getQueryCount());
  }

  private long getQueryCount() {
    final long queryCount = QueryCountHolder.getGrandTotal().getSelect();
    if (queryCount > 0) {
      final int DUPLICATE_COUNT_DIVIDE = 3;
      return queryCount / DUPLICATE_COUNT_DIVIDE;
    }
    return queryCount;
  }
}

 

10개의 게시글을 조회하는 API에서 N+1이 발생한 로그. 임계치를 정해서 일정 수 이상 호출된 경우 error 레벨 로그를 남기는 것도 좋을 것 같아 :D