MySQL :: 슬로우쿼리 잡는 명령어, ‘EXPLAIN ANALYZE’ 해석법

숑숑·2024년 10월 13일

db mysql

DB

목록 보기

6/7

이 글을 읽으면
1. 원인 불명의 슬로우쿼리를 분석할 수 있습니다.
2. EXPLAIN ANALYZE가 프로파일링한 결과를 해석할 수 있습니다.

쿼리가 왜 느리지?

살다보면 원인 불명의 슬로우쿼리, 한번쯤 만날 수도 있습니다.
EXPLAIN 으로 실행계획을 확인해도, 쿼리가 왜 느린지 알 수 없는 상황이 있습니다.

제가 정확히 이 상황을 업무 중 겪었습니다.
간단히 당시 상황을 정리하자면

서비스에 트래픽이 몰려서 메트릭이 불안정했다.
많이 쓰이는 DB 쿼리를 하나 튜닝해서 배포했다.
메트릭이 깔끔하게 잦아들었다!
하지만 EXPLAIN으로 실행계획을 분석한 결과, 튜닝 전후 차이는 크지 않다 …?

그래서 ‘되는데 왜 되는거지?’ 싶었던 상황입니다.
실행계획 상 개선한게 낫긴 했지만, 그 정도로 드라마틱해보이진 않았습니다.

이 고민을 시니어 분께 말씀드렸더니
실행 결과에 기반해서 원인을 분석할 수 있는 EXPLAIN ANALYZE 를 알게 됐습니다.
EXPLAIN ANALYZE의 프로파일링 결과를 어떻게 해석해야 하는지, 공식문서를 참고해서 정리해보고자 합니다.

EXPLAIN 의 함정

EXPLAIN은 실제 실행 결과를 다루지 않고, 실행 전 예측에 기반합니다.
그렇기에 항상 최적의 실행계획을 보장하지는 않고, 때로는 실제 실행 전략이 크게 다를 수도 있습니다.
특히 DB 옵티마이저에게 제공되는 통계 정보(데이터의 분포도와 인덱스 정보 등)가 부정확한 경우 잘못된 실행계획을 세울 가능성이 높습니다.

EXPLAIN ANALYZE 란?

MySQL이 제공하는 쿼리 프로파일링 도구입니다. (MySQL 8.0.18 부터 지원합니다.)
쿼리 실행 중 MySQL이 어디서 시간을 많이 썼는지, 그 이유가 뭔지 분석할 수 있습니다.

쿼리를 실제 실행하며 그 중 얻는 모든 시간과 행수를 측정합니다.
결과적으로 실행 전 계획과, 실제 측정치를 같이 출력합니다.

EXPLAIN과의 차이점

EXPLAIN -> 쿼리를 실행하지 않고, 실행 과정을 예측

EXPLAIN ANALYZE -> 쿼리를 실행하고, 실행 과정을 분석

그럼 EXPLAIN은 이제 필요없나?

저 또한 EXPLAIN ANALYZE를 처음 알았을 때는, EXPLAIN의 상위호환 기능처럼 보였습니다.
그래서 EXPLAIN은 이제 애매한 명령어가 아닐까 하는 의문이 들었습니다.

그러나 EXPLAIN ANALYZE는 실행 결과가 나와야 하기 때문에,
매우 느린 쿼리거나, 상용 환경에서 부하가 큰 쿼리를 분석하려 할 경우 부담이 될 수 있습니다.
이런 경우 실행을 하지 않아도 전략을 예측할 수 있는 EXPLAIN 이 더 유용할 수 있습니다.

사용법

쿼리

분석할 쿼리 앞에 EXPLAIN ANALYZE 키워드를 붙이고 실행합니다.

EXPLAIN ANALYZE
SELECT first_name, last_name, SUM(amount) AS total
FROM staff INNER JOIN payment
  ON staff.staff_id = payment.staff_id
     AND
     payment_date LIKE '2005-08%'
GROUP BY first_name, last_name;

출력

실제 쿼리 실행 후 분석 결과입니다.
해석법은 하단에 이어서 설명합니다.

-> Table scan on <temporary>  (actual time=0.001..0.001 rows=2 loops=1)
    -> Aggregate using temporary table  (actual time=58.104..58.104 rows=2 loops=1)
        -> Nested loop inner join  (cost=1757.30 rows=1787) (actual time=0.816..46.135 rows=5687 loops=1)
            -> Table scan on staff  (cost=3.20 rows=2) (actual time=0.047..0.051 rows=2 loops=1)
            -> Filter: (payment.payment_date like '2005-08%')  (cost=117.43 rows=894) (actual time=0.464..22.767 rows=2844 loops=2)
                -> Index lookup on payment using idx_fk_staff_id (staff_id=staff.staff_id)  (cost=117.43 rows=8043) (actual time=0.450..19.988 rows=8024 loops=2)

EXPLAIN ANALYZE 보는법

요약

