PostgreSQL 쿼리 느림? auto_explain으로 추적

서버는 멀쩡한데 특정 API만 간헐적으로 느려지고, 애플리케이션 로그에는 원인이 남지 않는 경우가 많습니다. 이럴 때 EXPLAIN ANALYZE 를 수동으로 찍어보는 방식은 한계가 있습니다. 느린 쿼리가 매번 같은 형태로 재현되지 않거나, 특정 파라미터 조합에서만 느려지거나, 운영 데이터 분포에서만 터지기 때문입니다.

auto_explain 은 PostgreSQL이 실제로 실행된 쿼리의 실행 계획을 자동으로 로그에 남기도록 해주는 확장입니다. 즉, “느려진 그 순간”의 실행 계획을 서버가 잡아줍니다. 이 글에서는 운영 환경에서 auto_explain 을 안전하게 켜고, 로그를 해석해 원인을 좁히는 방법을 다룹니다.

또한 운영 이슈는 데이터베이스만의 문제가 아니라 네트워크, LB 타임아웃, 커넥션 풀 고갈 같은 주변 요인과 얽히는 경우가 많습니다. HTTP 레벨에서 502·504가 동반된다면 원인 분리에도 도움이 되니, 필요하면 AWS ALB 502·504 난사 - 원인별 해결 체크리스트도 함께 참고하세요.

auto_explain이 해결해주는 문제

auto_explain 의 핵심 가치는 다음 3가지입니다.

재현 불가능한 느린 쿼리 포착: 특정 파라미터, 특정 시점의 통계/캐시 상태에서만 느려지는 쿼리도 로그로 남습니다.
실행 계획과 실제 실행 시간의 연결: 단순히 “느렸다”가 아니라, 어떤 노드가 시간을 먹었는지 확인할 수 있습니다.
운영에 가까운 관찰: 개발/스테이징에서 잘 나오던 계획이 운영에서만 틀어지는 경우(통계, 데이터 분포, 파라미터 선택성) 추적에 강합니다.

단, 로그가 급증할 수 있고, 설정을 잘못하면 부하가 늘 수 있습니다. 그래서 “필요한 만큼만” 켜는 것이 중요합니다.

설치 및 활성화: shared_preload_libraries

auto_explain 은 shared_preload_libraries 로 미리 로드해야 합니다. 즉, 설정 변경 후 PostgreSQL 재시작이 필요합니다.

postgresql.conf 또는 파라미터 그룹(Managed DB라면)에서 다음을 설정합니다.

# postgresql.conf
shared_preload_libraries = 'auto_explain'

# 최소 200ms 이상 걸린 쿼리만 계획 로깅
auto_explain.log_min_duration = '200ms'

# 실제 실행 시간/버퍼 사용량까지 포함
auto_explain.log_analyze = on
auto_explain.log_buffers = on

# 쿼리 텍스트도 함께 남기기(운영에서는 민감정보 주의)
auto_explain.log_statement = on

# 중첩 호출(함수 내부 쿼리 등)까지 로깅할지
auto_explain.log_nested_statements = on

# 샘플링(로그 폭주 방지). 1.0은 100%, 0.1은 10%
auto_explain.sample_rate = 0.1

# JSON 포맷(로그 파이프라인에서 파싱하기 좋음)
auto_explain.log_format = json

운영에서 권장되는 시작값

auto_explain.log_min_duration 은 처음엔 200ms ~ 500ms 정도로 시작하는 편이 안전합니다.
트래픽이 높다면 auto_explain.sample_rate 를 0.01 ~ 0.1 로 두고, 문제가 재현되는 시간대에만 일시적으로 올리는 방식이 좋습니다.
auto_explain.log_analyze = on 은 실행 단계에서 약간의 오버헤드가 생길 수 있습니다. 하지만 “실제 시간”이 필요하면 켜야 합니다. 상황에 따라 log_analyze 는 켜고 log_buffers 만 끄는 절충도 가능합니다.

세션 단위로만 켜기(리스크 최소화)

전체 서버에 적용이 부담되면, 특정 세션에만 켤 수도 있습니다. 단, auto_explain 자체는 preload 되어 있어야 합니다.

