pg_stat_statements로 느린 쿼리 찾고 auto_explain으로 실행계획 보기 - RDS/EC2 PostgreSQL 튜닝

운영 DB가 갑자기 느려졌다는 이야기를 들으면 제일 먼저 하는 일이 "어떤 쿼리가 느린지"부터 특정하는 것이다. 그런데 막상 접속해서 pg_stat_activity를 들여다봐도 그 순간 마침 도는 쿼리만 보이지, 하루 종일 DB 시간을 갉아먹는 진짜 범인은 잘 안 잡힌다. 예전에 슬로우 쿼리 로그만 켜고 grep 하던 글을 쓴 적이 있는데, RDS로 넘어오고 나서는 접근 방식을 바꿨다. 이 글은 그때 정리해 둔 순서를 다시 다듬은 것이다.

결론부터 말하자면, 누적 통계는 pg_stat_statements로 뽑아 총 실행시간이 큰 쿼리를 골라내고, 그 쿼리의 실제 실행계획은 auto_explain으로 서버 로그에 자동으로 떨구게 해서 확인한다. 두 확장은 역할이 다르다. 앞엣것은 "어떤 쿼리가 전체적으로 비싼가"를 알려주고, 뒤엣것은 "그 쿼리가 실제로 어떤 계획으로 도는가"를 보여준다. 둘을 같이 켜 두면 느린 쿼리를 찾고 인덱스나 계획을 고치는 데까지 한 번에 이어진다.

1. 두 확장이 무엇을 하는가

pg_stat_statements는 실행된 SQL을 정규화(literal 값을 $1 같은 파라미터로 치환)해서 같은 모양의 쿼리끼리 호출 횟수, 총 실행시간, 평균 실행시간, 반환 행 수, 버퍼 읽기량을 누적해 주는 확장이다. 즉 개별 실행이 아니라 "이 패턴의 쿼리가 서버가 켜진 뒤 총 몇 번 돌았고 시간을 얼마나 썼는가"를 pg_stat_statements 뷰 하나로 보여준다.

auto_explain은 일정 시간 이상 걸린 쿼리의 실행계획을 자동으로 서버 로그에 남기는 확장이다. 평소에 EXPLAIN을 손으로 붙일 수 없는 운영 트래픽에서, 느린 실행만 골라 계획을 기록해 준다. log_analyze를 켜면 예측 계획이 아니라 실제로 몇 행을 몇 번 돌았는지가 담긴 EXPLAIN ANALYZE 결과가 남는다.

아래에서는 설치와 확인, 느린 쿼리 집계, 실행계획 로그 확인, 인덱스 개선 검증을 차례로 살펴본다.

2. pg_stat_statements 켜기

이 확장은 공유 메모리를 잡아야 해서 shared_preload_libraries에 등록하고 서버를 재시작해야 한다. 세션에서 LOAD로는 못 켠다.

EC2 자체 설치 PostgreSQL

postgresql.conf를 고치고 재시작한다.

# postgresql.conf
shared_preload_libraries = 'pg_stat_statements'
compute_query_id = on
pg_stat_statements.max = 5000       # 추적할 쿼리 종류 수, 기본 5000
pg_stat_statements.track = top      # top(기본) | all | none
pg_stat_statements.save = on

$ sudo systemctl restart postgresql
$ sudo -u postgres psql sarc -c "CREATE EXTENSION IF NOT EXISTS pg_stat_statements;"
CREATE EXTENSION

여기서 한 번 걸리는 지점이 있다. 확장을 만들었는데 뷰가 비어 있으면 십중팔구 shared_preload_libraries에 안 올라간 것이다. 재시작 없이 ALTER SYSTEM만 해도 반영이 안 된다. 확인은 이렇게 한다.

sarc=# SHOW shared_preload_libraries;
 shared_preload_libraries
--------------------------
 pg_stat_statements
(1 row)

RDS PostgreSQL

RDS는 PostgreSQL 11 이상이면 기본 파라미터 그룹의 shared_preload_libraries에 pg_stat_statements가 이미 들어 있다. 다만 커스텀 파라미터 그룹을 쓰면 값이 빠져 있을 수 있으니 확인하고, 없으면 추가한 뒤 재부팅한다. shared_preload_libraries는 정적 파라미터라 재부팅이 필요하다.

$ aws rds modify-db-parameter-group \
    --db-parameter-group-name sarc-pg16 \
    --parameters "ParameterName=shared_preload_libraries,ParameterValue=pg_stat_statements,ApplyMethod=pending-reboot"

$ aws rds reboot-db-instance --db-instance-identifier sarc-db

