MySQL 슬로 쿼리 로그와 pt-query-digest로 병목 쿼리 순위 매기기
상품 리뷰 API의 응답 시간이 오후만 되면 들쭉날쭉하던 때가 있었다. 평균은 멀쩡했는데 상위 1% 구간만 몇 초씩 튀었다. 슬로 쿼리 로그는 이미 켜져 있었고 long_query_time은 기본값보다 낮춘 1초였다. 그런데 로그를 열면 매번 같은 배치 쿼리 서너 개만 보였다. 그 쿼리들은 새벽에 돌았고, 오후에 튀는 응답과는 상관이 없었다.
1초 문턱을 넘지 못하는 쿼리가 모여서 서버를 무겁게 만든다면 이 로그로는 끝내 찾을 수 없다. 그래서 문턱을 아예 없애고 잠깐 전부 받아 적은 다음 pt-query-digest로 순위를 매기기로 했다. 방법 자체는 간단했지만 중간에 두 번 발을 헛디뎠다.
long_query_time=0으로 잠깐 전부 받아 적기
MySQL 문서를 보면 long_query_time의 최솟값은 0이고 기본값은 10이다. 마이크로초 단위까지 지정할 수 있다. 0으로 두면 실행 시간과 관계없이 모든 쿼리가 슬로 로그에 들어간다. 이 값은 재시작 없이 바꿀 수 있다.
SET GLOBAL slow_query_log = ON;
SET GLOBAL log_output = 'FILE';
SET GLOBAL long_query_time = 0;
SHOW VARIABLES LIKE 'slow_query_log_file';나는 트래픽이 가장 몰리는 오후 두 시부터 30분만 받기로 했다. 30분이 지난 뒤 long_query_time을 1로 되돌리고 FLUSH SLOW LOGS로 파일을 끊었다. 초당 쿼리가 수천 건인 서버에서 이걸 하루 종일 켜 두면 시간당 기가바이트 단위로 로그가 쌓인다. 디스크 여유를 먼저 확인하고, 끌 시간을 미리 정해 두는 편이 좋다.
전역 값을 바꿔도 기존 연결은 옛 값을 쓴다
처음 30분이 지나고 파일을 열었을 때 나는 꽤 당황했다. 쿼리가 거의 없었다. 배치 서버에서 들어온 쿼리 몇 건만 0초대로 찍혀 있었고, 정작 보고 싶던 API 서버의 쿼리는 하나도 없었다.
이유는 long_query_time이 세션 변수라는 데 있었다. 새 연결은 맺어질 때 전역 값을 복사해 가지만, 이미 열려 있는 연결은 처음 받은 값을 그대로 쓴다. API 서버는 커넥션 풀로 연결을 몇 시간씩 붙잡고 있었으니 1초 문턱이 그대로 살아 있었던 것이다. 반대 방향도 똑같다. 0으로 받아 적은 뒤 전역 값을 되돌려도 그사이 맺어진 연결은 계속 모든 쿼리를 쓴다. 디스크가 계속 차서 이상하다며 그제야 알아차린 사람의 사연도 본 적이 있다.
두 번째 시도에서는 전역 값을 바꾼 뒤 애플리케이션을 순서대로 재시작해 풀을 새로 채웠다. 스레드를 강제로 끊는 방법도 있지만, 애플리케이션이 끊긴 연결을 매끄럽게 다시 잇는지 확인하지 않았다면 권하지 않는다. 되돌릴 때도 같은 절차를 밟아야 한다.
log_queries_not_using_indexes를 켰다가 디스크를 본 날
같은 시기에 옆 서비스에서 log_queries_not_using_indexes를 켠 적이 있다. 인덱스를 타지 않는 쿼리를 잡아 보자는 생각이었다. 문제는 이 옵션이 long_query_time 검사를 건너뛴다는 점이다. 인덱스 없이 행을 읽은 쿼리는 0.1밀리초 만에 끝나도 로그에 남는다.
한 시간쯤 뒤 디스크 사용량 알림이 울렸다. 로그를 열어 보니 대부분 공통 코드 테이블, 배송사 목록처럼 수십 행짜리 테이블을 통째로 읽는 쿼리였다. 그런 테이블은 원래 풀 스캔이 더 빠르다. 문제가 아닌 쿼리가 문제 있는 쿼리를 덮어 버린 셈이다. 허탈했다.
이 옵션을 켜야 한다면 다음 둘을 같이 만지는 것이 좋다.
| 변수 | 하는 일 | 내가 쓴 값 |
|---|---|---|
log_throttle_queries_not_using_indexes | 인덱스 미사용 쿼리를 분당 몇 건까지 쓸지 제한한다. 기본값 0은 무제한이다 | 60 |
min_examined_row_limit | 이 수보다 적은 행을 읽은 쿼리는 로그에 남기지 않는다 | 1000 |
min_examined_row_limit은 인덱스 미사용 쿼리에만 걸리는 조건이 아니다. 슬로 로그 전체의 조건이라서, long_query_time=0으로 전부 받을 때 함께 걸어 두면 작은 쿼리가 빠져 순위가 왜곡된다. 전부 받을 때는 0으로 둔다.
pt-query-digest 프로파일에서 Response time 비중 읽기
받아 둔 로그는 pt-query-digest에 넣는다. 이 도구는 상수 값을 걷어 낸 쿼리 모양, 곧 핑거프린트로 쿼리를 묶는다. 기본 정렬은 Query_time:sum, 다시 말해 총 응답 시간이다. 기본 --limit는 95%:20이라 전체 응답 시간의 95%를 채우거나 20개에 이르면 거기서 멈춘다.
pt-query-digest /var/lib/mysql/db1-slow.log > digest.txt
리포트 맨 위의 Profile 표가 순위표다. 그날 내 리포트의 위쪽은 이랬다.
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ============================== ============== ====== ====== ===== ==============
# 1 0x6A1F0C93D2B4E781A05C3F9E1B2D 412.3301 38.2% 921406 0.0004 0.00 SELECT product_option
# 2 0x9C02B7E45A16D3F08E2C71A94B6F 301.8876 27.9% 812 0.3718 0.41 SELECT review1위는 한 번에 0.4밀리초면 끝나는 쿼리였다. 1초 문턱으로는 절대 잡히지 않는다. 그런데 30분 동안 92만 번 불려서 전체 응답 시간의 38%를 차지했다. 상품 화면 하나를 그릴 때 옵션마다 쿼리를 한 번씩 날리는 코드였다. 하나하나는 빠른데 합치면 가장 비싼 쿼리였다.
Response time의 퍼센트는 이 쿼리를 없애면 서버가 덜어 낼 수 있는 몫의 상한으로 읽는다. R/Call은 한 번의 비용이고, V/M은 응답 시간의 분산을 평균으로 나눈 값이다. V/M이 0에 가까우면 늘 비슷한 속도로 돈다. 2위처럼 0.41쯤 되면 같은 쿼리인데 빠를 때와 느릴 때가 갈린다는 뜻이다. 오후에만 튀던 응답과 잘 맞는 신호였다.
Rows examine 비율이 가리키는 쿼리
Profile 아래에는 쿼리마다 상세 블록이 붙는다. 2위 쿼리의 블록에서 눈여겨본 줄은 둘이다.
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 812
# Exec time 27 302s 112ms 1s 372ms 640ms 180ms 340ms
# Rows sent 0 16.24k 20 20 20 20 0 20
# Rows examine 41 152.31M 187.00k 188.10k 187.57k 186.83k 1.02k 187.57kRows sent는 클라이언트에 돌려준 행 수, Rows examine은 그걸 만들려고 읽은 행 수다. 한 번에 20행을 돌려주려고 18만 7천 행을 읽었다. 9천 배가 넘는다. 게다가 pct 열을 보면 실행 시간은 전체의 27%인데 읽은 행은 41%였다. 서버가 행을 읽는 일의 절반 가까이를 이 쿼리 하나가 하고 있었다.
이 비율이 크면 인덱스가 조건을 제대로 걸러 주지 못하고 있다는 신호다. 이 쿼리는 상품별 리뷰를 최신순으로 20개 가져오는데, 인덱스가 product_id 하나뿐이라 그 상품의 리뷰를 전부 읽고 정렬했다. (product_id, created_at) 복합 인덱스를 만든 뒤 읽는 행이 20 근처로 떨어졌다. 깊은 페이지로 가는 OFFSET 목록도 이 비율이 크게 나오는데, 그 사연은 OFFSET 페이지네이션이 느려지는 이유와 키셋 전환기에 따로 적었다.
읽은 행 기준으로 순위를 다시 보고 싶으면 정렬 기준만 바꾸면 된다.
pt-query-digest --order-by Rows_examined:sum --limit 10 /var/lib/mysql/db1-slow.log지금 내가 로그를 받는 방식
평소에는 long_query_time을 1초로 두고 슬로 로그를 계속 켜 둔다. log_queries_not_using_indexes는 끈다. 켜야 할 때는 스로틀과 행 수 하한을 같이 건다. 이 로그는 혹시 모를 사고를 남기는 블랙박스로만 쓴다.
순위를 매겨야 할 일이 생기면 가장 바쁜 시간대에 30분만 문턱을 0으로 내린다. 바꾸기 전에 디스크 여유를 보고, 바꾼 뒤에는 커넥션 풀을 새로 채운다. 끝나면 되돌리고 다시 풀을 비운다. 그리고 리포트는 늘 Response time 비중부터 읽는다. 위에서 서너 줄 안에 답이 있는 경우가 많았다. 그다음 상세 블록에서 Rows examine을 Rows sent로 나눠 본다.
그날 이후로 느린 쿼리를 찾는다는 말을 조금 다르게 쓴다. 내가 찾는 건 오래 걸리는 쿼리가 아니라 서버 시간을 가장 많이 먹는 쿼리다. 둘이 같은 쿼리일 때도 있지만, 리뷰 API의 1위는 0.4밀리초짜리였다.