이번 시간에는 MySQL에서 Slow query log를 직접 켜 보고, 기록된 쿼리 가운데 무엇부터 봐야 하는지, 그다음 무엇을 확인하는지 mysqldumpslow와 EXPLAIN ANALYZE로 따라가 보며 배워가는 시간입니다.
예를 들어서 주문 조회 API가 가끔 느리다는 문의가 들어왔다고 해볼게요. 애플리케이션 로그에는 응답 시간만 찍혀 있어서, DB에서 어떤 쿼리가 오래 걸렸는지는 알 수 없어요. 이럴 때 MySQL에서 가장 먼저 켜 보는 것이 Slow query log입니다.
Slow query log는 정해 둔 기준보다 오래 걸린 쿼리를 파일이나 테이블에 남겨요. 다만 여기에 남은 쿼리가 모두 고쳐야 할 쿼리는 아니에요. 잠금을 기다리느라 늦었을 수도 있고, 한 번만 느렸을 수도 있거든요.
실습 준비
이 글의 명령은 모두 실습 코드의 mysql-slow-query-log/ 디렉터리에서 실행합니다.
compose.yaml: Slow query log 파일 위치를 고정한 MySQL 8.4setup.sql: 회원 1만 명의 주문 30만 건을 넣는 SQL
Docker Compose로 MySQL 8.4를 띄울게요. Slow query log 파일 위치만 고정해 두고, 나머지 설정은 서버가 뜬 뒤에 바꿉니다. compose.yaml은 이렇습니다.
services:
mysql:
image: mysql:8.4
command: --slow-query-log-file=/var/lib/mysql/slow.log
environment:
MYSQL_ROOT_PASSWORD: root
ports:
- "3351:3306"
주문 30만 건은 setup.sql로 넣어요. 회원 1만 명이 30건씩 주문했고, 주문 상태는 DONE이 90%를 차지합니다.
주문 시간 created_at에는 인덱스를 만들어 두고, 회원 번호 user_id와 상태 status에는 일부러 만들지 않았어요. 재귀 CTE로 주문 30만 건을 만들고, 상태 코드표 order_status 3행을 넣은 뒤 ANALYZE TABLE까지 합니다. 상태 코드표는 이 글에서는 쓰지 않아요.
자주 쓰는 명령은 셸 함수로 만들어 둘게요. clear_slow는 새로 남는 기록만 보려고 로그 파일을 비우는 함수라서 실습에서만 써 주세요. MYSQL_PWD 환경 변수로 비밀번호를 넘기는 방식도 실습에서만 쓰셔야 해요.
아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.
docker compose up -d
until docker compose logs mysql 2>&1 | grep -q 'ready for connections.*port: 3306 '; do sleep 1; done
sql() { docker compose exec -T -e MYSQL_PWD=root mysql mysql -uroot "$@"; }
slowlog() { docker compose exec -T mysql cat /var/lib/mysql/slow.log; }
clear_slow() { docker compose exec -T mysql sh -c ': > /var/lib/mysql/slow.log'; }
sql < setup.sql > /dev/null
먼저 현재 설정을 확인해 볼게요.
sql -t -e "SHOW VARIABLES WHERE Variable_name IN ('slow_query_log', 'slow_query_log_file', 'long_query_time', 'min_examined_row_limit', 'log_output', 'log_queries_not_using_indexes');"
+-------------------------------+-------------------------+
| Variable_name | Value |
+-------------------------------+-------------------------+
| log_output | FILE |
| log_queries_not_using_indexes | OFF |
| long_query_time | 10.000000 |
| min_examined_row_limit | 0 |
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/mysql/slow.log |
+-------------------------------+-------------------------+
출력을 보면 Slow query log는 기본으로 꺼져 있고, 켜더라도 10초가 넘는 쿼리만 남아요. log_output이 FILE이므로 기록은 slow_query_log_file에 쌓입니다.
실습 1: 기준 시간은 서비스마다 다릅니다
서버를 재시작하지 않고 Slow query log를 켜고, 기준을 0.05초로 낮춰 볼게요.
이 실습의 테이블은 작아서 쿼리가 대부분 1초 안에 끝나요. 그래서 기준도 작게 잡았습니다.
sql -e "SET GLOBAL slow_query_log = ON; SET GLOBAL long_query_time = 0.05;"
SET GLOBAL long_query_time은 새로 연결한 세션부터 적용돼요. 여기서는 sql 함수를 부를 때마다 새로 연결하니까 다음 명령부터 바로 적용됩니다.
이제 1초 동안 멈추는 쿼리와, 회원 한 명의 최근 주문 10건을 가져오는 쿼리를 실행해 주세요.
sql -e "SELECT SLEEP(1);" > /dev/null
sql -e "SELECT * FROM shop.orders WHERE user_id = 42 ORDER BY created_at DESC LIMIT 10;" > /dev/null
slowlog
/usr/sbin/mysqld, Version: 8.4.11 (MySQL Community Server - GPL). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
# Time: 2026-09-29T07:58:34.512021Z
# User@Host: root[root] @ localhost [] Id: 11
# Query_time: 1.009594 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1790668713;
SELECT SLEEP(1);
# Time: 2026-09-29T07:58:38.224819Z
# User@Host: root[root] @ localhost [] Id: 12
# Query_time: 0.199290 Lock_time: 0.000008 Rows_sent: 10 Rows_examined: 99960
SET timestamp=1790668718;
SELECT * FROM shop.orders WHERE user_id = 42 ORDER BY created_at DESC LIMIT 10;
두 쿼리가 모두 남았어요. 기본값 10초였다면 둘 다 남지 않았을 거예요.
long_query_time은 어디까지를 느리다고 볼지 정하는 기준선일 뿐이고, 모든 서비스에 맞는 정답은 없어요. 서비스의 응답 시간 목표에서 출발하시면 됩니다.
이 값은 CPU 시간이 아니라 실제로 흐른 시간으로 잽니다. 그래서 한가할 때는 기준 아래였던 쿼리가 부하가 몰릴 때는 기준을 넘을 수 있어요.
주문 조회 쿼리의 # Query_time 줄에는 네 가지 단서가 있어요.
Query_time: 쿼리 실행에 걸린 시간(초)입니다.Lock_time: 잠금을 얻는 데 걸린 시간(초)입니다.Rows_sent: 클라이언트에 보낸 행 수입니다.Rows_examined: 서버가 검사한 행 수입니다. 스토리지 엔진 안에서 처리한 행은 세지 않습니다.
여기서 눈여겨볼 건, 이 쿼리가 10건을 보내려고 99960행을 검사했다는 점이에요.
실습 2: 가장 느린 한 번보다 총 영향을 봅니다
로그를 열면 Query_time이 가장 큰 쿼리부터 눈에 들어와요. 그런데 서버에 주는 부담은 한 번 걸린 시간에 호출 횟수를 곱해야 보입니다.
확인해 볼게요. 오래 걸리는 통계 쿼리를 한 번, 앞의 주문 조회 쿼리를 회원을 바꿔 가며 100번 실행합니다.
clear_slow
sql -e "SELECT a.status, COUNT(*) FROM shop.orders a JOIN shop.orders b ON a.user_id = b.user_id WHERE a.id <= 100000 GROUP BY a.status;" > /dev/null
for i in $(seq 1 100); do echo "SELECT * FROM shop.orders WHERE user_id = $i ORDER BY created_at DESC LIMIT 10;"; done | sql > /dev/null
slowlog | grep -c '^# Query_time'
101
101건이 기록됐어요. 실행은 101번뿐인데도 파일을 눈으로 훑기가 벌써 어렵죠.
mysqldumpslow는 Slow query log를 읽어 같은 형태의 쿼리끼리 묶어 주는 도구예요. 숫자는 N, 문자열은 'S'로 바꿔서 user_id = 1과 user_id = 2를 같은 쿼리로 셉니다.
Perl 스크립트인데, mysql:8.4 이미지에는 mysqldumpslow도 Perl도 들어 있지 않아요. 그래서 로그 파일을 호스트로 복사해서, Homebrew의 mysql 패키지에 들어 있는 mysqldumpslow로 읽을게요. mysql-client@8.4 패키지에는 들어 있지 않으니 주의해 주세요.
docker compose cp mysql:/var/lib/mysql/slow.log ./slow.log
mysqldumpslow -s t -t 2 slow.log
Reading mysql slow query log from slow.log
Count: 100 Time=0.18s (17s) Lock=0.00s (0s) Rows=10.0 (1000), root[root]@localhost
SELECT * FROM shop.orders WHERE user_id = N ORDER BY created_at DESC LIMIT N
Count: 1 Time=1.77s (1s) Lock=0.00s (0s) Rows=3.0 (3), root[root]@localhost
SELECT a.status, COUNT(*) FROM shop.orders a JOIN shop.orders b ON a.user_id = b.user_id WHERE a.id <= N GROUP BY a.status
-s t: 총 실행 시간이 큰 순서로 정렬합니다.-s at: 평균 실행 시간이 큰 순서로 정렬합니다. 옵션을 주지 않으면 이 기준을 씁니다.-s c: 호출 횟수가 많은 순서로 정렬합니다.-s l,-s r: 잠금 시간, 보낸 행 수의 합계로 정렬합니다. 앞에a를 붙이면 평균입니다.-t 2: 상위 2개만 보여 줍니다.
출력의 Time=0.18s (17s)는 한 번에 평균 0.18초, 합계 17초라는 뜻이에요.
괄호 안 합계는 초 단위로 반올림해서, 통계 쿼리의 1.77초는 (1s)로 표시돼요. 그리고 mysqldumpslow는 기본으로 Query_time에서 Lock_time을 뺀 값을 시간으로 계산하고, -l을 주면 빼지 않습니다.
이번에는 같은 파일을 평균 시간 기준으로 정렬해 볼게요. 순서가 뒤집혀요.
mysqldumpslow -s at -t 2 slow.log
Reading mysql slow query log from slow.log
Count: 1 Time=1.77s (1s) Lock=0.00s (0s) Rows=3.0 (3), root[root]@localhost
SELECT a.status, COUNT(*) FROM shop.orders a JOIN shop.orders b ON a.user_id = b.user_id WHERE a.id <= N GROUP BY a.status
Count: 100 Time=0.18s (17s) Lock=0.00s (0s) Rows=10.0 (1000), root[root]@localhost
SELECT * FROM shop.orders WHERE user_id = N ORDER BY created_at DESC LIMIT N
한 번에 1.77초가 걸린 통계 쿼리가 맨 위로 올라왔어요.
가장 느린 쿼리만 보면 이 통계 쿼리를 먼저 고치게 되죠. 하지만 서버 시간을 더 많이 쓴 쪽은 0.18초짜리 주문 조회 쿼리이고, 이 쿼리는 고치면 호출될 때마다 효과가 쌓입니다.
실습 3: Slow query log 다음은 EXPLAIN입니다
Slow query log에는 어떤 쿼리가 느렸는지만 남아요. 왜 느렸는지는 실행 계획을 봐야 알 수 있습니다.
EXPLAIN ANALYZE는 쿼리를 실제로 실행하고, 단계마다 옵티마이저가 예상한 행 수와 실제로 읽은 행 수, 걸린 시간을 함께 보여 줍니다. 주문 조회 쿼리를 볼게요.
sql -e "EXPLAIN ANALYZE SELECT * FROM shop.orders WHERE user_id = 42 ORDER BY created_at DESC LIMIT 10\G"
*************************** 1. row ***************************
EXPLAIN: -> Limit: 10 row(s) (cost=0.907 rows=1) (actual time=13.5..148 rows=10 loops=1)
-> Filter: (shop.orders.user_id = 42) (cost=0.907 rows=1) (actual time=13.5..148 rows=10 loops=1)
-> Index scan on orders using idx_orders_created_at (reverse) (cost=0.907 rows=10) (actual time=0.12..141 rows=99960 loops=1)
인덱스 스캔 단계의 예상은 rows=10인데 실제는 rows=99960이에요.
42번 회원의 주문이 최근 쪽에 몰려 있지 않아서, 10건을 모을 때까지 인덱스를 한참 읽어야 했던 거예요. Slow query log의 Rows_examined: 99960과 같은 숫자죠.
user_id에는 인덱스가 없어서, 옵티마이저는 created_at 인덱스를 뒤에서부터 읽다가 user_id = 42인 행이 10개 모이면 멈추는 계획을 골랐어요. 이렇게 예상 행과 실제 행이 크게 다르면 옵티마이저가 상황을 잘못 판단한 것입니다.
그럼 조건과 정렬을 함께 처리하도록 (user_id, created_at) 인덱스를 만들고 다시 확인해 볼게요.
sql -e "CREATE INDEX idx_orders_user_created ON shop.orders (user_id, created_at);"
sql -e "EXPLAIN ANALYZE SELECT * FROM shop.orders WHERE user_id = 42 ORDER BY created_at DESC LIMIT 10\G"
*************************** 1. row ***************************
EXPLAIN: -> Limit: 10 row(s) (cost=10.5 rows=10) (actual time=0.325..0.33 rows=10 loops=1)
-> Index lookup on orders using idx_orders_user_created (user_id=42) (reverse) (cost=10.5 rows=30) (actual time=0.31..0.314 rows=10 loops=1)
이제 42번 회원의 주문만 인덱스에서 바로 찾아 최근 순으로 10건을 읽고 끝나요. 두 컬럼의 순서를 어떻게 정하는지 궁금하면 복합 인덱스를 다룬 글을 참고하세요.
정리
범위: MySQL 8.4.11(mysql:8.4 이미지), 주문 30만 건 테이블, long_query_time을 기본 10초에서 0.05초로 낮춰 확인.
- 기본 설정에서 Slow query log는 꺼져 있었고
long_query_time은 10초였어요. 직접 켜고, 기준은 서비스의 응답 시간 목표에 맞춰 정하세요. - 0.18초짜리 주문 조회 100번이 합계 17초로 1.77초 통계 쿼리 한 번보다 서버 시간을 더 썼지만,
mysqldumpslow -s at는 통계 쿼리를 맨 위에 올렸어요.mysqldumpslow -s t로 합계 순으로 보세요. - 10건을 보내려고 99960행을 검사한 주문 조회는
EXPLAIN ANALYZE의 예상이rows=10, 실제가rows=99960이었고,(user_id, created_at)인덱스를 만들자 10건만 읽고 끝났어요.Rows_sent에 비해Rows_examined가 크면EXPLAIN ANALYZE로 예상 행과 실제 행을 비교해 보세요. - 이 글에 싣지 않은 추가 측정에서는 행 잠금을 기다린
UPDATE가Query_time4.27초 중 4.20초가Lock_time이었고,LOCK TABLES에 막힌SELECT는 4.64초를 기다렸는데Lock_time이 0.000009초였어요.Lock_time이 작다고 잠금 대기가 없었다고 보지 마세요.