재부팅이 끝나면 접속해서 확장만 만들면 된다. RDS에서는 rds_superuser 권한으로 CREATE EXTENSION을 실행한다.

sarc=> CREATE EXTENSION IF NOT EXISTS pg_stat_statements;
CREATE EXTENSION

3. 총 실행시간이 큰 쿼리부터 골라낸다

튜닝 우선순위는 "한 번 실행이 느린 쿼리"가 아니라 "총 실행시간이 큰 쿼리"로 잡는 게 효율이 좋다. 평균이 1ms라도 하루 수십만 번 도는 쿼리가 전체 DB 시간을 더 많이 먹기 때문이다. total_exec_time 기준으로 정렬해서 상위를 본다.

SELECT queryid,
       calls,
       round(total_exec_time::numeric, 1)      AS total_ms,
       round(mean_exec_time::numeric, 2)       AS mean_ms,
       rows,
       shared_blks_read                        AS blks_read,
       left(query, 60)                         AS query
FROM   pg_stat_statements
ORDER  BY total_exec_time DESC
LIMIT  10;

출력 형태는 이렇다. 실제 수치는 트래픽과 데이터 양에 따라 달라지므로 아래는 모양을 보기 위한 예시다.

 queryid    | calls  | total_ms  | mean_ms | rows   | blks_read | query
------------+--------+-----------+---------+--------+-----------+---------------------------------------
 -284…91023 | 128473 | 412088.4  |    3.21 | 128473 |   983221  | SELECT * FROM board_post WHERE author_i
  591…22740 |    842 |  98771.2  |  117.30 |  15980 |   441002  | SELECT p.*, c.name FROM board_post p JO
  118…55031 |  52011 |  33110.0  |    0.64 | 520110 |     2210  | SELECT id, title FROM article WHERE cat
(… )

여기서 봐야 할 조합이 두 가지다. 첫째, total_ms가 큰데 calls도 큰 행은 호출이 잦은 쿼리라 인덱스 하나로 효과가 크게 난다. 둘째, blks_read가 유독 큰 행은 캐시에 없어 디스크에서 블록을 많이 읽는다는 뜻이라 I/O 부하의 원인일 수 있다. 위 예시에서는 첫 행이 author_id 조건 조회라 인덱스 후보가 뚜렷하다.

측정 구간을 새로 끊고 싶으면 통계를 리셋한다. 배포 직후나 특정 시간대만 보고 싶을 때 쓴다.

sarc=# SELECT pg_stat_statements_reset();

참고로 함수 안에서 도는 중첩 쿼리까지 잡으려면 pg_stat_statements.track = all로 바꾼다. 기본값 top은 클라이언트가 직접 보낸 최상위 문장만 센다. 그리고 계획 수립 시간까지 보려면 track_planning을 켜야 하는데, 동시 접속이 많으면 성능 저하가 생길 수 있어 기본값 off 그대로 두는 편을 권한다.

4. auto_explain으로 실행계획을 로그에 남긴다

느린 쿼리를 특정했으면 이제 그 쿼리가 실제로 어떤 계획으로 도는지 봐야 한다. 운영에서 매번 EXPLAIN ANALYZE를 손으로 붙일 수는 없으니 auto_explain에게 맡긴다.

EC2 자체 설치

auto_explain은 session_preload_libraries로도 올릴 수 있어서 재시작 없이 새 세션부터 적용할 수 있다. 아래처럼 설정하고 리로드한다.

# postgresql.conf
session_preload_libraries = 'auto_explain'
auto_explain.log_min_duration = '500ms'   # 이 시간 넘는 쿼리만 계획 기록, 기본 -1(끔)
auto_explain.log_analyze = on             # 실제 행 수/시간 포함, 기본 off
auto_explain.log_buffers = on             # 버퍼 사용량 포함(log_analyze 필요)
auto_explain.log_format = text            # text(기본) | json | yaml | xml

$ sudo systemctl reload postgresql

주의할 점 하나. log_analyze = on은 계획을 실제로 계측하면서 돌리기 때문에 타이밍 수집 비용이 붙는다. log_min_duration을 0이나 너무 낮게 잡으면 모든 쿼리에 계측이 걸려 오히려 느려질 수 있다. 그래서 처음엔 500ms 정도로 높게 잡고, 대상을 좁힌 뒤 내리는 편이 안전하다. 부담을 더 줄이려면 auto_explain.sample_rate(기본 1)를 낮춰 일부 실행만 기록하게 한다.

RDS

RDS에서는 auto_explain을 shared_preload_libraries에 추가하는 방식이 표준이라 재부팅이 필요하다. 파라미터 그룹에 라이브러리와 옵션을 함께 넣는다.

