쿼리 모니터링 구축기
배경
최근 운영중인 서비스에서 데이터베이스 성능 문제로 요청 지연이 발생하는 문제가 있었습니다.
해당 서비스에서는 Aurora Serverless v2를 사용하고 있는데요,
데이터베이스의 최대 ACU(Aurora Capacity Unit)에 도달하고 CPU 사용률 또한 100%가 되면서 요청이 지연되거나 커넥션 타임아웃이 발생하고 있던 상황이었습니다.
알람으로 문제를 파악하여 최대 ACU를 늘려 문제는 금세 해결되었지만 재발할 가능성이 존재했습니다.
문제 원인
사용률, 레이턴시, 쓰로우풋과 같은 메트릭에 대한 내부 비정상 지표가 존재하지 않기도 했었고 처리량이 많아 문제가 발생한건지, 아니면 병목 구간(슬로우 쿼리나 N+1 문제와 같은)이 있어서 발생한건지 알기 어려웠습니다.
따라서, 우아한형제들 RDS 모니터링 기준의 워닝 임계치 지표를 참고하여 비교 분석 해보았습니다.
위 지표를 토대로 문제되었던 시간동안의 데이터베이스 메트릭을 비교해본 결과, CPU 사용률(CPU Utilization)과 조회 응답 시간(Select Latency)이 워닝 레벨 수준의 기준치보다 높게 나온 것을 알 수 있었고, 그 외에 나머지 지표들은 하회하는 것을 확인하였습니다.
저희 서비스는 트래픽이 주말과 저녁에 몰리는 경향이 있고, 복잡한 커멘드 작업보다는 복잡한 쿼리가 비교적 많은 특징이 있습니다.
그럼에도 불구하고, 우아한형제들에서 정한 조회 레이턴시 워닝 기준치인 200ms와 비교했을 때 사용자가 많은 시간대가 아님에도 250ms~500ms 사이에 위치하고 있었습니다. 따라서 조회 쿼리에 병목이 존재하고 있다는 것을 알게 되었고, 수백 ms 이하로 응답하던 쿼리들이 초 단위 지연이 발생했다는 지표에서는 DB가 과도한 트래픽이나 비효율적인 쿼리에 의해 문제가 발생한 것이라고 판단하였습니다.
액션 아이템
CloudWatch 로그나 데이터베이스 메트릭만으로도 운영 안정성은 어느정도 해결할 수 있다라고 생각했지만, 인프라 레벨까지 가기전에 애플리케이션 레벨에서 워닝 수준의 알림을 받아 선제적으로 처리 가능한 환경을 만들면 좋겠다는 생각이 들었습니다.
그래서 쿼리 모니터링 시스템을 구축하여 인프라에서 측정하는 더 큰 범위의 임계치보다 더 작고 섬세한 단위의 임계치를 설정해서 현재 시스템의 상태를 더 빠르게 탐지 가능하게 하는 것을 목표로 진행하게 되었습니다. 이번에 구현한 모니터링 대상은 슬로우 쿼리와 N+1 쿼리가 발생하는 상황에 대한 것입니다.
링크드인으로 블라드의 SQL 로깅 포스팅에서 DataSource를 데코레이트 하는 라이브러리를 본 게 기억이 나서 DataSourceProxy를 알아보게 되었습니다.
https://github.com/jdbc-observations/datasource-proxy
GitHub - jdbc-observations/datasource-proxy: Provide listener framework for JDBC interactions and query executions via proxy.
Provide listener framework for JDBC interactions and query executions via proxy. - jdbc-observations/datasource-proxy
github.com
DataSource Proxy
DataSource Proxy는 DataSource를 래핑하고, Connection, Statement, ResultSet을 가로채는 기능을 기본적으로 제공하는데요,
내부적으로 DataSource를 어떻게 등록하는지 궁금하여 설정 파일(Configuration)에서 등록하는 빈을 찾아보았습니다.
설정 파일에서 DataSourceDecoratorBeanPostProcessor를 빈으로 등록하고 있었고, 해당 클래스는 BeanPostProcessor, Ordered, ApplicationContextAware 인터페이스를 상속받아 구현하고 있었습니다.
이 중에서도 이름에서도 알 수 있듯이 BeanPostProcessor가 빈 후처리를 통해 관련 구현부가 프록시 빈으로 만들어내고 있을 것이라고 추측하였습니다.
참고로 저희는 프라이머리 / 세컨더리 구조로 운영하고 있었기 때문에 쿼리를 실행하는 시점에 커넥션을 가져오는 프록시 객체인 LazyConnectionDataSourceProxy를 기존에도 사용하고 있었습니다.
여기에 쿼리 로깅 역할을 위임할 DataSourceProxy도 추가되어야 하는 상황이라 다음의 다이어그램 플로우로 데이터소스를 말아가는 방식입니다.
데코레이트된 빈을 받기까지의 과정은 다음과 같습니다.
(1) 데코레이터로 감싸는 조건에 알맞는 DataSource를 찾고, 스프링 컨텍스트에서 데코레이터 빈을 조회한 다음
(2) 해당 데코레이터 빈으로 랩핑하여 새로운 DataSource(DataSourceProxy)를 리턴받아
(3) 이전 데이터소스와 다르다면 데코레이트된 데이터소스로 빈(Bean) 교체가 일어나게 됩니다.
DataSource Proxy 동작 원리
DataSource(DataSourceProxy)가 어떻게 등록되는지 확인해보았으니 어떻게 동작되는지도 알아보겠습니다.
datasource-proxy에는 로깅, 쿼리 메트릭, 쿼리 통계, 쿼리 파라미터 변환기(Transformer)와 같은 커스텀한 설정들을 할 추가적으로 설정할 수 있도록 지원하고 있습니다. 이 중에서 쿼리 실행 전후에 커스텀 리스너를 주입하여 JDBC API 상호작용이 일어날 때 호출되는 기능 위주로 다루어 볼 예정입니다.
여기서 주로 알아볼 리스너는 쿼리 실행 메서드(execute, executeBatch, executeQuery 등)가 실행될때 호출되는 QueryExecutionListener입니다.
해당 리스너는 두 가지 기능 명세를 가지고 있습니다.
public interface QueryExecutionListener {
void beforeQuery(ExecutionInfo execInfo, List<QueryInfo> queryInfoList);
void afterQuery(ExecutionInfo execInfo, List<QueryInfo> queryInfoList);
}ExecutionInfo에는 쿼리 실행에 대한 컨텍스트 정보가 전달되고, QueryInfo에는 실제 정보가 전달되어 넘어옵니다.
이제 구현
QueryExecutionListener
가장 먼저 실행된 모든 쿼리를 수집할 수 있는 커스텀 리스너를 추가하는 것입니다.
이 리스너는 실행전후 호출되는 기능 명세를 가지고 있는 QueryExecutionListener를 구현하 여 쿼리를 실행한 이후에 실행된 쿼리 정보를 스레드 로컬에 저장하는 역할을 합니다. 그러면 필요한 시점에 스레드 로컬에서 쿼리 정보를 꺼내어 추가적인 처리가 가능해지게 됩니다.
public class QueryCollector implements QueryExecutionListener {
@Override
public void beforeQuery(final ExecutionInfo executionInfo, final List<QueryInfo> list) {
}
@Override
public void afterQuery(final ExecutionInfo executionInfo, final List<QueryInfo> queryInfos) {
queryInfos.stream()
.map(QueryInfo::getQuery)
.forEach(ExecutedQueryContext::add);
}
}
방금 구현한 QueryCollector는 뒤에서 다시 사용할 것이라 잠시 미루어 두겠습니다.
SlowQueryListener
이번에는 슬로우 쿼리를 탐지해 알려주는 리스너를 추가해보겠습니다.
datasource-proxy는 QueryExecutionListener만 제공하는 것이 아닌 미리 구현된 몇 가지 클래스들도 일부 제공하고 있습니다.
QueryExecutionListener에 대한 계층 구조를 보면 하위 구현 클래스로 SlowQueryListener가 존재하는데 이 클래스를 활용하여 슬로우 쿼리를 탐지하도록 구현해보겠습니다.
동작 원리
SlowQueryListener의 실행 과정을 풀어서 설명한다면 쿼리 실행전에 스케줄러에 슬로우 쿼리 관련 작업을 등록하고 쿼리 실행 정보를 저장합니다. 임계 시간안에 쿼리가 종료된다면 아무런 작업도 실행하지 않고, 만약 임계 시간이 초과했는데도 쿼리가 여전히 실행중이라면 등록해둔 작업이 실행되어 슬로우 쿼리 로그를 찍는 원리입니다.
단계별로 나누어 다시 알아보겠습니다.
(1) 쿼리가 실행전에 beforeQuery가 실행되어 쿼리 실행 정보를 Map 저장소에 저장
protected Map<String, RunningQueryContext> inExecution = new ConcurrentHashMap<String, RunningQueryContext>();
@Override
public void beforeQuery(ExecutionInfo execInfo, List<QueryInfo> queryInfoList) {
final String execInfoKey = getExecutionInfoKey(execInfo);
...
RunningQueryContext context = new RunningQueryContext(execInfo, queryInfoList, now, stopwatch);
this.inExecution.put(execInfoKey, context);
}
(2) 쿼리 실행이 끝난 이후에 afterQuery가 실행되어 Map에서 쿼리 실행 정보를 삭제
protected Map<String, RunningQueryContext> inExecution = new ConcurrentHashMap<String, RunningQueryContext>();
@Override
public void afterQuery(ExecutionInfo execInfo, List<QueryInfo> queryInfoList) {
String executionInfoKey = getExecutionInfoKey(execInfo);
this.inExecution.remove(executionInfoKey);
}
(3) 만약, 쿼리 실행 시간이 임계 시간(threshold)보다 길어서 쿼리 실행 정보가 Map에 남아있다면(context != null) onSlowQuery를 호출하여 슬로우 쿼리 로그를 발생
Runnable check = new Runnable() {
@Override
public void run() {
// if it's still in map, that means it's still running
RunningQueryContext context = SlowQueryListener.this.inExecution.get(execInfoKey);
if (context != null) {
long elapsedTime = context.stopwatch.getElapsedTime();
// populate elapsed time
if (context.executionInfo.getElapsedTime() == 0) {
context.executionInfo.setElapsedTime(elapsedTime);
}
onSlowQuery(context.executionInfo, context.queryInfoList, context.startTimeInMills);
}
}
};
쿼리 실행중임에도 불구하고 쿼리 로그가 발생할 수 있도록 가능하게 하는 것은 일정 시간 이후에 동작되게 하는 ScheduledExecutorService 덕분입니다.
protected ScheduledExecutorService executor = Executors.newSingleThreadScheduledExecutor(new ThreadFactory() {
@Override
public Thread newThread(Runnable r) {
Thread thread = Executors.defaultThreadFactory().newThread(r);
thread.setDaemon(SlowQueryListener.this.useDaemonThread);
return thread;
}
});
@Override
public void beforeQuery(ExecutionInfo execInfo, List<QueryInfo> queryInfoList) {
...
this.executor.schedule(check, this.threshold, this.thresholdTimeUnit);
...
}
따라서, SlowQueryListener를 상속받아 원하는 로그 포맷(EntryPoint, Query, Params 등)이 되도록 포맷팅하여 구현하면 슬로우 쿼리가 발생하였을때 다음의 로그를 남는 것을 확인할 수 있습니다.
[nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Getting transaction for [x.x.x.x.XxxService.readAll]
[nio-8080-exec-3] org.hibernate.SQL : SELECT SLEEP(?)
[nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (1:INTEGER) <- [3]
[pool-2-thread-1] c.h.d.config.SlowQueryLoggingListener : [SLOW QUERY] conn = {5(reader-db-1)} - 2002ms /* null */ Query = SELECT SLEEP(?), Params = [3]
이 과정에서 진입점(어떤 메서드에서 시작되었는지) 정보는 ExecutionInfo나 QueryInfo에서 가져올 수 없었기에 인터셉터를 추가하여 핸들러 호출 이전에 요청 정보를 파싱해서 스레드 변수(MDC)에 저장하도록 만들었습니다.
@Slf4j
public class MdcHandlerInterceptor implements HandlerInterceptor {
public static final String MDC_HANDLER_KEY = "handler";
private static final String HANDLER_METHOD_DELIMITER = ".";
@Override
public boolean preHandle(
final HttpServletRequest request,
final HttpServletResponse response,
final Object handler
) throws Exception {
if (handler instanceof HandlerMethod handlerMethod) {
final String handlerName = handlerMethod.getBeanType().getSimpleName();
final String methodName = handlerMethod.getMethod().getName();
final String controllerInfo = handlerName + HANDLER_METHOD_DELIMITER + methodName;
MDC.put(MDC_HANDLER_KEY, controllerInfo);
}
return true;
}
@Override
public void afterCompletion(
final HttpServletRequest request,
final HttpServletResponse response,
final Object handler,
final Exception ex
) throws Exception {
MDC.clear();
}
}@Override
protected void onSlowQuery(...) {
...
final List<String> queries = queryInfos.stream()
.map(query -> String.format("[SLOW QUERY] conn = {%s(%s)} - %dms /* %s */ Query = %s, Params = [%s]",
connectionId,
dataSourceName,
elapsedTime,
MDC.get(MDC_HANDLER_KEY),
query.getQuery(),
parseParameters(query))
)
.toList();
...
}[nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Getting transaction for [x.x.x.x.XxxService.readAll]
[nio-8080-exec-3] org.hibernate.SQL : SELECT SLEEP(?)
[nio-8080-exec-3] org.hibernate.orm.jdbc.bind : binding parameter (1:INTEGER) <- [3]
[pool-2-thread-1] c.h.d.config.SlowQueryLoggingListener : [SLOW QUERY] conn = {5(reader-db-1)} - 2002ms /* null */ Query = SELECT SLEEP(?), Params = [3]
하지만 그럼에도 불구하고, 로그 결과를 보면 MDC.get()을 통해 스레드 변수에서 핸들러 정보를 가져오면 데이터가 존재하지 않아 null이 반환된 것을 알 수 있습니다.
로그를 다시 자세히 보면 쿼리가 실행된 스레드(nio-8080-exec-3)와 슬로우 쿼리 로그를 찍은 스레드(pool-2-thread-1)가 서로 다르다는 것을 확인할 수 있습니다.
그 이유는, SlowQueryListener의 ScheduledExecutorService를 초기화할때 새로운 스레드를 만들어서 동작하게 하기 때문입니다.
즉, 기존의 원본 스레드의 컨텍스트 정보가 새로운 스레드로 전달되지 않아 MDC 정보가 손실되는 것이죠.
따라서 새로운 스레드에서 실행될 때 기존 스레드의 컨텍스트를 복사해주는 추가적인 구현이 필요합니다.
이를 해결하기 위해 아래와 같이 ScheduledThreadPoolExecutor를 래핑하여 MDC 정보를 복사하는 위임 클래스를 만들었습니다.
public class DelegatingScheduledExecutorService extends ScheduledThreadPoolExecutor {
public DelegatingScheduledExecutorService(final int corePoolSize) {
super(corePoolSize);
}
@Override
public ScheduledFuture<?> schedule(Runnable command, long delay, TimeUnit unit) {
Map<String, String> mdcContext = MDC.getCopyOfContextMap(); // copy MDC
return super.schedule(() -> {
if (mdcContext != null) {
MDC.setContextMap(mdcContext); // paste MDC
}
try {
command.run();
} finally {
MDC.clear();
}
}, delay, unit);
}
}
그 결과, MDC 정보가 새로운 스레드에 잘 전달되어 핸들러 정보가 정상적으로 출력되는 것을 확인할 수 있었습니다.
[nio-8080-exec-5] o.s.t.i.TransactionInterceptor : Getting transaction for [x.x.x.x.XxxService.readAll]
[nio-8080-exec-5] org.hibernate.SQL : SELECT SLEEP(?)
[nio-8080-exec-5] org.hibernate.orm.jdbc.bind : binding parameter (1:INTEGER) <- [3]
[ool-2-thread-10] c.h.d.config.SlowQueryLoggingListener : [SLOW QUERY] conn = {6(routing-datasource)} - 3000ms /* BoardController.readAll */ Query = SELECT SLEEP(?), Params = [[3]]
[nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Completing transaction for [x.x.x.x.XxxService.readAll]참고로, 스프링 애플리케이션에서 동일한 문제가 생기면 일반적으로 TaskDecorator로 해결하게 됩니다. 하지만 여기에서 해당 데코레이터 인터페이스를 사용하지 않은 이유는 SlowQueryListener는 Java 표준 라이브러리인 ScheduledExecutorService를 직접 사용하므로, TaskDecorator를 사용해도 ScheduledExecutorService에서 실행되는 스레드에는 MDC 값이 전달되지 않습니다.
즉, TaskDecorator는 Spring의 ThreadPoolTaskExecutor와 같은 Executor 프레임워크에서만 적용 가능하기 때문입니다.
N+1 쿼리
슬로우 쿼리 로그가 정상적으로 출력되었으니 미뤄두었던 N+1 쿼리도 이어서 진행하겠습니다.
SlowQueryListener처럼 N+1 쿼리도 datasource-proxy에서 기본 제공하는 리스너가 있는지 확인해보았는데, 비슷한 이름의 리스너인 DataSourceQueryCountListener를 찾을 수 있었습니다. 하지만, DML별 통계와 실행 시간만 다루어 쿼리별 중복 횟수를 집계해 로그를 남기기에는 한계가 있었습니다.
또한, Listener는 쿼리 실행 직후에 동작되기 때문에 임계치가 10번인데 100번의 중복 쿼리가 발생한다면 90번의 추가 로그 쿼리가 남게되는 비효율이 생길 수도 있습니다.
따라서, 별도 AOP를 만들어 원하는 시점에 원하는 대상에 대해서만 검사하도록 하였습니다.
@Aspect
@Component
public class NPlusQueryChecker {
private static final int THRESHOLD = 3;
@Around("@within(x.x.x.x.QueryChecker) || @annotation(x.x.x.x.QueryChecker)")
public Object detectNPlusQuery(final ProceedingJoinPoint pjp) throws Throwable {
ExecutedQueryContext.init();
try {
Object result = pjp.proceed();
List<String> queries = ExecutedQueryContext.get();
check(queries);
return result;
} finally {
ExecutedQueryContext.clear();
}
}
private void check(final List<String> queries) {
Map<String, Long> countMap =
queries.stream().collect(Collectors.groupingBy(q -> q, Collectors.counting()));
countMap.forEach((sql, count) -> {
if (count >= THRESHOLD) {
final String handler = MDC.get(MdcHandlerInterceptor.MDC_HANDLER_KEY);
log.error("[N PLUS] repeated = {}, /* {} */ Query = {}", count, handler, sql);
}
});
}
}[nio-8080-exec-5] o.s.t.i.TransactionInterceptor : Getting transaction for [x.x.x.x.XxxService.readAll]
[nio-8080-exec-5] org.hibernate.SQL : select c1_0.board_id,c1_0.comment_id,c1_0.content,c1_0.created_at,c1_0.updated_at from comment c1_0 where c1_0.board_id=?
[nio-8080-exec-5] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [1]
[nio-8080-exec-5] org.hibernate.SQL : select c1_0.board_id,c1_0.comment_id,c1_0.content,c1_0.created_at,c1_0.updated_at from comment c1_0 where c1_0.board_id=?
[nio-8080-exec-5] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [2]
[nio-8080-exec-5] org.hibernate.SQL : select c1_0.board_id,c1_0.comment_id,c1_0.content,c1_0.created_at,c1_0.updated_at from comment c1_0 where c1_0.board_id=?
[nio-8080-exec-5] org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [3]
[nio-8080-exec-5] c.h.d.config.GlobalTransactionalAspect : [N PLUS] repeated = 3, /* BoardController.readAll */ Query = select c1_0.board_id,c1_0.comment_id,c1_0.content,c1_0.created_at,c1_0.updated_at from comment c1_0 where c1_0.board_id=?
[nio-8080-exec-3] o.s.t.i.TransactionInterceptor : Completing transaction for [x.x.x.x.XxxService.readAll]
최종적으로 N+1 쿼리도 위와 같이 로그가 잘 찍히는 것을 확인할 수 있었습니다.
결론
쿼리 모니터링만으로 CPU 사용량을 정확히 대변하지는 않지만 병목을 해결하는 사이클을 정리하면서 현재 시스템의 상태를 아는 것이 문제 해결의 시작점임을 알게 되어 쿼리 모니터링 시스템을 구현해보게 되었습니다. 지금은 RDS Performance Insights도 활성화함에 따라 DB 부하를 주는 쿼리나 데이터베이스 부하 차트를 통해 병목 현상을 좀 더 쉽게 파악할 수 있게 되어 의미는 조금 퇴색 되었을수도 있지만, 개발/스테이지 환경에서 활용할 수도 있고 이번 일을 계기로 운영 안정성과 모니터링의 중요성을 다시금 알게 되었습니다