[DB] Slow Query Log 를 통해 병목 현상 진단 및 개선

회사에서 첫 개발 기능을 배포했다. 

테스트 환경에서는 문제가 없었으나, 수천만개의 데이터가 쌓인 운영 DB 에서 호출 지연 이슈가 있었다. 
어디서 병목이 생기는지 정확히 파악하기 위해 Slow Query Log 를 사용한 과정을 작성해보겠다. 

※ 보안 안내: 본 포스팅은 실제 운영 서비스의 도메인 정보를 보호하기 위해 '학사 관리 시스템(학생 성적 이력)' 사례로 치환하여 작성되었습니다. 기술적 트러블슈팅의 핵심 로직과 명령어, 해결 과정은 실제 사례와 동일합니다.

 

1. Slow Query 로그 설정 명령어

DB에 직접 접속하여 아래 명령어들을 차례로 실행한다. 

 

1.1 슬로우 쿼리 로그 기능을 활성화한다.

SET GLOBAL slow_query_log = 'ON';

 

1.2 슬로우 쿼리로 기록할 임계 시간을 2초로 설정한다.

SET GLOBAL long_query_time = 2;

1.3 인덱스를 사용하지 않는 쿼리는 실행 시간과 관계없이 무조건 로그에 기록하도록 설정한다.

SET GLOBAL log_queries_not_using_indexes = 'ON';

1.4 설정이 제대로 반영되었는지, 로그 파일이 어디에 저장되는지 확인한다.

SHOW VARIABLES LIKE 'slow_query%';

 

 

2. 슬로우 쿼리 로그 분석

로그 파일을 열어본 결과, 통계 조회를 수행하는 특정 쿼리에서 약 33~34초의 지연이 발생하는 것을 확인할 수 있었음

# Time: 251229  6:58:45
# User@Host: db_user[db_user] @  [172.17.0.1]
# Thread_id: 12  Schema: SCHOOL_DB  QC_hit: No
# Query_time: 33.369276  Lock_time: 0.000045  Rows_sent: 869  Rows_examined: 1332764
# Rows_affected: 0  Bytes_sent: 43388
SET timestamp=1766991525;
SELECT student_id, sum(score) FROM STUDENT_EXAM_SCORE ... (생략)

• `Query_time: 33.369276`: 이 쿼리 하나를 처리하는 데 33초가 걸렸음을 의미
• `Rows_examined: 1,332,764`: DB가 결과를 내기 위해 내부적으로 약 133만 건의 행을 훑음
• Rows_sent: 869`: 결과로 돌아온 데이터는 869건

이 결과를 통해 869건의 데이터를 골라내는데 인덱스가 부적절하여 133만 건 전체를 일일이 대조하는 풀 테이블 스캔(Full Table Scan)이 발생하고 있다는 것을 알 수 있음

 

인덱스가 왜 부적절한가 ?

테이블에는 아래와 같은 인덱스들이 존재함

• `IDX_EXAM_DATE_SCHOOL (EXAM_DATE, SCHOOL_ID)`
• `IDX_STUDENT_ID (STUDENT_ID)`
• `IDX_SUBJECT_ID (SUBJECT_ID)`

▶ 1. 잘못된 인덱스 컬럼 순서

`EXAM_DATE` 와 같이 범위 검색이 발생하는 컬럼이 인덱스의 선두에 있었다. 

인덱스 선두 컬럼이 범위 조건일 경우, 그 뒤에 오는 `SCHOOL_ID`와 같은 동등 조건 컬럼을 효율적으로 필터링에 사용하지 못함

 

▶  2. 단일 인덱스의 한계

쿼리는 학교(`SCHOOL_ID`), 과목(`SUBJECT_ID`), 날짜(`EXAM_DATE`)를 동시에 필터링하지만, 인덱스는 각각 따로 흩어져 있었다. 이 경우 DB 엔진 두가지 시나리오를 고민하게 된다. 

• Index Merge : 여러 단일 인덱스를 각각 검색한 뒤, 그 결과들을 메모리상에서 병합하는 과정을 거침. 데이터가 커질수록 병합 연산 자체가 CPU 와 메모리에 상당한 부하를 줌
• 부적절한 단일 인덱스 선택 : 하나의 인덱스를 선택하는 건데, 만약 하나의 인덱스만 선택된다면, 해당 학교의 모든 성적 데이터를 일단 다 읽어온 뒤 나머지 조건(과목, 날짜)은 인덱스 없이 하나하나 대조해야한다. 이 과정에서 랜덤 I/O 가 대량으로 발생하여 성능이 떨어짐

이로 인해 869건의 데이터를 골라내는데 인덱스가 제 역할을 못 해 133만 건 전체를 일일이 대조하는 풀 테이블 스캔이 발생한 것이다. 

 

3. 해결시도 : 복합 인덱스 재설계

• 기존에는 각 컬럼에 인덱스가 흩어져 있어 쿼리가 여러  조건을 복합적으로 처리할 때 제 성능을 못 냄
• 쿼리의 필터링순서 (학교 > 과목 > 날짜 > 학생) 을 반영한 신규 인덱스 생성

-- 성적 이력 테이블 최적화
CREATE INDEX idx_score_listing_optimization 
ON STUDENT_EXAM_SCORE (SCHOOL_ID, SUBJECT_ID, EXAM_DATE, STUDENT_ID);

-- 출석 이력 등 유사한 검색 패턴을 가진 테이블도 동시 최적화
CREATE INDEX idx_attendance_optimization 
ON STUDENT_ATTENDANCE_LOG (SCHOOL_ID, SUBJECT_ID, RECORD_DATE, STUDENT_ID);

 

• 검색 조건에서 `=` 로 비교되는 `SCHOOL_ID`와 `SUBJECT_ID`를 인덱스 가장 앞에 오도록 함
• 범위 검색(`>=`, `<=`)이 일어나는 `EXAM_DATE`를 동등 조건 뒤에 배치하여, 좁혀진 데이터 안에서만 범위를 훑도록 함
• 마지막에 `STUDENT_ID`를 포함함으로써, `GROUP BY`나 정렬 시 DB가 별도의 정렬 작업(Internal Sort)을 할 필요 없이 인덱스에 저장된 순서 그대로를 읽게 함

4. 최적화 이후 식별된 Slow Query Log

# Time: 251229  8:50:18
# User@Host: db_user[db_user] @  [172.17.0.1]
# Thread_id: 60  Schema: SCHOOL_DB  QC_hit: No
# Query_time: 0.270972  Lock_time: 0.000057  Rows_sent: 869  Rows_examined: 116466
# Rows_affected: 0  Bytes_sent: 43388
SET timestamp=1766998218;
SELECT student_id, sum(score) FROM STUDENT_EXAM_SCORE ... (생략)

 

• `Query_time: 0.27초`: 기존 33초에서 단축됨. 
• `Rows_examined: 116,466`: 인덱스를 통해 필요한 11만 건의 데이터만 골라냄

 

Slow Query Log 를 사용해 병목현상을 진단하고, 

인덱스 재설계 이후, 사용자 체감상 무한 로딩에 가까웠던 기능이 클릭 즉시(0.2초대) 응답하는 수준으로 개선됨. 

- before : 33초

- after : 0.2 초