분명... slow쿼리를 모니터링하려고 했는데... 어째서...

 return wrapPreparedStatement(preparedStatement, sql);​

슬로쿼리 모니터링 인터페이스 제작

모니터링 서비스를 만들면서, DB가 슬로우 쿼리로 판단한 요청을 로그나 알람 형태로 수집하고 보여주는 기능을 구현하고자 했습니다. 초기에는 long_query_time 값을 의도적으로 매우 낮게 설정한 뒤 테스트를 진행했고, 이때는 스케줄링 방식으로 실행했을 때도 비교적 정상적으로 슬로우 로그가 기록되는 것을 확인할 수 있었습니다. 하지만 실제 운영 환경을 가정해 long_query_time을 1~2초 수준으로 조정한 뒤 다시 테스트했을 때는 기대와 달리 slow.log가 기록되지 않았습니다. 조회한 쿼리가 단순한 SELECT 문이었기 때문일 수도 있지만, 현재로서는 그 이유를 명확히 판단하지 못했습니다. 이 부분은 추가적인 확인이 필요하다고 생각합니다. 그래서 데이터를 의도적으로 크게 늘려 보면서 다시 테스트했습니다. 100만 건, 1000만 건, 그 이상까지 확장하려 했고, 최종적으로는 1억 건 수준까지 시도하고자 했습니다. 다만 도커 환경의 디스크 용량 문제로 인해 더 이상 데이터를 적재할 수 없었고, 확인해보니 약 4000만 건 정도까지 입력된 상태였습니다.이 정도로 데이터를 늘렸음에도 불구하고 SQL 자체의 처리 시간은 여전히 1초 안팎이었습니다. 이 결과를 보면 데이터 양이 아직 충분하지 않았다고 볼 수도 있고, 혹은 단일 테이블 조회였기 때문에 생각보다 빠르게 처리된 것일 수도 있습니다. 이러한 해석 모두 완전히 틀렸다고 보기는 어렵습니다. 다만 흥미로운 점은 API 전체 조회 속도는 1초 이상이 소요되었다는 점입니다. 즉, 실제 체감 성능은 느렸지만, DB 쿼리 자체는 슬로우 쿼리로 분류되지 않았습니다. 앞으로는 많은 데이터가 들어왔음에도 왜 쿼리 실행 시간이 1초 이내로 유지되었는지 학습해보고, 슬로우 쿼리를 어떤 방식으로 효과적으로 수집하고 보여줄 수 있을지 더 고민해볼 예정입니다.

1000만건의 데이터도 1초안에 쿼리가 실행되어지는 이유

쿼리 실행이 1초안에 발생하는 이유는 여러가지가 있었습니다. 일단 제가 사용했던 쿼리를 먼저 살펴보겠습니다.

Page<Post> findAllByDeletedAtIsNull(Pageable pageable);

이것을 쿼리로 생각해보면 다음과 같습니다.

SELECT *
FROM post
WHERE deleted_at IS NULL
LIMIT 10000000;

제일 큰 이유는 조건이 매무 단순하다는 것입니다.
delete_at이 null인 조건은 DB가 처리하기에 복잡한 조건이 아닙니다. 
그렇다면 어떤 조건들이 복잡한 조건인지 살펴보겠습니다.

DB가 생각하는 복잡한 조건에 대해 알아봅시다.

DB에서 말하는 복잡한 조건은 단순히 조건식이 길다는 의미가 아니라, DB가 데이터를 찾거나 계산하는 과정에서 추가적인 작업이 많이 필요한 경우를 의미합니다. 즉, 한 row를 읽고 바로 판단할 수 있는 조건이 아니라 추가 연산, 정렬, 집계, 탐색 비용이 발생하는 조건을 말합니다.

첫 번째는 컬럼에 함수나 연산이 적용된 경우입니다.

WHERE LOWER(name) = 'john'
WHERE DATE(created_at) = '2025-01-01'
WHERE price * 1.1 > 100

이 경우 DB는 값을 읽은 뒤 함수나 연산을 수행해야 하므로 모든 row에 대해 추가 계산이 발생합니다.

두 번째는 패턴 검색이나 문자열 탐색이 필요한 경우입니다.

WHERE name LIKE '%kim'

 

앞에 %가 붙은 검색은 B-Tree 인덱스를 활용하기 어렵기 때문에 대부분 테이블 전체를 검사해야 합니다.

세 번째는 정렬이 필요한 경우입니다.

