이번 시간에는 PostgreSQL의 EXPLAIN (ANALYZE, BUFFERS) 출력을 읽으면서, 인덱스를 안 쓰는 대표적인 경우를 직접 확인하며 배워가는 시간입니다.
예를 들어서 우리가 orders 테이블의 status 컬럼에 인덱스를 만들었다고 해볼게요. 그런데 WHERE status = 'DONE' 쿼리의 실행 계획에는 여전히 Seq Scan이 나와요.
PostgreSQL의 플래너는 쿼리마다 몇 행이 나올지 예상하고, 그 예상으로 비용이 가장 낮은 실행 방법을 고릅니다. 그러니 인덱스를 안 쓰는 데는 이유가 있고, 그 이유는 실행 계획에 거의 다 드러나요.
실습 준비
이 글의 명령은 모두 실습 코드의 postgresql-explain-index/ 디렉터리에서 실행합니다.
compose.yaml: PostgreSQL 17 컨테이너 하나(프로젝트 이름pgexp)setup.sql:customers10만 명과orders100만 건, 인덱스 2개를 만드는 SQLhold.sql:HOLD주문 30만 건을 넣는 SQL
Docker로 PostgreSQL 17을 띄워요. 서버 설정은 바꾸지 않았습니다. 이 글의 결과에 영향을 주는 기본값은 다음과 같아요.
shared_buffers = 128MB: PostgreSQL이 테이블과 인덱스 페이지를 올려 두는 공유 메모리 크기입니다.seq_page_cost = 1,random_page_cost = 4: 플래너가 페이지를 순서대로 읽는 비용과 띄엄띄엄 읽는 비용을 얼마로 계산할지 정하는 값입니다. 띄엄띄엄 읽기를 네 배 비싸게 봐요.
compose.yaml입니다. name이 compose 프로젝트 이름이 되니까, 아래 docker compose 명령은 모두 이 파일이 있는 디렉터리에서 실행해 주세요.
name: pgexp
services:
db:
image: postgres:17
environment:
POSTGRES_PASSWORD: postgres
POSTGRES_DB: lab
ports:
- "7110:5432"
mem_limit: 1g
주문의 customer_id는 고객 10만 명에게 고르게 나눠 주었고, status는 DONE이 약 95%, PAID가 약 4%, CANCEL이 약 1%가 되게 했어요.
setup.sql은 두 테이블을 autovacuum_enabled = off로 만들고 데이터를 넣은 뒤, orders의 customer_id와 status에 인덱스를 만들고 VACUUM ANALYZE까지 실행합니다.
autovacuum은 VACUUM과 ANALYZE를 알아서 돌리는데, 실습 도중에 끼어들면 통계가 바뀌어 결과가 흔들립니다. 그래서 이 글에서는 ANALYZE를 직접 실행해요. 운영 환경에서는 끄지 않습니다.
psql은 컨테이너 안에 있는 것을 씁니다. 자주 쓰니까 셸 함수로 만들어 둘게요.
아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.
docker compose up -d
until docker compose exec -T db pg_isready -U postgres -d lab > /dev/null 2>&1; do sleep 1; done; sleep 1
sql() { docker compose exec -T db psql -U postgres -d lab "$@"; }
sql < setup.sql
sql -c "SELECT relname, pg_size_pretty(pg_relation_size(oid)) AS size FROM pg_class WHERE relname IN ('orders', 'customers')"
sql -c "SELECT status, count(*) FROM orders GROUP BY status ORDER BY status"
relname | size
-----------+---------
customers | 7400 kB
orders | 112 MB
(2 rows)
status | count
--------+--------
CANCEL | 9937
DONE | 950182
PAID | 39881
(3 rows)
orders는 112MB로, shared_buffers 128MB에 거의 다 들어가는 크기예요.
실습 1: 실행 계획 읽기
먼저 컨테이너를 재시작해 shared_buffers를 비울게요. 그다음 한 고객의 주문을 찾는 쿼리를 EXPLAIN으로 봅니다.
docker compose restart db
until docker compose exec -T db pg_isready -U postgres -d lab > /dev/null 2>&1; do sleep 1; done; sleep 1
sql -c "EXPLAIN SELECT * FROM orders WHERE customer_id = 42"
QUERY PLAN
----------------------------------------------------------------------------------------
Index Scan using idx_orders_customer_id on orders (cost=0.42..44.23 rows=10 width=80)
Index Cond: (customer_id = 42)
(2 rows)
EXPLAIN은 쿼리를 실행하지 않고 플래너가 세운 계획과 예상치만 보여 줘요. 괄호 안의 값은 이렇습니다.
cost=0.42..44.23: 첫 행을 내기까지의 비용과 모든 행을 내기까지의 비용입니다. 단위는 시간이 아니라, 페이지 하나를 순서대로 읽는 비용(seq_page_cost)을 1로 놓은 상대값이에요.rows=10: 이 노드가 낼 것으로 예상한 행 수입니다.width=80: 행 하나의 평균 크기(바이트) 예상치입니다.
Index Cond는 인덱스에서 찾는 범위를 정하는 조건이에요. 이 조건이 붙어 있으면 인덱스로 범위를 좁혀 읽었다는 뜻입니다.
같은 쿼리를 EXPLAIN (ANALYZE, BUFFERS)로 두 번 실행해 볼게요. ANALYZE를 붙이면 쿼리를 실제로 실행하고, BUFFERS를 붙이면 페이지를 몇 개 읽었는지도 함께 나와요. PostgreSQL 17에서는 BUFFERS를 직접 적어야 합니다.
sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE customer_id = 42"
sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE customer_id = 42"
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------
Index Scan using idx_orders_customer_id on orders (cost=0.42..44.23 rows=10 width=80) (actual time=0.317..0.906 rows=10 loops=1)
Index Cond: (customer_id = 42)
Buffers: shared read=13
Planning:
Buffers: shared hit=137
Planning Time: 0.924 ms
Execution Time: 0.995 ms
(7 rows)
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------
Index Scan using idx_orders_customer_id on orders (cost=0.42..44.23 rows=10 width=80) (actual time=0.046..0.167 rows=10 loops=1)
Index Cond: (customer_id = 42)
Buffers: shared hit=13
Planning:
Buffers: shared hit=137
Planning Time: 1.889 ms
Execution Time: 0.247 ms
(7 rows)
뒤쪽 괄호가 실제 실행 결과예요.
actual time=0.317..0.906: 첫 행이 나온 시간과 마지막 행이 나온 시간(ms)입니다.rows=10: 실제로 나온 행 수입니다. 예상rows=10과 같으니 플래너가 정확히 예상했어요.loops=1: 이 노드가 실행된 횟수입니다.Buffers: shared read=13: 8KB 페이지 13개를shared_buffers밖에서 가져왔다는 뜻입니다. 운영체제 캐시에 있었을 수도 있고, 디스크에서 읽었을 수도 있어요.Buffers: shared hit=13: 같은 13개 페이지를shared_buffers에서 바로 찾았다는 뜻입니다.
첫 번째 실행은 재시작 직후라 13개 모두 read였고, 두 번째 실행은 모두 hit이었어요. 실행 시간도 0.995ms에서 0.247ms로 줄었습니다.
같은 쿼리라도 캐시 상태에 따라 시간은 달라지지만 읽은 페이지 수(hit과 read의 합)는 같아요. 그래서 두 계획을 비교할 때는 시간과 함께 버퍼 수를 봐 주세요.
실습 2: 많이 찾으면 Seq Scan이 빠를 수 있습니다
플래너가 status = 'DONE'의 행 수를 어떻게 예상하는지부터 볼게요. ANALYZE가 모은 통계는 pg_stats 뷰에서 볼 수 있어요.
sql -c "SELECT most_common_vals, most_common_freqs, correlation FROM pg_stats WHERE tablename = 'orders' AND attname = 'status'"
sql -c "SELECT reltuples FROM pg_class WHERE relname = 'orders'"
most_common_vals | most_common_freqs | correlation
--------------------+----------------------+-------------
{DONE,PAID,CANCEL} | {0.9504,0.0396,0.01} | 0.9059889
(1 row)
reltuples
-----------
1e+06
(1 row)
most_common_vals: 자주 나오는 값 목록입니다.most_common_freqs: 각 값이 전체에서 차지하는 비율입니다. ANALYZE는 테이블 전체가 아니라 표본을 읽어서 계산하므로 실제 비율과 조금 다를 수 있어요.pg_class.reltuples: 테이블의 전체 행 수 추정치입니다.
등호 조건의 값이 most_common_vals에 있으면, 예상 행 수는 그 값의 비율에 전체 행 수를 곱한 값이에요. CANCEL은 0.01 × 1,000,000 = 10000행, DONE은 0.9504 × 1000000 = 950400행으로 예상됩니다. 세 값을 차례로 실행해 볼게요.
sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE status = 'CANCEL'"
sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE status = 'PAID'"
sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE status = 'DONE'"
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------
Index Scan using idx_orders_status on orders (cost=0.42..5640.85 rows=10000 width=80) (actual time=0.670..467.164 rows=9937 loops=1)
Index Cond: (status = 'CANCEL'::text)
Buffers: shared hit=9 read=7200
Planning:
Buffers: shared hit=140
Planning Time: 5.913 ms
Execution Time: 468.942 ms
(7 rows)
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------
Index Scan using idx_orders_status on orders (cost=0.42..11535.77 rows=39600 width=80) (actual time=0.147..578.147 rows=39881 loops=1)
Index Cond: (status = 'PAID'::text)
Buffers: shared hit=6777 read=6705
Planning:
Buffers: shared hit=140
Planning Time: 0.904 ms
Execution Time: 581.439 ms
(7 rows)
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Seq Scan on orders (cost=0.00..26786.00 rows=950400 width=80) (actual time=0.064..905.917 rows=950182 loops=1)
Filter: (status = 'DONE'::text)
Rows Removed by Filter: 49818
Buffers: shared hit=13876 read=410
Planning:
Buffers: shared hit=140
Planning Time: 0.966 ms
Execution Time: 967.476 ms
(8 rows)
예상 행은 pg_stats로 계산한 값과 정확히 같아요. CANCEL과 PAID는 인덱스를 썼고, 전체의 95%인 DONE은 Seq Scan을 골랐습니다.
Seq Scan에서는 조건이 Index Cond가 아니라 Filter에 붙어요. 모든 행을 읽은 뒤 조건에 안 맞는 행을 버렸다는 뜻이고, 버린 행 수가 Rows Removed by Filter입니다.
정말 Seq Scan이 나은지 확인하려고 enable_seqscan을 끄고 같은 쿼리를 실행해 볼게요. 이 설정은 Seq Scan을 완전히 막지는 않고, 다른 방법이 있으면 그쪽을 고르게 만들어요. 비교용으로만 쓰고 운영 설정으로 두지 않습니다.
sql -c "SET enable_seqscan = off" -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE status = 'DONE'"
SET
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------
Bitmap Heap Scan on orders (cost=10594.02..36760.03 rows=950400 width=80) (actual time=43.962..421.993 rows=950182 loops=1)
Recheck Cond: (status = 'DONE'::text)
Heap Blocks: exact=14286
Buffers: shared hit=13912 read=1177
-> Bitmap Index Scan on idx_orders_status (cost=0.00..10356.42 rows=950400 width=0) (actual time=41.371..41.372 rows=950182 loops=1)
Index Cond: (status = 'DONE'::text)
Buffers: shared hit=4 read=799
Planning:
Buffers: shared hit=140
Planning Time: 1.057 ms
Execution Time: 495.264 ms
(11 rows)
->로 시작하는 줄이 하위 노드예요. 먼저 Bitmap Index Scan이 인덱스에서 조건에 맞는 행의 위치를 모아 페이지 단위의 비트맵을 만들고, 그다음 Bitmap Heap Scan이 그 페이지들을 파일 순서대로 한 번씩 읽어요.
플래너가 비용을 36760으로 계산해, Seq Scan의 26786보다 높게 봤어요. 강제한 계획도 테이블의 모든 페이지(Heap Blocks: exact=14286)를 읽었고, 인덱스 페이지 803개를 더 읽었어요.
시간은 세 번씩 다시 재서 비교해 볼게요.
for i in 1 2 3; do sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE status = 'DONE'" | grep "Execution Time"; done
for i in 1 2 3; do sql -c "SET enable_seqscan = off" -c "EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM orders WHERE status = 'DONE'" | grep "Execution Time"; done
Execution Time: 344.137 ms
Execution Time: 670.681 ms
Execution Time: 507.097 ms
Execution Time: 378.725 ms
Execution Time: 402.512 ms
Execution Time: 719.585 ms
Seq Scan은 344~671ms, 강제한 계획은 379~720ms로 범위가 겹쳤어요.
노트북의 Docker에서 다른 작업과 함께 돌린 실습이라 시간이 크게 흔들렸고, 데이터도 거의 다 메모리에 있어서 디스크를 띄엄띄엄 읽는 비용은 드러나지 않았습니다. 플래너는 random_page_cost = 4로 그 비용을 가정하고 계획을 세워요.
시간 차이는 뚜렷하지 않았지만, 읽은 페이지 수는 Seq Scan이 더 적었어요. 조건에 맞는 행이 대부분이면 인덱스를 거쳐도 테이블 페이지를 거의 다 읽게 됩니다.
실습 3: 통계가 낡으면 계획이 틀립니다
플래너는 실제 데이터가 아니라 마지막 ANALYZE 때 모은 통계를 봅니다.
이번에는 보류 상태인 HOLD 주문 30만 건을 새로 넣어 볼게요. 이 테이블은 autovacuum을 꺼 두었으니 통계는 바뀌지 않아요. hold.sql은 generate_series(1000001, 1300000)으로 status = 'HOLD' 주문 30만 건을 넣습니다.
sql < hold.sql
sql -c "SELECT reltuples, relpages, pg_relation_size('orders') / 8192 AS pages FROM pg_class WHERE relname = 'orders'"
INSERT 0 300000
reltuples | relpages | pages
-----------+----------+-------
1e+06 | 14286 | 18572
(1 row)
pg_class에는 아직 100만 행, 14286페이지로 남아 있고, 실제 파일은 18572페이지예요. 플래너는 전체 행 수는 현재 파일 크기에 맞춰 보정하지만, HOLD라는 값의 비율은 보정할 방법이 없어요.
HOLD 주문과 고객 이메일을 조인해 볼게요.
sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT c.email, o.amount FROM orders o JOIN customers c ON c.id = o.customer_id WHERE o.status = 'HOLD'"
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.72..16.76 rows=1 width=25) (actual time=4.390..1007.284 rows=300000 loops=1)
Buffers: shared hit=903326 read=1198 dirtied=1
-> Index Scan using idx_orders_status on orders o (cost=0.43..8.45 rows=1 width=8) (actual time=0.584..275.729 rows=300000 loops=1)
Index Cond: (status = 'HOLD'::text)
Buffers: shared hit=4523 read=1 dirtied=1
-> Index Scan using customers_pkey on customers c (cost=0.29..8.31 rows=1 width=25) (actual time=0.002..0.002 rows=1 loops=300000)
Index Cond: (id = o.customer_id)
Buffers: shared hit=898803 read=1197
Planning:
Buffers: shared hit=228 read=22
Planning Time: 44.082 ms
Execution Time: 1030.048 ms
(12 rows)
most_common_vals에 없는 값이면 플래너는 목록에 있는 값들의 비율을 1에서 뺀 나머지를 다른 값들이 나눠 가진다고 봅니다. 지금은 세 값의 비율을 더하면 1이라 나머지가 없고, 예상 행 수는 최솟값인 1행이 돼요.
Nested Loop는 첫 번째 하위 노드(바깥쪽)에서 행을 하나 받을 때마다 두 번째 하위 노드(안쪽)를 한 번씩 실행하는 조인이에요. 예상이 1행이라면 고객을 한 번만 찾으면 되니 좋은 계획이죠.
그런데 실제로는 안쪽의 customers 스캔이 loops=300000, 즉 30만 번 실행됐어요. 이 노드의 rows=1은 한 번 실행했을 때의 평균이라, 전체로는 30만 행입니다. 버퍼는 90만 개가 넘었어요.
이제 ANALYZE orders로 통계를 새로 모으고 같은 쿼리를 실행해 볼게요.
sql -c "ANALYZE orders"
sql -c "EXPLAIN (ANALYZE, BUFFERS) SELECT c.email, o.amount FROM orders o JOIN customers c ON c.id = o.customer_id WHERE o.status = 'HOLD'"
ANALYZE
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
Hash Join (cost=3175.43..26229.15 rows=295971 width=25) (actual time=77.045..275.342 rows=300000 loops=1)
Hash Cond: (o.customer_id = c.id)
Buffers: shared hit=5449
-> Index Scan using idx_orders_status on orders o (cost=0.43..22273.23 rows=297483 width=8) (actual time=0.044..68.796 rows=300000 loops=1)
Index Cond: (status = 'HOLD'::text)
Buffers: shared hit=4524
-> Hash (cost=1925.00..1925.00 rows=100000 width=25) (actual time=76.704..76.706 rows=100000 loops=1)
Buckets: 131072 Batches: 1 Memory Usage: 6880kB
Buffers: shared hit=925
-> Seq Scan on customers c (cost=0.00..1925.00 rows=100000 width=25) (actual time=0.009..19.934 rows=100000 loops=1)
Buffers: shared hit=925
Planning:
Buffers: shared hit=250
Planning Time: 0.733 ms
Execution Time: 294.574 ms
(15 rows)
예상 행이 297483으로 실제 30만 행에 가까워졌고, 조인 방식이 Hash Join으로 바뀌었어요. customers를 Seq Scan으로 한 번 읽어 메모리에 해시 테이블(Hash 노드)을 만들고, 주문 30만 행을 하나씩 대조합니다.
버퍼는 904524개에서 5449개로 줄었어요. 그래서 실행 계획에서 예상 행과 실제 행이 크게 다른 노드가 있으면, 거기서부터 원인을 찾아 주세요.
정리
범위: PostgreSQL 17(서버 설정 기본값), 주문 100만 건(112MB) orders 테이블, 이 테이블의 autovacuum은 끔, 시간은 세 번씩 다시 잼.
- 전체의 95%인
DONE은 Seq Scan을 골랐고, 인덱스를 강제하자 테이블 14286페이지를 모두 읽고 인덱스 803페이지를 더 읽었으며 시간은 344~671ms와 379~720ms로 겹쳤습니다. 조건에 맞는 행이 대부분인 쿼리의 Seq Scan을 문제로 보지 마세요. HOLD30만 건을 넣고 ANALYZE 전에는 예상 1행으로 Nested Loop를 골라 안쪽 스캔이loops=300000, 버퍼 904524개였고, ANALYZE 뒤에는 Hash Join으로 버퍼 5449개가 됐습니다. 대량 INSERT나 이관 뒤 느려지면pg_stat_user_tables의last_analyze,last_autoanalyze를 보고ANALYZE를 실행해 주세요.- 이 글에 싣지 않은 추가 측정에서는 타입이나 정렬 규칙 때문에도 인덱스를 못 썼습니다.
int컬럼을42.0과 비교하자 컬럼이numeric으로 바뀌어 테이블 전체를 읽었고, 정렬 규칙en_US.utf8에서LIKE 'user42%'는email컬럼의 일반 인덱스를 쓰지 못해text_pattern_ops인덱스로 925페이지에서 22페이지로 줄었습니다. 파라미터 타입을 컬럼 타입에 맞추고, 계획에서 조건이Index Cond에 들어갔는지Filter에 들어갔는지 봐 주세요.