빠르게 원하는 정보를 찾는 분들을 위한 섹션입니다.
넘기고 하단 해설 섹션부터 보셔도 무방합니다.

용어 정리:

용어	의미
(들여쓰기)	같은 레벨: 상단에 위치한게 먼저 실행 / 다른 레벨: 더 안쪽에 위치한게 먼저 실행
actual	실행 결과
time	실행 시간(ms)
time=a…b 중 a	첫번째 행을 읽어오는데 들었던 시간의 평균(ms)
time=a…b 중 b	모든 행을 읽어오는데 들었던 시간의 평균(ms)
rows	반환된 행수의 평균
loops	작업을 반복한 횟수
cost	CPU 사이클, I/O 접근 빈도 등 리소스 소모에 대한 추정치

트러블슈팅 시 접근법:

쿼리 시간이 느린 경우
- time(실행 시간)이 가장 큰 부분을 찾는다.
실행 시 사용된 전략이 비합리적인 경우
- rows(반환된 행수)가 실행 계획과 크게 차이나는 부분이 있는지 확인한다.
- 실행 계획 상의 rows로 전략을 세우기 때문에, 차이가 크다면 전략이 비합리적인 원인이 될 수 있다.
- 해결법으로는 연관 컬럼에 인덱스 추가 등을 고려할 수 있다.

해설

사용법에서 적은 쿼리와 출력본을 예시로 사용하겠습니다.
먼저 간단히 예시 쿼리와 테이블 구조를 짚고 넘어가겠습니다.

SELECT first_name, last_name, SUM(amount) AS total
FROM staff INNER JOIN payment
  ON staff.staff_id = payment.staff_id
     AND
     payment_date LIKE '2005-08%'
GROUP BY first_name, last_name;

쿼리 역할: 2005년 08월에 결제한 이력이 있는 스태프 명단과, 스태프 별 결제 금액 합계
테이블
- staff: 스태프 목록
  컬럼 설명 인덱스
  staff_id 스태프 ID O
  first_name 이름 X
  last_name 이름 X
- payment: 결제 이력
  컬럼 설명 인덱스
  payment_id 결제이력 ID O
  staff_id 스태프 ID O
  payment_date 결제 날짜 X

컬럼	설명	인덱스
staff_id	스태프 ID	O
first_name	이름	X
last_name	이름	X

컬럼	설명	인덱스
payment_id	결제이력 ID	O
staff_id	스태프 ID	O
payment_date	결제 날짜	X

아래는 각각 EXPLAIN, EXPLAIN ANALYZE 실행 결과입니다.
차이점에 유의하며 살펴보시기 바랍니다.

EXPLAIN 결과:

-> Table scan on <temporary>
    -> Aggregate using temporary table
        -> Nested loop inner join  (cost=1757.30 rows=1787)
            -> Table scan on staff  (cost=3.20 rows=2)
            -> Filter: (payment.payment_date like '2005-08%')  (cost=117.43 rows=894)
                -> Index lookup on payment using idx_fk_staff_id (staff_id=staff.staff_id)  (cost=117.43 rows=8043)

EXPLAIN ANALYZE 결과:

-> Table scan on <temporary>  (actual time=0.001..0.001 rows=2 loops=1)
    -> Aggregate using temporary table  (actual time=58.104..58.104 rows=2 loops=1)
        -> Nested loop inner join  (cost=1757.30 rows=1787) (actual time=0.816..46.135 rows=5687 loops=1)
            -> Table scan on staff  (cost=3.20 rows=2) (actual time=0.047..0.051 rows=2 loops=1)
            -> Filter: (payment.payment_date like '2005-08%')  (cost=117.43 rows=894) (actual time=0.464..22.767 rows=2844 loops=2)
                -> Index lookup on payment using idx_fk_staff_id (staff_id=staff.staff_id)  (cost=117.43 rows=8043) (actual time=0.450..19.988 rows=8024 loops=2)

들여쓰기의 의미는 아래와 같습니다.

같은 레벨: 상단에 위치한게 먼저 실행
다른 레벨: 더 안쪽에 위치한게 먼저 실행

(cost=1757.30 rows=1787) (actual time=0.816..46.135 rows=5687 loops=1)

EXPLAIN과 EXPLAIN ANALYZE 결과에서 보이는 가장 뚜렷한 차이가 하나 있습니다.
바로 actual 이라는 키워드입니다.

아래와 같은 의미를 가집니다.

actual이 붙지 않은 괄호 영역: 실행 계획 (EXPLAIN과 동일)
actual이 붙은 괄호 영역: 실제 실행 후 분석한 결과

(actual time=0.464..22.767 rows=2844 loops=2)

각 파라미터의 의미입니다.

time
- 첫번째 숫자(0.464): 첫 행을 읽어오는데 들었던 시간의 평균 (ms)
- 두번째 숫자(22.767): 모든 행을 읽는데 들었던 시간의 평균 (ms)
rows: 실제 반환된 행수의 평균
loops: 해당 작업이 반복된 횟수

