설치·접속: PostgreSQL 설치와 접속
부제: "DB가 전반적으로 굼뜬데 어떤 쿼리 탓인지 감이 안 잡힐 때" — 워크로드 전체를 랭킹으로 훑어 범인을 지목하고, 그 쿼리가 실제로 느려지는 순간의 실행계획을 로그에서 건져낸다.
느린 쿼리를 잡을 때 흔히 EXPLAIN을 떠올리지만, 그건 "이 쿼리 하나"만 본다. 문제는 대개 "어떤 쿼리가 범인인지 모른다"는 데 있다. pg_stat_statements는 서버가 돌린 모든 SQL의 누적 통계를, auto_explain은 임계 시간을 넘긴 쿼리의 실행계획을 자동으로 잡아준다. 둘을 이으면 누가(랭킹) → 왜(플랜) 파이프라인이 완성된다.
두 모듈 모두 shared_preload_libraries에 등록하고 서버를 재시작해야 한다(로드 후에는 세션 단위로 auto_explain.* GUC를 켤 수 있다).
# postgresql.conf
shared_preload_libraries = 'pg_stat_statements,auto_explain'
compute_query_id = onCREATE EXTENSION IF NOT EXISTS pg_stat_statements;1단계 — 통계를 0으로 리셋하고 워크로드를 흘려보낸다
측정 구간을 명확히 하려고 먼저 카운터를 비운다. 그다음 평소 트래픽에 해당하는 쿼리 몇 개를 실행한다(여기서는 20만 행짜리 이벤트 테이블 집계·중복제거와 shop 테이블 읽기를 섞었다).
SELECT pg_stat_statements_reset();
-- 무거운 축: 전체 스캔 집계 (3회)
SELECT kind, count(*), avg(user_id) FROM events GROUP BY kind;
-- 무거운 축: 필터 + 중복제거 (2회)
SELECT count(DISTINCT token) FROM events WHERE user_id < 500;
-- 가벼운 축: 인덱스 포인트 조회
SELECT * FROM events WHERE user_id = 42;
SELECT * FROM events WHERE user_id = 77;
-- shop 읽기
SELECT o.id, u.name, o.qty FROM orders o JOIN users u ON u.id = o.user_id
ORDER BY o.qty DESC LIMIT 10;
SELECT count(*) FROM users WHERE email LIKE '%@example.com';2단계 — total_exec_time 상위로 범인을 랭킹한다
pg_stat_statements는 상수를 $1로 치환해 "의미가 같은 쿼리"를 하나로 묶는다(정규화). 그래서 user_id = 42와 user_id = 77이 user_id = $1 한 줄에 calls=2로 합쳐진다. 튜닝 우선순위는 실행 한 번의 속도가 아니라 총 소모 시간(total_exec_time) 으로 정한다.
SELECT substring(query, 1, 48) AS query,
calls,
round(total_exec_time::numeric, 2) AS total_ms,
round(mean_exec_time::numeric, 3) AS mean_ms,
rows,
round(100.0 * shared_blks_hit
/ nullif(shared_blks_hit + shared_blks_read, 0), 1) AS hit_pct
FROM pg_stat_statements
WHERE query NOT LIKE '%pg_stat_statements%'
ORDER BY total_exec_time DESC
LIMIT 6; query | calls | total_ms | mean_ms | rows | hit_pct
--------------------------------------------------+-------+----------+---------+------+---------
SELECT count(DISTINCT token) FROM events WHER | 2 | 104.52 | 52.260 | 2 | 96.8
SELECT kind, count(*), avg(user_id) FROM even | 3 | 36.75 | 12.251 | 12 | 100.0
SELECT * FROM events WHERE user_id = $1 | 2 | 0.42 | 0.212 | 400 | 100.0
SELECT o.id, u.name, o.qty FROM orders o JOIN us | 1 | 0.06 | 0.057 | 10 | 100.0
SELECT p.name, count(*) FROM orders o JOIN produ | 1 | 0.05 | 0.052 | 20 | 100.0
SELECT count(*) FROM users WHERE email LIKE $1 | 1 | 0.00 | 0.005 | 1 | 100.01등은 count(DISTINCT token) 쿼리다. 총 104.52ms, 호출당 52ms. 캐시 히트율(hit_pct)도 96.8%로 유일하게 100% 미만이라 디스크까지 건드린 흔적이 보인다. 범인은 지목됐다. 이제 "왜 느린지"를 봐야 한다.
3단계 — auto_explain으로 그 쿼리의 실제 플랜을 자동 로깅한다
pg_stat_statements는 "얼마나 느린지"는 알려줘도 "왜 느린지"는 말해주지 않는다. 여기서 auto_explain을 켠다. log_min_duration=0이면 모든 문장을, log_analyze=true면 추정이 아닌 실측(EXPLAIN ANALYZE급) 플랜을 로그에 남긴다. 운영에서는 임계값을 0 대신 '200ms' 같은 값으로 걸어 느린 것만 잡는다.
SET auto_explain.log_min_duration = 0; -- 0 = 모든 문장, 운영은 '200ms' 식
SET auto_explain.log_analyze = true; -- 실측 플랜(actual time/rows)
SET auto_explain.log_buffers = true; -- 버퍼/디스크 접근까지
SELECT count(DISTINCT token) FROM events WHERE user_id < 500;플랜은 화면이 아니라 서버 로그에 쌓인다. 꺼내 본다.
sudo tail -f /var/lib/postgresql/16/main/log/postgresql-*.log2026-07-18 01:31:19.604 UTC [20361] postgres@shop LOG: duration: 61.263 ms plan:
Query Text: SELECT count(DISTINCT token) FROM events WHERE user_id < 500;
Aggregate (cost=15956.92..15956.93 rows=1 width=8) (actual time=61.255..61.256 rows=1 loops=1)
Buffers: shared hit=1263 read=85, temp read=453 written=454
-> Sort (cost=15461.15..15709.03 rows=99154 width=33) (actual time=50.533..56.109 rows=100000 loops=1)
Sort Key: token
Sort Method: external merge Disk: 3624kB
Buffers: shared hit=1263 read=85, temp read=453 written=454
-> Bitmap Heap Scan on events (cost=1104.74..4520.16 rows=99154 width=33) (actual time=1.434..9.871 rows=100000 loops=1)
Recheck Cond: (user_id < 500)
Heap Blocks: exact=1260
Buffers: shared hit=1260 read=85
-> Bitmap Index Scan on events_user_idx (cost=0.00..1079.95 rows=99154 width=0) (actual time=1.346..1.347 rows=100000 loops=1)
Index Cond: (user_id < 500)
Buffers: shared read=85원인이 눈에 보인다. Sort Method: external merge Disk: 3624kB — 10만 행을 token으로 정렬하는데 work_mem이 모자라 디스크로 흘러넘쳤다(temp read=453 written=454). 전체 61ms 중 정렬이 50ms를 먹는다. 인덱스 조회(1ms)나 힙 스캔(10ms)이 아니라 정렬이 병목이다. 조치는 명확하다 — 이 쿼리 세션의 work_mem을 올리거나, token에 인덱스를 얹거나, 애초에 DISTINCT가 꼭 필요한지 다시 본다.
랭킹으로 누구를 잡고, 자동 로깅으로 왜인지를 재현 없이 잡았다. 문제 쿼리를 로컬에서 억지로 재현할 필요가 없다는 게 이 조합의 핵심이다.
이렇게도 쓴다
부하가 큰 서버라면 auto_explain을 전량이 아니라 표본만 잡아 오버헤드를 줄인다. (조합: sample_rate)
SET auto_explain.log_min_duration = '200ms';
SET auto_explain.log_sample_rate = 0.1; -- 임계 초과 문장의 10%만 기록
pg_stat_statements를 총 시간이 아니라 I/O 관점으로 다시 정렬해 "디스크를 가장 많이 친 쿼리"를 찾는다. (조합: shared_blks_read)
SELECT substring(query,1,50), calls, shared_blks_read, temp_blks_written
FROM pg_stat_statements
ORDER BY shared_blks_read DESC LIMIT 10;
플랜을 사람이 아니라 기계가 파싱하도록 JSON으로 남겨 로그 수집기로 보낸다. (조합: log_format)
SET auto_explain.log_format = 'json';
SET auto_explain.log_min_duration = 0;
범인을 지목한 뒤 그 쿼리만 직접 손으로 뜯어본다. auto_explain이 못 잡는 즉석 분석용. (조합: EXPLAIN)
EXPLAIN (ANALYZE, BUFFERS, SETTINGS)
SELECT count(DISTINCT token) FROM events WHERE user_id < 500;
호출당 평균이 아니라 편차가 큰 쿼리(가끔 튀는 쿼리)를 stddev로 찾는다. (조합: stddev_exec_time)
SELECT substring(query,1,50), calls, mean_exec_time, stddev_exec_time
FROM pg_stat_statements
WHERE calls > 5 ORDER BY stddev_exec_time DESC LIMIT 10;언제 다른 도구로 가나: 지금 이 순간 무엇이 도는지(진행 중 쿼리, 락 대기)는 누적 통계가 아니라 pg_stat_activity를 본다. pg_stat_statements는 "끝난 쿼리들의 역사"이고, activity는 "지금의 현장"이다.