[SpringBoot] JPA 쿼리 성능 감시 가이드

개요

팀 내 JPA 쿼리 성능 감시 가이드를 작성하는 업무를 맡은 김에 간단하게 다음 항목을 정리해 보겠습니다.

• JPA slow 쿼리 검출
• JPA N + 1 문제가 의심되는 api 검출

 

JPA N + 1 문제가 의심되는 api의 경우 범고래님 블로그를 많이 참고했습니다! 감사합니다.

 

프로젝트 환경

• SpringBoot 2.6.3
• Java 1.8

 

Jpa slow 쿼리 검출

application.yml에 다음과 같이 설정을 하면 Hibernate에서 slow query를 로깅해 줍니다.

 

 

테스트 삼아 100ms를 기준으로 잡았고 그 결과 실행시간이 205ms인 SELECT 쿼리가 아래와 같이 로깅되었습니다.

 

 

오래 걸린 쿼리를 로깅하는 것 자체는 좋았지만 구현한 JpaRepository가 워낙 많다 보니 검출된 쿼리들이 어느 메서드를 통해 호출되는지 파악하기 쉽지 않았습니다.

이에 따라 저는 AOP를 구현해 JPA 쿼리 실행 시간을 측정하고, 실행 시간이 일정 임계값을 초과하는 경우 어느 메서드가 오래 걸렸는지 로깅하도록 구현했습니다.

 

 

코드 부연 설명

• JpaRepository에서의 모든 쿼리 실행 시점을 지정하기 위해 Spring Data의 CrudRepository 인터페이스와 해당 인터페이스의 구현체를 대상으로 AOP를 적용해 모든 JPA 쿼리 실행에 대해 Aspect을 적용
• 메서드를 호출하는 시점에 시작 시간, 메서드명, 그리고 전달된 매개변수를 ThreadLocal에 저장
• 메서드가 실행된 후 ThreadLocal에 저장된 시작 시간과 비교하여 실행 시간을 측정하고 만약 실행 시간이 설정한 임계치 이상일 경우 로깅

 

Jpa N + 1 문제가 의심되는 api 검출

JPA에서 N+1 문제는 관련된 엔티티를 로딩할 때 발생할 수 있는 성능 문제이며 해당 문제는 Lazy Loading이 활성화된 상황에서 한 개의 엔티티를 가져올 때 관련된 엔티티들이 필요할 때마다 추가적인 쿼리가 발생하여 성능에 영향을 미칩니다.

• ex) 하나의 주문(Order) 엔티티와 여러 개의 주문 상품(OrderItem) 엔티티가 있을 때, Lazy Loading으로 설정되어 있다면 주문 엔티티를 조회할 때는 쿼리가 한 번만 실행되지만, 주문의 각 상품을 접근할 때마다 각각의 상품에 대한 추가적인 쿼리가 발생
• 이는 주문이 10개 있을 때, 관련된 상품을 로딩하기 위해 10번의 추가 쿼리가 발생하여 총 11번의 쿼리가 실행되는 상황을 의미하며 하나의 sql을 호출했지만 연관된 필드에 대한 쿼리가 N번 나간다고 해서 N+1 문제
• N+1 문제는 보통 Fetch Join 혹은 @BatchSize를 통해 해결

 

앞서 설명한 대로, N+1 문제는 성능에 영향을 미칠 수 있으므로 어떤 API에서 N+1 문제가 발생할 수 있는지 파악해야 합니다.

저는 단일 쓰레드에서 동일한 SELECT 문이 N번 호출될 경우 N+1 문제가 의심된다고 가정하고 접근했습니다.

 

N+1 문제가 의심되는 api를 검출하기 위해서는 다음의 클래스들이 필요합니다.

• Hibernate가 데이터베이스와 상호 작용할 때 SQL 문을 검사하고 조작할 수 있는 StatementInspector 인터페이스 구현체
• 모든 api를 호출하기 전과 후를 트래킹 할 수 있는 HandlerInterceptor 구현체

 

1. StatementInspector

 

• Hibernate StatementInspector는 Hibernate가 데이터베이스와 상호 작용할 때 SQL 문을 검사하고 조작할 수 있는 인터페이스
• 주로 SQL 쿼리를 로깅하거나 수정하기 위해 사용

 

저는 StatementInspector에서 제공하는 inspect 메서드를 통해 Hibernate에서 호출하는 sql문을 가로채 SELECT문만 발라내서 Map에 저장하는 방식으로 구현했습니다.

• Map의 key는 호출한 Select 쿼리
• Map의 value는 호출한 횟수

만약 Map 내 key-value 쌍 중 value가 2 이상일 경우 동일한 쿼리가 2번 이상 호출되었다는 의미로 N+1 문제가 발생했음을 의심해 볼 수 있습니다.

 

2. 인터셉터

 

• api를 호출하기 전 preHandle() 메서드 내 ThreadLocal에 로깅할 DTO 저장
  • 이때 시작 시간 저장

 

• api 실행 후 afterCompletion() 메서드에서 ThreadLocal에 저장된 시작 시간을 기준으로 실행 시간을 측정하고 Map을 꺼내와 value가 2 이상인 key가 있는지 확인
  • 만약 value가 2 이상인 key 즉, 동일 쿼리가 2번 이상 호출되었을 경우 N+1 문제를 발생시키는 것으로 간주해 해당 api 메서드, api URL, 그리고 단일 쓰레드에서 호출한 sql문들을 로깅

 

* 다만, @BatchSize를 통해 최적화했음에도 불구하고 @BatchSize에 비해 많은 결과가 나와 N+1 문제가 아님에도 동일 쿼리를 여러 번 호출하는 케이스도 있으므로 애플리케이션 분석 후 적합한 로깅 기준을 선정하시면 될 것 같습니다.

 

3. 구현 내용

 

3.1 JpaInspector.java

 

 

* 멀티 모듈 프로젝트일 경우 EntityManager의 property에 다음과 같이 적용 필요

 

 

* 싱글 모듈일 경우 아래와 같이 application.yml에 JpaInspector 경로를 명시 필요

 

3.2 NPlusOneDetectInterceptor.java

 

 

* WebMvcConfigurer에 interceptor 등록 필요

 

3.3 NPlusOneInterceptorConfig.java

 

 

3.4 QueryCounterDto.java

 

3.5 NPlusOneSuspiciousDto.java

 

3.6 적용 결과