SELECT *
FROM post
ORDER BY created_at DESC

정렬을 수행하려면 DB는 데이터를 읽은 뒤 메모리에 모아서 정렬 작업을 수행해야 합니다.
데이터가 많을수록 정렬 비용이 크게 증가합니다.

네 번째는 집계나 그룹 연산이 필요한 경우입니다.

SELECT author_id, COUNT(*)
FROM post
GROUP BY author_id

이 경우 DB는 데이터를 읽은 뒤 같은 값을 가진 row들을 묶고 집계 계산을 수행해야 합니다.

다섯 번째는 여러 테이블을 결합하는 경우입니다.

SELECT *
FROM post p
JOIN user u ON p.user_id = u.id

JOIN이 들어가면 DB는 한 테이블의 데이터를 읽으면서 다른 테이블에서 매칭되는 데이터를 계속 찾아야 하기 때문에 처리 과정이 더 복잡해집니다.

여섯 번째는 서브쿼리가 포함된 경우입니다.

SELECT *
FROM post
WHERE user_id IN (
SELECT id FROM user WHERE age > 30
)

이 경우 DB는 내부적으로 서브쿼리를 실행하거나 결과를 별도로 처리해야 하므로 실행 계획이 복잡해질 수 있습니다.
정리하면, SQL에서 복잡한 조건이란 단순히 값 비교만 하는 것이 아니라 추가적인 계산, 정렬, 그룹핑, 테이블 결합 등의 작업이 필요한 경우를 의미합니다. 이러한 작업이 많아질수록 DB가 수행해야 하는 연산량과 I/O 비용이 증가하게 됩니다.
따라서 데이터베이스 성능에서는 단순히 데이터의 개수보다, 쿼리가 수행하는 작업의 종류와 복잡도가 더 큰 영향을 미칩니다.

순차적으로 읽었을 가능성이 매우 크다.

PK만 잡혀 있고 deleted_at 인덱스가 없다면, DB는 보통 테이블을 순서대로 읽으면서 조건을 검사합니다.
이게 중요한 이유는 순차 읽기(sequential scan) 가 생각보다 빠르기 때문입니다. DB가 힘들어하는 건 여기저기 점프하는 랜덤 I/O인데,
지금은 단일 테이블을 앞에서부터 쭉 읽는 형태라면 오히려 효율적일 수 있습니다.
즉, 1000만 건을 복잡하게 찾는 것은 느릴 수 있지만, 1000만 건을 "쭉 읽는 것"은 생각보다 빠를 수 있습니다.

저장 장치와 캐시 영향이 크다

1000만 건이어도 전부 디스크에서 매번 새로 읽는 게 아닐 수 있습니다.

• InnoDB Buffer Pool
• OS 페이지 캐시

(이들에 대해서는 이글에서는 다루지는 않습니다.)

이런 곳에 이미 데이터가 올라와 있으면, 디스크가 아니라 메모리에서 읽게 됩니다. 그러면 속도가 확 빨라집니다.
그래서 실험에서 특히 주의해야 하는 게, 처음 조회한 속도와 두 번째 이후 조회한 속도는 다를 수 있다는 점입니다.

row 크기가 작으면 1000만 건도 감당 가능하다

1000만 건은 숫자만 보면 커 보이는데, 실제로는 row 하나가 얼마나 큰지도 중요합니다.
예를 들어 컬럼이 몇 개 안 되고 TEXT, BLOB 같은 큰 컬럼이 없으면 한 페이지에 많은 row가 들어갑니다.
그러면 DB는 적은 페이지 I/O로 많은 데이터를 읽을 수 있습니다.
즉, 같은 1000만 건이어도 row가 가벼운 테이블은 빠를 수 있고 row가 무거운 테이블은 훨씬 느릴 수 있습니다.

DB 실행 시간과 애플리케이션 응답 시간은 다르다

여기서 많이 헷갈립니다. DB는 1초 안에 끝났더라도, API는 더 오래 걸릴 수 있습니다.

왜냐하면 API 쪽에는

• JDBC ResultSet 처리
• JPA 엔티티 매핑
• 영속성 컨텍스트 관리
• Page 객체 생성
• JSON 직렬화
• 네트워크 전송

이런 비용이 추가되기 때문입니다.
특히 1000만 건을 JPA 엔티티로 들고 오는 것은 DB보다 애플리케이션이 더 힘들 수 있습니다.
그래서 DB slow log 는 안 찍혔지만, 그런데 API 는 느리는 상황이 충분히 나올 수 있습니다.

