[260917 TIL] ANALYZE는 왜 한 시간이 걸렸나

이 글에는 나(사람)의 시점이 없다. 클로드에게 완전히 선생님 시점에서 써달라고 부탁했다.
나는 클로드 선생님이 이 문제를 해결하는 과정을 1시간 넘게 지켜봤다.
지켜보며 배운 것이 정말 많았으므로, 이 TIL엔 내 시점을 넣지 않고 생성된 그대로 놔둔다.

---

ANALYZE는 왜 한 시간이 걸렸나 — 네 번 틀리고 콜레이션에 닿기까지

이 글은 내 시점에서 쓴다.
사람이 읽는 회고가 아니라, 내가 무엇을 보고 무엇을 틀렸고 무엇이 나를 고쳤는지의 기록이다.

발단은 곁가지였다.

personas 100만 행에 halfvec 인덱스를 얹는 작업 중에 ANALYZE personas를 돌려 뒀는데,
사용자가 물었다.

 

"analyze 가 항상 엄청오래걸리던데 얼마나 걸릴지 예측 가능할까요"

나는 답을 추측으로 채우려다 멈췄다.

마침 그 ANALYZE가 눈앞에서 돌고 있었다.

---

첫 단서 — 진행률이 100%인데 끝나지 않는다

pg_stat_progress_analyze를 봤다.

phase               | computing statistics
sample_blks_total   | 30000
sample_blks_scanned | 30000     ← 100%
wait_event          | (없음)
elapsed             | 00:50:26

 

읽기는 이미 끝나 있었다. 50분 내내 computing statistics 단계였고 wait_event가 비어 있었다.
디스크가 아니라 CPU에서 멎어 있다.

 

그리고 더 중요한 것 — 저 뷰는 표본 블록 읽기 진행률만 준다.
정작 오래 걸리는 연산 단계에는 진행률 카운터가 없다.

 

사용자의 "언제 끝날지 모르겠다"는 체감은 착각이 아니었다. 계측 공백이 실재했다.
그래서 나는 ETA를 만들어내지 않았다. 낼 근거가 Postgres 안에 없다고 말했다.

두 번째 단서 — 행 수는 범인이 아니다

대신 예측의 실마리가 하나 있었다.
연산 대상은 min(행 수, 300 × default_statistics_target) = 30,000행 고정이다.

테이블이 100만 행이든 3천만 행이든 이 단계 비용은 거의 같다.

그렇다면 시간을 정하는 것은 행 수가 아니라 컬럼 구성이고,
같은 스키마의 30,000행 표본으로 재면 본 테이블 시간을 근사할 수 있다.

측정 가능한 명제가 생겼다. 여기서부터 가설을 세우기 시작했다. 그리고 네 번 틀렸다.

---

가설 1 — 임베딩 컬럼이 비싸다 (틀림)

가장 그럴듯했다. vector(1536)은 행당 6KB고 TOAST에 나가 있다.
3만 개를 정렬 비교하면 느릴 수밖에 없다고 생각했다.

ANALYZE (embedding 만 통계)   →   4 ms

 

4밀리초. 가설이 즉사했다.

나중에 확인 사살도 됐다. 임베딩 컬럼을 뺀 30,000행 테이블의 ANALYZE가 179초였다.
임베딩은 무죄였다. 오히려 제일 쌌다.

가설 2 — text[] 배열의 MCELEM 계산이 범인이다 (틀림)

skills_list·hobbies_list는 array_typanalyze가 원소별 빈도를 따로 계산한다.
구조적으로 비싼 경로다. 유력하다고 적었다.

skills_list    8,641 ms
hobbies_list   7,900 ms

 

비싸긴 한데 179초 중 16초다. 지배적이지 않다. 또 틀렸다.

---

가장 위험했던 순간 — "모든 컬럼이 45초다"

컬럼별로 끊어 재기로 했다. 결과가 이렇게 나왔다.

uuid      text      39,826 ms
sex       text      45s+ 타임아웃
age       integer   45,077 ms
province  text      45s+ 타임아웃
district  text      45s+ 타임아웃
...

 

sex는 고유값이 2개다. age는 정수다. 3만 행짜리 테이블이다.
이게 45초일 리가 없다.

 

여기가 이 조사에서 가장 위험한 지점이었다.
숫자가 가지런했기 때문이다. 전 컬럼이 균일하게 40~45초.

"이 테이블의 ANALYZE는 컬럼과 무관하게 비싸다"는 그럴듯한 표를 그대로 보고할 수 있었다.

그럴듯함이 아니라 부조리를 봤다. 고유값 2개짜리 컬럼이 45초라는 건 말이 안 된다.
말이 안 되면 내 측정이 틀린 것이다.

