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

운영 장애의 부하원이 reader CPU 포화였고, 어떤 쿼리가 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 CPU 를 점유하는 동안 다른 쿼리들도 함께 느려져 로그에 섞입니다. 그래서 작업 방식을 다음 반복 절차로 정했습니다.

1. 최신 슬로우 로그를 다운로드해 pt-query-digest 로 1위 지문을 확인합니다.
2. 1위 쿼리의 매퍼·화면을 특정하고, 튜닝(재작성/인덱스) 후 결과가 byte-identical 인지 검증해 배포합니다.
3. 배포 후 로그를 다시 다운로드해 1위가 제거됐는지 판정하고, 새로 1위가 된 쿼리로 반복합니다.

이 절차를 네 번 반복했습니다. 반복할 때마다 1위가 변경됐습니다. 예약목록(13배 개선) 다음에 메인배너(50배)가 확인됐고, 그다음 포인트 조회(900배), 마지막으로 체크인 조회(630배 이상)가 1위가 되었습니다. 전부 첫 로그에서는 1위에 가려 보이지 않던 쿼리들입니다.

판정에도 요령이 하나 필요했습니다. 배포 직후 로그에는 재기동 전 인스턴스가 기록한 슬로우 기록이 섞입니다. 지문의 마지막 발생 시각이 배포·재기동 시각 이전이면 "사라진 것" 으로 판정했습니다 (# Time: 이 UTC 라는 점도 혼동하기 쉬워 주의해야 합니다).

종료 조건

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

정리

• 슬로우 로그는 파라미터 그룹으로만 활성화할 수 있고, CloudWatch export 를 먼저 비활성화해야 과금이 없습니다.
• 슬로우 시간은 파레토 분포라 로그 한 번으로 전체 계획을 수립할 수 없습니다. 1위를 제거해야 다음 병목이 확인되므로, 튜닝과 재진단을 한 사이클로 묶는 것이 맞았습니다.
• 판정 기준은 경과 시간이 아니라 지문이 사라졌는지 여부입니다. 배포 시각 전후로 로그를 구분해서 확인해야 합니다.