---

먼저 슬로우 쿼리라는 개념을 다시 정의할 필요가 있다고 생각합니다. 앞선 실험에서 확인했듯이, 데이터가 1000만 건 이상 존재하더라도 항상 느린 쿼리가 되는 것은 아니었습니다. 단순 조회의 경우 예상보다 빠르게 처리될 수 있으며, 이 경우 DB 입장에서는 슬로우 쿼리로 판단되지 않을 수도 있습니다. 하지만 이러한 상황에서도 API 응답 시간은 충분히 느려질 수 있습니다. 즉, 사용자는 느리다고 느끼지만 DB에서는 슬로우 쿼리가 기록되지 않는 상황이 발생할 수 있습니다. 이때 중요한 것은 어디에서 지연이 발생하는지 정확하게 파악하는 것이라고 생각합니다. 일반적으로 슬로우 쿼리를 확인하기 위해 DB에서 생성하는 slow.log 파일을 분석하는 것은 매우 자연스러운 접근 방식입니다. 하지만 만약 쿼리 자체는 빠르게 실행되었고, 실제 병목이 애플리케이션 로직이나 데이터 처리 과정에 있다면 어떻게 해야 할까요? 이 경우 단순히 DB의 슬로우 로그만 확인하는 방식으로는 문제를 파악하기 어렵습니다. 그렇다고 해서 애플리케이션 레벨에서만 느린 요청을 기준으로 판단하는 것도 정확한 접근이라고 보기는 어렵습니다. 결국 중요한 것은 DB, 애플리케이션, 네트워크 등 각 계층에서의 처리 시간을 구분하여 관찰하는 것입니다. 어디에서 실제 지연이 발생하는지를 명확하게 파악해야 보다 정확한 모니터링과 문제 분석이 가능하다고 생각합니다.

일단은 다시 처음부터 테스트를 진행하도록 하겠습니다.

일단 DB에서 슬로우 쿼리는 1초로 설정하겠습니다.
앞으로 DB에서 발생한 슬로우 쿼리는 단순히 느린 요청이 아니라, 쿼리 자체의 성능이 떨어졌다는 신호로 보고 쿼리를 수정하거나 튜닝해야 하는 대상으로 사용해야 할 것 같습니다.

slow.log파일도 초기화를 시켜뒀습니다.

데이터는 1000만건 정도 들어가있는 상태입니다. 이제 postman으로 돌려보겠습니다. (스웨거로 돌리고 싶었지만 시간체크를 하지 않나요..ㅜㅜ)

생각보다 api 조회 성능이 나쁘지 않네요. 이러면 어떻게 해야할지... 당황스럽네요.

일단, 마음 추수리고 그럼에도 불구하고 앱에서도 측정하는 방법을 추가하였습니다.
처음에는 AOP를 이용하는 방법을 생각했었는데 AOP말고 인터셉터로 사용할 수 있는 방법이 있었습니다.

AOP가 아닌 인터셉터로 구현한 이유?

AOP를 사용하면 일반적으로 Repository 나 Service 메서드의 실행 시간을 측정하게 됩니다. 하지만 이렇게 측정한 시간은 실제 SQL 1건의 실행 시간이라기보다, 메서드 전체 수행 시간이 함께 포함된 값입니다. 예를 들어 하나의 서비스 메서드 안에서 여러 개의 SQL이 실행될 수 있습니다. 이 경우 AOP로는 해당 메서드가 얼마나 오래 걸렸는지는 알 수 있지만, 어떤 쿼리가 느렸는지, 혹은 각 쿼리가 얼마나 걸렸는지를 정확하게 구분하기 어렵습니다.
또한 JPA를 사용하는 경우에는 지연 로딩과 같이 개발자가 직접 작성하지 않은 SQL이 내부적으로 추가 실행될 수 있습니다.
이러한 쿼리들은 메서드 단위 측정만으로는 추적이 부정확해질 수 있습니다.
반면 현재처럼 DataSource 또는 Statement 레벨을 가로채는 방식은, 실제 JDBC execute 시점을 기준으로 동작합니다.
즉, 애플리케이션 메서드가 아니라 실제로 실행된 SQL 단위로 시간을 측정할 수 있습니다.