SELECT l.pid, l.mode, l.granted, c.relname FROM pg_locks l ...

 pid | mode                     | granted | relname
 111 | ShareUpdateExclusiveLock | t       | anz     ← 옛 ANALYZE가 살아 있다
 624 | ShareUpdateExclusiveLock | f       | anz     ← 내 측정이 줄 서 있다

 

락 대기였다. 연산이 아니라.

내가 취소했다고 «믿었던» ANALYZE가 살아 있었다.

스크립트에 ANALYZE가 네 개 있었고, 하나를 취소하자 psql이 다음 문장으로 넘어갔다.
pg_cancel_backend는 쿼리를 끊지 세션을 끊지 않는다.

연결째 끊고 다시 쟀다.

ANALYZE bench.anz (age)   →   1,230 ms

 

45초가 1.2초가 됐다. 데이터는 한 글자도 안 바뀌었다.

측정값이 전부 비슷하면 공통 원인을 의심해라. 그 공통 원인이 측정 장치 자신일 수 있다.

가설 3 — 긴 텍스트라서 느리다 (틀림)

락을 풀고 다시 재니 범인이 선명하게 드러났다.

uuid          text       163 ms
sex           text        75 ms
age           integer     67 ms
province      text       223 ms
district      text     2,346 ms
occupation    text     2,421 ms
persona       text   156,932 ms   ←
skills_list   text[]   8,641 ms
hobbies_list  text[]   7,900 ms

 

persona 하나가 157초, 전체의 94%.

나는 "긴 한국어 텍스트라 비교가 비싸다"고 설명하려 했다.

district·occupation(짧은 한국어) 2.3초 대 persona(긴 한국어) 157초 —
길이 × 콜레이션 비용이라는 깔끔한 이야기였다.

그리고 길이를 쟀다.

persona:  평균 81자, 최대 141자, 고유값 30,000개 (전부 유니크)

 

81자. 짧다. 네 번째로 틀렸다.

---

결정적 실험 — 같은 데이터, 콜레이션만 다르게

가설이 네 번 깨지고 나서야 변인을 하나만 남기는 실험을 설계했다.
같은 persona 데이터를 두 테이블에 복사하고, 한쪽만 COLLATE "C"로 바꿨다.

ANALYZE (COLLATE "C")      →        91 ms
ANALYZE (기본 콜레이션)     →   156,416 ms

 

1,719배. 데이터는 동일하다. 콜레이션만 다르다.

datcollate      | en_US.utf8
datlocprovider  | c            (glibc)

 

한국어 문자열을 en_US.utf8 규칙으로 비교하고 있었다.
ANALYZE는 히스토그램을 만들려고 3만 개 표본을 정렬하고,
그 과정에서 glibc strcoll을 약 45만 번 호출한다.
비교 1회당 약 350µs. 그게 157초다.

그리고 전부가 한 그림으로 맞았다

콜레이션이 원인이라면 비용은 길이가 아니라 「서로 다른 값의 개수」를 따라야 한다.
정렬 비교 횟수가 그것을 따르니까.

컬럼	고유값	시간
sex	2개	75 ms
province	수십 개	223 ms
district·occupation	수백~수천	2.3~2.4 초
persona	30,000개 (전부 유니크)	157 초

 

정확히 맞는다.

남은 건 하나였다. 왜 임베딩만 공짜인가?

vector_ops가 btree 기본 연산자 클래스라 정렬 경로를 타야 하는데.

통계를 열어 봤다.

attname   | avg_width | has_mcv | has_histogram
embedding |        18 |    f    |      f          ← 아무것도 없다
district  |        19 |    t    |      t

 

avg_width = 18은 TOAST 포인터 크기다. 값이 한 번도 펼쳐지지 않았다.

analyze.c에는 WIDTH_THRESHOLD(1KB)가 있다.

그보다 넓은 값은 MCV·히스토그램 계산에서 통째로 건너뛴다.
임베딩은 6,148바이트 — 3만 개 전부가 "too wide"로 스킵된다. 정렬 자체가 일어나지 않는다.

여기서 이 사건의 아이러니가 완성된다.

6KB짜리 벡터 컬럼은 «너무 커서» 공짜였고,
81자짜리 텍스트 컬럼은 «적당히 작아서» 157초였다.

 

내 첫 가설이 정확히 거꾸로였던 이유다.
나는 크기를 봤는데, Postgres는 크기를 보고 포기한다.

---

처방과 결과

원인을 알고 나니 처방은 세 줄짜리 판단이었다.

persona를 비롯한 서술형 텍스트 11개는 앱에서 화면에 실려 나갈 뿐
WHERE·ORDER BY·JOIN 어디에도 쓰이지 않는다.
플래너가 그 히스토그램을 쓸 일이 없다. 157초는 통째로 순손실이다.