-- 특정 세션에서만 임계값을 낮춰 관찰
SET auto_explain.log_min_duration = '50ms';
SET auto_explain.log_analyze = on;
SET auto_explain.log_buffers = on;
SET auto_explain.log_format = json;

-- 관찰하고 싶은 쿼리 실행
SELECT ...;

이 방식은 장애 대응 중 “특정 배치/특정 관리 세션”에서만 잠깐 켜서 추적할 때 유용합니다.

로그에서 무엇을 봐야 하나

auto_explain 로그는 결국 EXPLAIN (ANALYZE, BUFFERS, ...) 결과를 자동 출력한 것입니다. 해석 포인트는 크게 5가지입니다.

최상단 실행 시간: 전체 쿼리 시간이 어느 정도인지
병목 노드: Seq Scan, Nested Loop, Sort, HashAggregate 등 어디서 시간이 소모되는지
Rows 추정치 vs 실제치: Plan Rows 와 Actual Rows 차이가 큰지
Buffers: shared hit(캐시 적중) vs read(디스크 읽기)가 많은지
I/O vs CPU: 디스크 read가 많으면 I/O 병목, 정렬/해시가 크면 메모리·CPU 병목 가능

예시 1: 인덱스가 있는데도 Seq Scan이 뜨는 경우

인덱스가 존재해도 플래너가 Seq Scan 을 선택할 수 있습니다. 대표 원인은 선택성이 낮거나(대부분의 행이 조건을 만족), 통계가 오래됐거나, 파라미터 값에 따라 최적 계획이 달라지는 경우입니다.

-- 인덱스
CREATE INDEX CONCURRENTLY idx_orders_status ON orders(status);

-- 문제 쿼리
SELECT *
FROM orders
WHERE status = 'PAID'
ORDER BY created_at DESC
LIMIT 50;

이때 로그에서 Seq Scan on orders 와 함께 Sort 가 크게 보인다면 다음을 의심합니다.

status = 'PAID' 가 테이블 대부분이라 인덱스 이점이 없음
ORDER BY created_at 를 만족하는 복합 인덱스가 없음

해결 방향은 보통 복합 인덱스입니다.

CREATE INDEX CONCURRENTLY idx_orders_status_created_at
ON orders(status, created_at DESC);

또는 통계가 오래됐다면:

ANALYZE orders;

예시 2: Nested Loop 폭발(조인 순서/카디널리티 오판)

Nested Loop 자체가 나쁜 것은 아니지만, 외부 테이블에서 많은 행을 뽑은 뒤 내부 테이블을 반복 탐색하면 실행 시간이 기하급수적으로 늘어납니다.

SELECT u.id, o.id
FROM users u
JOIN orders o ON o.user_id = u.id
WHERE u.country = 'KR'
  AND o.created_at >= now() - interval '7 days';

auto_explain 로그에서 다음 조합이 보이면 위험 신호입니다.

Nested Loop
내부 쪽에서 Index Scan 이 수만~수백만 번 반복
Actual Rows 가 Plan Rows 보다 훨씬 큼

대응은 보통 다음 중 하나입니다.

조인/필터 컬럼 인덱스 보강
통계 갱신(특히 조인 컬럼)
쿼리 구조 변경(서브쿼리로 먼저 줄이기)

예를 들어 orders(created_at, user_id) 인덱스가 없으면 7일 조건이 비싸질 수 있습니다.

CREATE INDEX CONCURRENTLY idx_orders_created_at_user_id
ON orders(created_at, user_id);

예시 3: Sort/Hash가 메모리를 넘겨 디스크로 스필

정렬이나 해시는 work_mem 을 초과하면 임시 파일을 쓰면서 급격히 느려질 수 있습니다. auto_explain.log_buffers 와 함께, 서버 로그에서 temp file 관련 메시지(설정에 따라)까지 보면 힌트가 나옵니다.

-- 큰 그룹핑
SELECT user_id, count(*)
FROM events
WHERE created_at >= now() - interval '1 day'
GROUP BY user_id
ORDER BY count(*) DESC
LIMIT 100;

이 경우 개선은 크게 3가지입니다.

적절한 인덱스로 입력을 줄이기(예: events(created_at, user_id))
집계 범위를 줄이거나 사전 집계 테이블 도입
특정 쿼리만 SET work_mem 으로 상향(세션 단위)