결국 슬로우 쿼리 모니터링의 목적이 "어떤 서비스 메서드가 느린가"를 찾는 것이 아니라 "어떤 SQL이 실제로 느리게 수행되었는가"를 식별하는 것이라면, AOP보다 인터셉터 기반의 데이터소스 프록시 방식이 더 적절하다고 판단했습니다.

DataSource 또는 Statement 레벨 가로채기

public class AppDbLatencyDataSource extends DelegatingDataSource

이 클래스를 사용하게 되면 Datasource를 유지하면서 새로운 기능으로 확장이 가능하다고 합니다.
데이터베이스 성능을 이해하려면 애플리케이션과 데이터베이스가 어떻게 통신하는지부터 생각해볼 필요가 있습니다.
애플리케이션은 데이터베이스와 직접 데이터를 주고받으며 동작하기 때문입니다. 먼저 애플리케이션과 데이터베이스가 어떤 방식으로 연결되는지 살펴보겠습니다. 일반적으로 데이터베이스와 애플리케이션 간의 통신은 TCP 기반 네트워크 프로토콜을 통해 이루어집니다.
즉, 애플리케이션에서 쿼리를 실행하면 내부적으로는 TCP 연결을 통해 데이터베이스 서버로 요청이 전달되고, 데이터베이스는 쿼리를 처리한 뒤 결과를 다시 TCP를 통해 애플리케이션으로 반환합니다.
이 과정에서 단순히 SQL을 실행하는 것뿐만 아니라 네트워크 전송, 결과 데이터 반환, 데이터 파싱 등의 과정이 함께 이루어지게 됩니다.
따라서 데이터베이스 성능을 분석할 때는 단순히 SQL 실행 시간뿐만 아니라, 애플리케이션과 데이터베이스 간의 통신 과정도 함께 고려할 필요가 있습니다.

데이터베이스와 통신하기 위해서는 Connection을 통해 연결을 맺어야 합니다

Connection은 애플리케이션과 데이터베이스 사이에서 실제로 데이터를 주고받는 대화 채널(세션) 역할을 합니다.
Connection을 통해 다음과 같은 작업을 수행하게 됩니다.

• SQL 실행 객체(PreparedStatement) 생성
• 트랜잭션 제어 (commit, rollback)
• 자동 커밋 및 트랜잭션 격리 수준 설정
• 데이터베이스와의 실제 연결 유지 및 종료

일반적으로 SQL이 실행되는 흐름은 다음과 같습니다.

Connection → PreparedStatement → execute

먼저 Connection을 통해 데이터베이스와 연결을 맺고, 그 다음 PreparedStatement를 생성하여 실행할 SQL을 준비합니다.
마지막으로 execute()를 호출하면서 실제로 SQL이 데이터베이스로 전달됩니다. 여기서 우리가 주목해야 하는 부분은 바로 execute() 호출 시점입니다. 이 시점에서 애플리케이션은 실제로 SQL을 데이터베이스로 보내게 되고, 데이터베이스는 쿼리를 실행한 뒤 그 결과를 다시 애플리케이션으로 반환합니다.
즉, SQL 실행 시간을 정확하게 측정하려면 메서드나 비즈니스 로직 단위가 아니라, 실제 JDBC execute()가 호출되는 시점을 기준으로 측정해야 합니다.

Connection에 대해서는 어느 정도 이해가 되었으니, 이제 PreparedStatement와 execute가 무엇인지 생각해볼 필요가 있습니다.

특히 PreparedStatement의 역할을 이해하는 것이 중요합니다. PreparedStatement는 실제로 실행할 SQL을 준비하는 객체입니다.
애플리케이션은 Connection을 통해 PreparedStatement를 생성하고, 그 안에 실행할 SQL을 설정하게 됩니다.

예를 들어 다음과 같은 코드가 있다고 가정해보겠습니다.

PreparedStatement ps = connection.prepareStatement(
    "SELECT * FROM post WHERE id = ?"
);
ps.setLong(1, 10);
ps.executeQuery();

이 과정에서 먼저 prepareStatement()를 호출하면서 SQL이 준비(prepared) 됩니다.
이 단계에서는 SQL 구조가 데이터베이스에 전달되고, 실행 계획을 준비하는 과정이 이루어질 수 있습니다.
그 다음 setLong()과 같은 메서드를 통해 실제 파라미터 값을 바인딩합니다.

마지막으로 execute() 또는 executeQuery()가 호출되는 순간,
PreparedStatement에 준비된 SQL이 실제로 데이터베이스에 전달되고 실행됩니다.
즉, 흐름을 정리하면 다음과 같습니다.