주의!
loops가 2 이상인 경우, time과 rows는 전체 실행 시간을 나타내지 않습니다.
반복된 작업의 평균이기 때문에, 전체 실행 시간은 time 값에서 loops 만큼 곱한 값과 비슷하다고 보시면 됩니다.
실제로 위 예시에서 Filter문의 시간(22.767)과 Nested Loop Join의 시간 (46.135)를 보면 두배 이상인 것을 볼 수 있습니다.

그럼 예시 중 아래 부분을 해석할 수 있습니다.

-> Nested loop inner join  (cost=1757.30 rows=1787) (actual time=0.816..46.135 rows=5687 loops=1)
		-> Table scan on staff  (cost=3.20 rows=2) (actual time=0.047..0.051 rows=2 loops=1)
		-> Filter: (payment.payment_date like '2005-08%')  (cost=117.43 rows=894) (actual time=0.464..22.767 rows=2844 loops=2)
				-> Index lookup on payment using idx_fk_staff_id (staff_id=staff.staff_id)  (cost=117.43 rows=8043) (actual time=0.450..19.988 rows=8024 loops=2)

결론부터 말하자면,
staff를 driving 테이블, payment를 driven 테이블로 두고 중첩 inner join을 하고 있습니다.

Nested loop inner join 바로 하단에 Table scan of staff 문이 있습니다.
즉 staff를 먼저 접근했으므로, staff가 driving 테이블이 됩니다.

그리고 Filter 라인의 loops가 2로, 하단 작업을 두번 반복했다는 뜻입니다.
staff 행 하나 당, payment 테이블의 인덱스(idx_fk_staff_id) 검색 작업을 했다는 뜻입니다.
staff 행수가 2개니 총 2번 반복한게 됩니다.

순서대로 정리해보자면

staff 테이블을 먼저 테이블 스캔합니다.
- 총 시간: 0.051ms
- 반환된 행수(staff): 2개
그리고 중첩 inner join 전략에 따라, staff의 행마다 payment 테이블에서 검색작업을 합니다. (반복)
- 조인을 위해 payment의 FK인 staff_id 인덱스를 사용해서 맞는 행을 찾습니다.
  - (1) 총 시간: 평균 19.988ms
  - 반환된 행수(payment): 8024개
- 그리고 필터링 조건인 payment.payment_date like '2005-08% 을 실행합니다.
  - (2) 총 시간: 평균 (22.767 - 19.988)ms
  - 반환된 행수(payment): 평균 2844개
Nested loop inner join 종료
- 총 시간: 46.135ms
- 반환된 행수(staff): 2개

(2)에서 뺄셈식이 들어간 이유는,
payment 테이블 조회 후 순수 필터링에만 드는 시간을 계산하기 위해 Filter 라인 시간에서 Index lookup 시간만큼을 뺐습니다.

튜닝을 해본다면?

만약 예시 쿼리를 튜닝하고자 한다면, 가장 큰 시간을 차지하는 (1) 부분을 집중적으로 살펴보면 됩니다.
이런 식으로 원인을 찾기 힘들었던 슬로우쿼리도 개선할 수 있습니다.

EXPLAIN과 차이가 많이 나는 이유?

한 가지 눈에 띄게 차이가 나는 곳이 있습니다.

-> Filter: (payment.payment_date like '2005-08%')  (cost=117.43 rows=894) (actual time=0.464..22.767 rows=2844 loops=2)

실행계획 행수: 894
실제 행수: 2844

왜 행수가 거의 3배나 차이가 날까요?
실행계획은 통계 정보에 기반하는데, 이 정보가 부정확할 수 있습니다.

근본적으로는, 필터링에 사용되는 payment_date 컬럼에 인덱스가 걸려있지 않기 때문입니다.
인덱스가 걸린 컬럼과 달리, MySQL이 추가 통계 정보를 얻는데 제한이 있습니다.

그럼 아래 문장에서는 왜 행수가 비슷한지도 알 수 있습니다.

-> Index lookup on payment using idx_fk_staff_id (staff_id=staff.staff_id)  (cost=117.43 rows=8043) (actual time=0.450..19.988 rows=8024 loops=2)

실행계획 행수: 8043
실제 행수: 8024

이 정도면 꽤나 잘 예측했습니다.
staff_id 는 FK이므로 인덱스가 걸려있습니다.
즉 옵티마이저에 통계 정보가 충분히 제공되고 있어 올바른 실행계획을 세울 수 있습니다.

참고

https://dev.mysql.com/blog-archive/mysql-explain-analyze/

숑숑

툴 만들기 좋아하는 삽질 전문(...) 주니어 백엔드 개발자입니다.

이전 포스트

휘발성 DB인 Redis, 어떻게 믿고 쓰는걸까?

다음 포스트

MySQL 트러블슈팅 회고 (feat. 대소문자 구분)

2개의 댓글

GoldenDusk

2024년 10월 16일

숑숑님 글 잘 보고 갑니다!!

1개의 답글