쿼리 개수를 왜 세어야 할까?
JPA를 사용하게 되면 쿼리를 직접 작성하지 않다 보니(물론 native query를 사용하는 때도 있습니다만 일반적으로는) 예상보다 많은 쿼리가 실행되는 경우가 많습니다. 대표적으로 N+1 문제를 예로 들 수 있겠네요. 그러다 보니 쿼리가 몇 번이나 날아가는지를 확인하려면 show_sql 기능을 켜서 일일이 쿼리 로그를 보고 개수를 세어서 확인해야 합니다. 불편하면서도 개발자의 실수가 발생할 수 있는 부분이죠. 일일이 쿼리 로그를 세는 대신 쿼리가 실행될 때마다 카운팅을 해서 API 요청이 종료되는 시점에 쿼리 개수를 로그로 보여줄 수 있다면 좋지 않을까요?
쿼리 개수를 세는 법
문제는 쿼리 개수를 세는 법이었습니다. 가장 기본적으로 떠올릴 수 있는 아이디어는 "쿼리가 실행될 때 query count 값을 1 증가시킨다."였습니다. 이를 위해서는 두 가지 조건이 필요했습니다.
- 쿼리가 실행되기 바로 전에
queryCount값을 증가시키는 메서드를 실행시킬 수 있어야 한다. queryCount를 관리하는 객체의 생명주기는 HTTP request와 일치해야 한다.
2번 조건은 만족시키기 쉬웠습니다. 스프링에서 제공하는 @RequestScope를 활용하여 HTTP request 생명주기를 가지는 빈을 만들어서 사용하면 됩니다. 하지만 1번은 어떨까요? 가장 러프하게는 쿼리 실행 시점에 AOP를 이용하는 방법을 생각해 볼 수 있습니다. 그런데 하이버네이트에서는 쿼리문을 가로챌 수 있는 StatementInspector를 제공하고 있습니다. 오늘은 하이버네이트에 종속적이기는 하지만 조금 더 쉽게 쿼리 개수를 셀 수 있는 StatementInspector를 이용한 방식을 살펴보도록 하겠습니다.
StatementInspector
StatementInspector는 하이버네이트가 제공하는 인터페이스입니다. 메서드로 inspect라는 메서드를 가지고 있는데요, HibernateProperty로 StatementInspector 구현체를 등록하면 쿼리 실행 시점에 실행될 쿼리문을 인자로 받는 inspect 메서드가 실행됩니다.
이 StatementInspector 구현체를 저희가 원하는 대로 만들어 쿼리 개수를 세는데 활용해보도록 하겠습니다.
그런데 쿼리 개수는 HTTP request 별로 다르게 저장해야 합니다. 각 요청 별로 실행되는 쿼리 개수를 셀 것이기 때문이죠. 하지만 StatementInspector는 HibernateProperty로 하나만 등록이 가능합니다. 때문에 StatementInspector 자체의 생명주기를 request로 유지할 수는 없습니다. 대신 쿼리 개수를 저장하기 위한 request 스코프의 빈을 만들어주겠습니다.
@Component
@RequestScope
@Getter
public class ApiQueryCounter {
private int count;
public void increaseCount() {
count++;
}
}단순히 개수만 저장해줄 객체이기 때문에 구현은 간단합니다. 개수를 저장할 필드값 하나와 해당 필드값을 증가시켜주는 메서드, 그리고 getter만 구현하면 됩니다.
이제 ApiQueryCounter의 값을 증가시켜주는 로직을 가진 StatementInspector 구현체를 만들어보도록 하겠습니다.
@Component
public class ApiQueryInspector implements StatementInspector {
private final ApiQueryCounter apiQueryCounter;
public ApiQueryInspector(final ApiQueryCounter apiQueryCounter) {
this.apiQueryCounter = apiQueryCounter;
}
@Override
public String inspect(final String sql) {
apiQueryCounter.increaseCount();
return sql;
}ApiQueryInspector를 만들어주었습니다. 빈으로 만들어 준 뒤, ApiQueryCounter의 의존성을 주입받아줍니다. inspect 메서드가 실행되면 쿼리가 실행된다는 의미이므로 apiQueryCounter.increaseCount를 호출해주고 매개변수로 받은 쿼리를 그대로 반환하여 실행시켜주면 됩니다.
하지만 여기서 끝이 아닙니다. ApiQueryCounter는 request 스코프죠? 그렇기 때문에 ApiQueryInspector의 생성 시점에는 프록시가 주입되고, HTTP request 안에서 실제 빈으로 초기화됩니다. 하지만 ApiQueryInspector는 request 스코프가 아니기 때문에 inspect 메서드는 request 스코프 밖에서도 작동할 수 있습니다. 예를 들어 인수 테스트 시 데이터베이스를 초기화해주는 쿼리를 실행하는 경우를 들 수 있겠네요. 이런 경우 ScopeNotActiveException이 발생하게 됩니다. try ~ catch로 예외를 처리해줄 수도 있지만, 조금 더 성능이 좋은 if문을 활용해보도록 하겠습니다.
@Override
public String inspect(final String sql) {
if (isInRequestScope()) {
apiQueryCounter.increaseCount();
}
return sql;
}
private boolean isInRequestScope() {
return Objects.nonNull(RequestContextHolder.getRequestAttributes());
}RequestContextHolder.getRequestAttributes는 현재 스레드의 RequestAttributes를 반환합니다. 만약 request 스코프 내부에 있다면 RequestAttributes는 null값이 아니겠죠? 그래서 null이 아닌 경우에만 apiQueryCounter를 작동시키도록 설정해줍니다.
이 경우 HTTP 요청을 보내지 않는 단위 테스트가 문제가 될 수 있는데요, 저는 가짜 RequestAttributes를 넣어서 이 문제를 해결했습니다.
@SpringBootTest
class ApiQueryInspectorTest {
@Autowired
private ApiQueryInspector apiQueryInspector;
@Autowired
private ApiQueryCounter apiQueryCounter;
@Test
void request_안에서_inspect를_호출하면_QueryCounter를_증가시킨다() {
// given
RequestContextHolder.setRequestAttributes(new ServletRequestAttributes(new MockHttpServletRequest()));
// when
apiQueryInspector.inspect("sql");
// then
assertThat(apiQueryCounter.getCount()).isOne();
}
}RequestContextHolder.setRequestAttributes 메서드와 MockHttpServletRequest 객체를 활용하여 request 스코프를 mocking해줄 수 있습니다.
하이버네이트 설정으로 등록하기
하지만 StatementInspector의 구현체를 만들었다고 쿼리를 가로챌 수 있는 것은 아닙니다. 이 구현체를 하이버네이트가 사용하도록 설정해주어야 합니다. 구현하기 전에 레퍼런스를 많이 찾아봤었는데요, 대부분의 레퍼런스들이 application.properties나 application.yml을 이용해 설정해주는 예제였습니다. 그런데 저희는 이런 식으로 하이버네이트 설정을 등록할 수 없습니다. ApiQueryInspector가 저희가 만든 커스텀 빈을 주입받고 있기 때문이죠. 그래서 다른 빈들이 모두 초기화되고 나서 HibernateProperty로 등록하도록 해야 합니다.
@Configuration
public class HibernateConfig {
private final ApiQueryInspector apiQueryInspector;
public HibernateConfig(final ApiQueryInspector apiQueryInspector) {
this.apiQueryInspector = apiQueryInspector;
}
@Bean
public HibernatePropertiesCustomizer hibernatePropertyConfig() {
return hibernateProperties ->
hibernateProperties.put(AvailableSettings.STATEMENT_INSPECTOR, apiQueryInspector);
}
}@Configuration 안에서 @Bean으로 빈 등록을 해주게 되면 컴포넌트 스캔보다 나중에 빈 등록이 된다는 점을 이용, HibernateConfig 설정을 만들어서 ApiQueryInspector를 HibernateProperties에 등록하도록 하겠습니다. 이제 쿼리가 실행될 때마다 inspect 메서드가 호출되게 됩니다.
인터셉터에서 로그를 기록
마지막 단계입니다. 쿼리 개수를 세었으니 로그로 기록해야겠죠? LoggingInterceptor를 만들어 인터셉터에서 로깅을 해보도록 하겠습니다.
@Slf4j
@Component
public class LoggingInterceptor implements HandlerInterceptor {
private static final String QUERY_COUNT_LOG_FORMAT = "STATUS_CODE: {}, METHOD: {}, URL: {}, QUERY_COUNT: {}";
private static final String QUERY_COUNT_WARNING_LOG_FORMAT = "쿼리가 {}번 이상 실행되었습니다.";
private static final int QUERY_COUNT_WARNING_STANDARD = 10;
private final ApiQueryCounter apiQueryCounter;
public LoggingInterceptor(final ApiQueryCounter apiQueryCounter) {
this.apiQueryCounter = apiQueryCounter;
}
@Override
public void afterCompletion(final HttpServletRequest request, final HttpServletResponse response,
final Object handler, final Exception ex) {
final int queryCount = apiQueryCounter.getCount();
log.info(RESPONSE_LOG_FORMAT, response.getStatus(), request.getMethod(), request.getRequestURI(),
queryCount);
if (queryCount >= QUERY_COUNT_WARNING_STANDARD) {
log.warn(QUERY_COUNT_WARNING_LOG_FORMAT, QUERY_COUNT_WARNING_STANDARD);
}
}
}매 HTTP request가 끝날 때마다, 즉 응답을 할 때마다 실행된 쿼리 개수를 로그로 기록해주고, 쿼리가 10번 이상 실행되었다면 경고 로그를 찍어주도록 설정을 완료했습니다. 테스트해 볼까요?
정상적으로 몇 개의 쿼리가 실행되었는지 찍히네요! 혹시 모르니 정말로 쿼리가 2번 날아갔는지 확인해보겠습니다.
show_sql로 확인해보니 정말 2번의 쿼리가 실행된 것을 확인할 수 있습니다.
지금까지 Hibernate의 StatementInspector를 활용해 쿼리 개수를 세는 방법을 알아보았습니다. 하지만 이 방법은 하이버네이트에 종속적이기 때문에 하이버네이트를 사용하지 않는 쿼리(예를 들면 JDBC로 직접 쿼리를 날리거나 다른 JPA 구현체를 사용하는 경우가 있을 수 있습니다.)의 개수는 셀 수 없다는 단점이 있습니다. 다음 시간에는 하이버네이트 대신 JDBC와 스프링 AOP를 활용하여 쿼리 개수를 세는 방법을 알아보도록 하겠습니다.