Connection → PreparedStatement 생성 → 파라미터 바인딩 → execute() 호출 → SQL 실행

여기서 중요한 점은 실제 SQL 실행은 execute() 시점에 발생한다는 것입니다. 따라서 SQL 실행 시간을 정확하게 측정하려면 Service나 Repository 메서드가 아니라, JDBC의 execute()가 호출되는 시점을 기준으로 측정하는 것이 더 정확합니다.
이러한 이유로 슬로우 쿼리를 측정할 때는 AOP보다는 DataSource 또는 Statement 레벨을 가로채는 방식이 더 적절하다고 볼 수 있습니다.

여기서 주목해야 하는 사실이 우리는 쿼리의 시간을 측정하는것이 목표입니다. 그렇기 때문에 만약 preparedStatement이 아니라면 시간 측정 대상이 아니기 때문에 결과를 그대로 반환 합니다.

if (!"prepareStatement".equals(methodName) && !"prepareCall".equals(methodName)) {
  return result;
}

if (!(result instanceof PreparedStatement preparedStatement)) {
  return result;
}

이제 모든 sql문이 preparedStatement인 코드만 모여졌습니다.
다시 프록시로 감싸겠습니다.

return wrapPreparedStatement(preparedStatement, sql);

앞서 Connection과 PreparedStatement, 그리고 execute() 호출 시점을 살펴보았으니, 이제는 실제로 SQL 실행에 얼마의 시간이 소요되는지 측정해야 합니다.

String traceId = resolveTraceId();
long startedNanos = System.nanoTime();

try {
  Object result = invoke(target, method, args);
  monitor.collect(sql, traceId, toElapsedMillis(startedNanos));
  return result;
} catch (Throwable throwable) {
  monitor.collect(sql, traceId, toElapsedMillis(startedNanos));
  throw throwable;
}

traceId는 MDC에서 읽은 값을 사용하였습니다. 자세한 내용은 다음글을 참고해주세요.

MDC란 무엇인가 그리고 어떻게 설정할 수 있을까?

그리고 monitor를 통해 기록을 하도록 하였습니다.

이제 모니터...

if (!enabled || elapsedMillis < slowThresholdMillis) {
  return;
}

만약, 설정된 시간보다 더 적게 걸린다면, 슬로우 쿼리가 아니기 때문에 무시를 하고
그렇지 않는 경우에는 적절한 파싱을 거친뒤, 어떻게 보여줄지에 대한 핸들러를 만들었습니다.

@Bean
public AppDbLatencyEventHandler appDbLatencyEventHandler() {
  return event -> {
    log.info("앱 슬로쿼리 감지: queryTime={}초, sql={}", event.queryTime(), event.sql());
  };
}

결론

처음 의도자체는 DB에서 읽어서 보여주는 것이 조금더 합리적이라고 판단하였습니다. 하지만 외부 환경에서 파일을 읽는 작업이다보니 추가적인 리소스가 발생하여 자주 사용하지 못한다는 단점을 가지고 있었습니다. 그럼에도 불구하고 진행했던 이유는 실시간으로 보여줄 필요가 없을거 같다 느껴져 진행했었습니다. 하지만 1000만건의 데이터가 들어갔음에도 불구하고 slow.log에 로그가 찍히지않는 문제가 발생하였습니다. 엎친데 덮친격으로 스웨거에서는 속도가 빠르게 나오지는 않았습니다. 체감상 2~3s정도 걸렸던거 같습니다. 그래서 애플리케이션측면에서도 슬로우 쿼리를 측정하는것이 나쁘지 않다고 판단하였습니다. 아무리 슬로우 쿼리일지라도 어디에서 느린 성능을 보이는지 정확하게 판단이 되어진다면, 조금더 빠른 대처가 가능하다고 생각하였습니다. 만들다보니 하나 안 사실이 있는데 애플리케이션은 실시간으로 보여줄수 있었습니다. 즉,  DB에서 읽었을때 보다 빠르게 대처가 가능하였습니다. 지금 생각해보면 DB에서 파일을 읽어서 가져올 필요없이 DB에는 설정만해놓고 애플리케이션에서 확인하고 만약에 로그가 발생하였다면, 그때 DB의 slow.log파일을 읽어보는 것이 합당하지 않나 여겨집니다. (참고로 스웨거에서는 느렸지만 포스트맨으로 확인해보니 50s안쪽으로 들어왔었습니다.)