BEGIN;
SET LOCAL work_mem = '128MB';

SELECT user_id, count(*)
FROM events
WHERE created_at >= now() - interval '1 day'
GROUP BY user_id
ORDER BY count(*) DESC
LIMIT 100;
COMMIT;

파라미터에 따라 계획이 바뀌는 문제(제너릭 플랜)

Prepared statement 를 많이 쓰는 환경(ORM, PgBouncer transaction pooling 등)에서는 “특정 값에서만 느린” 문제가 자주 나옵니다. 플래너가 값별 최적화 대신 일반화된 계획을 선택하는 경우가 있기 때문입니다.

이때 auto_explain 로 특정 파라미터에서 실행된 실제 계획을 잡아두면, 다음을 점검할 수 있습니다.

쿼리가 prepared 로 실행되는지
인덱스 선택이 값에 따라 달라지는지
통계가 선택성을 제대로 반영하는지

상황에 따라 plan_cache_mode 를 조정하거나, 쿼리를 분기(선택성 높은 값/낮은 값)하는 전략이 필요할 수 있습니다.

auto_explain 로그를 운영에서 다루는 팁

1) 민감정보(PII) 주의

auto_explain.log_statement = on 은 쿼리 텍스트가 그대로 남을 수 있습니다. 애플리케이션이 리터럴 값을 쿼리에 직접 박아 넣는다면 개인정보가 로그로 유출될 수 있습니다.

가능하면 바인딩 파라미터를 사용
로그 접근 권한을 최소화
필요 시 log_statement 를 끄고, 애플리케이션에서 쿼리 식별자(해시)만 남기는 방식 고려

2) 로그 폭주 방지

log_min_duration 을 너무 낮게 잡지 않기
sample_rate 로 샘플링 적용
특정 시간대에만 임시로 낮추는 운영 절차 마련

3) 다른 관찰 도구와 함께 쓰기

auto_explain 은 “왜 느린지(계획)”를 보여주고, pg_stat_statements 는 “무엇이 많이 느린지(집계)”를 보여줍니다. 둘은 역할이 다릅니다.

pg_stat_statements 로 상위 느린 쿼리 후보를 찾고
후보 쿼리가 실제로 느려지는 순간을 auto_explain 로 포착

이 조합이 가장 효율적입니다.

장애 대응 플로우(실전 체크리스트)

느린 구간의 타임라인 확보(애플리케이션 지표, DB 커넥션 수, CPU, 디스크 read)
auto_explain.log_min_duration 을 일시적으로 낮추거나 sample_rate 를 올려 포착 확률을 높임
로그에서 병목 노드 확인(Seq Scan, Nested Loop, Sort, HashAggregate)
Actual Rows 와 Plan Rows 차이가 크면 통계/카디널리티 문제를 우선 의심
인덱스 추가는 CREATE INDEX CONCURRENTLY 로 운영 영향 최소화
개선 후 동일 조건에서 다시 관찰(로그 재확인)

인프라가 쿠버네티스 위에 있고, 간헐적 지연이 네트워크/DNS 문제로 보인다면 DB 이전에 클러스터 레벨 점검이 필요할 수도 있습니다. 그런 경우 EKS에서 CoreDNS 정상인데 DNS가 간헐 실패할 때 같은 이슈도 함께 분리해보면 원인 파악이 빨라집니다.

마무리

auto_explain 은 “느린 쿼리의 실행 계획을 운영에서 자동 채집”한다는 점에서, 재현이 어려운 성능 문제에 특히 강합니다. 다만 로그/오버헤드/민감정보 리스크가 있으므로 log_min_duration, sample_rate, 세션 단위 설정을 조합해 안전하게 운용하는 것이 핵심입니다.

정리하면,

느린 순간을 잡아야 한다면 auto_explain
어떤 쿼리가 문제인지 찾는 데는 pg_stat_statements
계획의 병목은 Actual Rows vs Plan Rows, Buffers read, Sort/Hash 스필 여부로 좁혀간다

이 3단계를 체계화하면 “가끔 느린데 원인을 못 찾는” 상태에서 빠르게 벗어날 수 있습니다.