ALTER TABLE personas ALTER COLUMN persona SET STATISTICS 0;
-- ... 서술형 텍스트 11개

	ANALYZE
처방 전	63분 이상 (끝내 완료 못 함)
처방 후	32초

 

WHERE에 쓰는 sex·age·province·district·occupation과 조회 키 uuid는 건드리지 않았다.
어차피 싸다. 배열 2개(합 16.5초)도 남겼다 — 끄면 37배까지 가지만,
계획만 있고 아직 안 만든 GIN 인덱스가 살아나면 MCELEM 통계가 필요하다.
되돌리기 쉬운 쪽을 열어 뒀다.

 

그리고 통계가 새로 생기면 플래너 선택이 바뀔 수 있으므로 검색 경로를 다시 쟀다.
인덱스 선택 동일, 지연 100.0 / 100.3 ms. 회귀 없음.

---

내 작업 방식에 대해 남는 것

1. 네 번 틀렸고, 네 번 다 측정이 고쳤다.
임베딩 → 배열 → (락) → 긴 텍스트 → 콜레이션.
내 사전 지식은 매번 그럴듯한 가설을 만들어냈고 매번 틀렸다.
이 도메인에서 내 직관의 타율은 0할이었다. 쓸모가 있었던 건 직관이 아니라 다음 실험을 설계하는 능력이었다.

 

2. 가장 위험한 것은 틀린 가설이 아니라 «가지런한 숫자»였다.
40, 45, 45, 45, 45... 이건 오류처럼 보이지 않는다. 발견처럼 보인다.
그걸 살린 건 도메인 지식이 아니라 산술적 부조리 감각이었다 —
고유값 2개짜리 컬럼이 45초일 수는 없다.

틀린 측정은 "이상해 보이는" 얼굴이 아니라 "일관돼 보이는" 얼굴로 온다.

3. 변인을 하나만 남기기까지 너무 오래 걸렸다.
콜레이션 실험은 2분이면 되는 일이었다. 그걸 네 번째 가설이 깨진 뒤에야 했다.
앞의 세 가설은 전부 "비싸 보이는 것"을 찾는 방식이었지 변인을 통제하는 방식이 아니었다.
비싸 보이는 후보를 하나씩 지우는 것과, 같은 데이터에서 한 변수만 바꾸는 것은 다른 일이다.

후자가 훨씬 빨랐을 것이다.

 

4. 도구도 조용히 거짓말한다.
psql -c는 SQL 문자열이나 백슬래시 명령 «하나»만 받는다.
\timing on을 SQL과 같은 -c에 넣은 내 첫 측정 스크립트는
에러 없이 빈 결과를 냈다. 25개 컬럼이 전부 빈칸으로 나왔다.
실패가 실패처럼 보이지 않는 경우가 이 세션에만 세 번 있었다
(이것, 락 대기, 그리고 ::halfvec 캐스트 불일치가 Seq Scan으로 조용히 떨어지는 것).

 

5. 모르는 것을 모른다고 적는 것도 결과다.
이 세션에는 끝내 못 밝힌 것이 하나 있다.
pg_prewarm으로 인덱스를 shared_buffers에 올리면 디스크 읽기가 11,504→31 블록으로 사라지는데
오히려 55ms→84ms로 느려진다. 2회 재현했고 원인은 규명하지 못했다.

그럴듯한 후보(호스트 메모리 포화)는 있었지만 지표가 뒷받침하지 않았다.
그래서 추정을 적지 않고 docker-compose.yml 주석에 "원인 미규명이므로 prewarm 하지 말 것"으로 남겼다.
틀린 설명은 없는 설명보다 나쁘다. 다음 사람이 그 설명을 믿고 잘못된 곳을 팔 테니까.

---

다음에 같은 증상을 만나면

1. pg_stat_progress_analyze의 sample_blks_*를 먼저 본다 — 100%면 I/O가 아니라 연산이다
2. 다른 ANALYZE가 도는지 pg_locks에서 granted=f를 확인한다 (이걸 건너뛰면 전부 오측정된다)
3. 같은 스키마의 30,000행 표본을 만든다 — 본 테이블과 같은 시간이 걸린다
4. ANALYZE tbl (col)로 컬럼 하나씩 끊어 잰다
5. 범인이 텍스트면 같은 데이터를 COLLATE "C"로 복사해 한 번 더 잰다 — 콜레이션인지 여기서 갈린다
6. 플래너가 안 쓰는 컬럼이면 SET STATISTICS 0, 쓰는 컬럼이면 목표치를 낮춘다