슬로우 쿼리 1위를 고치기 전에는 2위가 보이지 않는다

운영 장애의 부하원이 reader CPU 포화였고, 어떤 쿼리가 태우는지 특정하려면 슬로우 쿼리 로그가 필요했습니다. 그런데 그동안 안 켜져 있었고, 켜는 방법에도 함정이 몇 개 있었습니다.

비용 없이 켜기

AWS 콘솔에서 권하는 경로(CloudWatch Database Insights, 로그 export)는 과금 대상입니다. Aurora 자체 슬로우 로그를 파일로만 남기면 추가 비용이 없습니다.

⧉# ① CloudWatch export 를 먼저 끈다 (이걸 안 끄고 켜면 로그가 CloudWatch 로 흘러가 과금)
aws rds modify-db-cluster --db-cluster-identifier <cluster> \
  --cloudwatch-logs-export-configuration '{"DisableLogTypes":["slowquery","general"]}' \
  --apply-immediately

# ② cluster 파라미터 그룹에서 켠다 (dynamic → 재부팅 불필요)
aws rds modify-db-cluster-parameter-group --db-cluster-parameter-group-name <PG> \
  --parameters "ParameterName=slow_query_log,ParameterValue=1,ApplyMethod=immediate" \
               "ParameterName=long_query_time,ParameterValue=1,ApplyMethod=immediate"

함정들:

• SET GLOBAL slow_query_log=1 은 RDS 에서 ERROR 1227 (SUPER 권한) 으로 막힙니다. 마스터 유저도 안 됩니다. 파라미터 그룹이 유일한 경로입니다.
• long_query_time 기본값 10초는 "평상시 0.5초 → 포화 때 수십 초" 류를 정상 구간에서 못 잡습니다. 반대로 0 에 가깝게 두면 장애 순간(모든 쿼리가 느려질 때) 로깅 I/O 가 부하를 보탭니다. 1초에서 시작했습니다.
• 로그 다운로드(download-db-log-file-portion)는 호출당 최대 약 1MB 라, Marker 로 끝까지 이어받지 않으면 앞부분만 받고 다 받은 줄 알게 됩니다.
• reader 인스턴스의 로그를 반드시 따로 확인해야 합니다. 읽기 부하 병목은 reader 에서 나는데, writer 로그만 보면 아무것도 없습니다.

분석은 pt-query-digest(percona-toolkit) 를 썼습니다. 파라미터만 다른 같은 쿼리를 지문(fingerprint)으로 묶어 총 소요시간 비중으로 정렬해 줍니다.

1위를 고치기 전에는 2위가 안 보입니다

첫 로그의 Profile 은 이랬습니다. 1위 한 패턴이 전체 슬로우 시간의 97%.

⧉Rank  Response time    Calls  Item
   1  ...... 97.x%     ....   SELECT ... (예약목록 계열)
   2  ......  1.x%     ....   ...

이 상태에서 2위 이하를 분석하는 건 의미가 없었습니다. 표본이 적어 순위가 불안정하고, 1위가 reader 를 태우는 동안 다른 쿼리들도 덩달아 느려져 로그에 섞입니다. 그래서 방식을 반복 루프로 잡았습니다.

1. 최신 슬로우 로그를 내려받아 pt-query-digest 로 1위 지문 확인
2. 1위 쿼리 → 매퍼·화면 특정 → 튜닝(재작성/인덱스) → 결과 byte-identical 검증 → 배포
3. 배포 후 로그를 다시 떠서 1위가 사라졌는지 판정하고, 새로 1위가 된 쿼리로 반복

이 루프를 네 바퀴 돌았습니다. 바퀴마다 1위가 바뀌었습니다 — 예약목록(13배 개선) 다음에 메인배너(50배)가 보였고, 그다음 포인트 조회(900배), 마지막으로 체크인 조회(630배 이상)가 올라왔습니다. 전부 첫 로그에서는 1위에 가려 보이지 않던 것들입니다.

판정에도 요령이 하나 필요했습니다. 배포 직후 로그에는 재기동 전 인스턴스가 흘린 잔여 슬로우가 섞입니다. 지문의 마지막 발생 시각이 배포·재기동 시각 이전이면 "사라진 것" 으로 판정했습니다 (# Time: 은 UTC 라는 것도 한 번 헷갈리면 계속 헷갈립니다).

종료 조건

네 바퀴째 배포 후 재진단에서, 남은 슬로우가 서비스 쿼리가 아니라 수동으로 실행한 애드혹 집계 1건뿐이었습니다. 서비스에 정의된 쿼리 중 슬로우 후보가 없어진 시점을 종료로 잡고, 이후는 배포나 이슈가 있을 때 같은 절차로 스팟 체크하기로 했습니다. 상시 대시보드 없이도, "로그 내려받기 + digest" 가 스크립트 한 번이라 유지 비용이 거의 없습니다.

정리

• 슬로우 로그는 파라미터 그룹으로만 켤 수 있고, CloudWatch export 를 먼저 꺼야 과금이 없습니다
• 슬로우 시간은 파레토 분포라 스냅샷 한 장으로 전체 계획을 세울 수 없습니다 — 1위를 제거해야 다음 병목이 드러나므로, 튜닝과 재진단을 한 사이클로 묶는 게 맞았습니다
• 판정 기준은 벽시계가 아니라 지문의 소멸 여부입니다. 배포 시각 전후로 로그를 잘라서 봐야 합니다