$ aws rds modify-db-parameter-group \
    --db-parameter-group-name sarc-pg16 \
    --parameters \
      "ParameterName=shared_preload_libraries,ParameterValue='auto_explain,pg_stat_statements',ApplyMethod=pending-reboot" \
      "ParameterName=auto_explain.log_min_duration,ParameterValue=500,ApplyMethod=immediate" \
      "ParameterName=auto_explain.log_analyze,ParameterValue=1,ApplyMethod=immediate"

RDS는 로그 파일을 직접 tail 할 수 없으니 계획은 RDS 콘솔의 로그 뷰어나 CloudWatch Logs로 확인한다. EC2 자체 설치라면 log_directory 밑 로그 파일을 그대로 tail 하면 된다.

로그에 찍히는 계획

조건이 맞으면 서버 로그에 이런 항목이 남는다. log_analyze를 켰으므로 예측 rows와 실제 rows가 나란히 찍혀 계획이 빗나갔는지 바로 보인다.

LOG:  duration: 812.443 ms  plan:
  Query Text: SELECT * FROM board_post WHERE author_id = $1 ORDER BY created_at DESC
  Sort  (cost=1994.61..1997.11 rows=1000 width=220) (actual time=811.9..812.1 rows=642 loops=1)
    Sort Key: created_at DESC
    ->  Seq Scan on board_post  (cost=0.00..1944.80 rows=1000 width=220)
                                (actual time=0.05..809.3 rows=642 loops=1)
          Filter: (author_id = 42)
          Rows Removed by Filter: 5163

Seq Scan에 Rows Removed by Filter: 5163이 보인다. 전체 테이블을 훑으면서 조건에 안 맞는 5163행을 버렸다는 뜻이고, author_id에 인덱스가 없다는 신호다.

5. 인덱스를 넣고 계획이 바뀌는지 확인한다

진단이 끝났으면 인덱스를 만든다. 운영 테이블이라면 락을 오래 잡지 않도록 CONCURRENTLY로 만든다. 이 옵션은 트랜잭션 블록 안에서는 못 쓰고, 실패하면 무효 인덱스가 남을 수 있으니 만든 뒤 상태를 확인한다.

sarc=# CREATE INDEX CONCURRENTLY idx_board_post_author_created
         ON board_post (author_id, created_at DESC);
CREATE INDEX

author_id로 거르고 created_at으로 정렬하는 쿼리라, 두 컬럼을 묶은 복합 인덱스를 정렬 방향까지 맞춰 만들면 정렬 단계도 인덱스로 흡수된다. 같은 쿼리를 다시 EXPLAIN (ANALYZE, BUFFERS)로 확인한다.

sarc=# EXPLAIN (ANALYZE, BUFFERS)
         SELECT * FROM board_post WHERE author_id = 42 ORDER BY created_at DESC;
                                    QUERY PLAN
----------------------------------------------------------------------------------
 Index Scan using idx_board_post_author_created on board_post
     (cost=0.29..24.11 rows=642 width=220) (actual time=0.03..0.41 rows=642 loops=1)
   Index Cond: (author_id = 42)
   Buffers: shared hit=18
 Planning Time: 0.18 ms
 Execution Time: 0.55 ms

Seq Scan이 Index Scan으로 바뀌었고 Sort 노드가 사라졌다. Rows Removed by Filter도 없어졌다. 실제 소요 시간은 데이터 양과 캐시 상태에 따라 다르지만, 이 사례처럼 전체 스캔이 인덱스 조회로 바뀌면 큰 폭으로 줄어든다.

마지막으로 배포 뒤 pg_stat_statements_reset()으로 통계를 끊고 한동안 두었다가 다시 상위 쿼리를 뽑아, 그 queryid의 total_ms와 mean_ms가 실제로 내려갔는지 확인한다. 계획만 바뀌고 누적 시간이 안 줄면 인덱스가 안 쓰이거나 다른 쿼리가 병목인 것이다.

6. 정리

순서는 이렇게 굳어진다. pg_stat_statements로 total_exec_time이 큰 쿼리를 골라 후보를 좁히고, auto_explain으로 그 쿼리의 실제 계획을 로그에서 확인해 Seq Scan이나 빗나간 행 추정 같은 문제를 짚는다. 그다음 인덱스나 쿼리를 고치고, EXPLAIN (ANALYZE, BUFFERS)로 계획이 바뀐 것을 보고, 통계를 리셋해 누적 시간이 실제로 줄었는지로 마무리한다. RDS든 EC2 자체 설치든 확장을 켜는 방법만 다를 뿐 진단 순서는 같다.