pg_stat_io로 새벽 3시에 vacuum I/O 폭탄 잡은 이야기

지난주 화요일 새벽 3시, 슬랙 알림이 미친 듯이 울렸다. 결제 DB의 P99 레이턴시가 평소 12ms에서 280ms로 튀어 올랐다. 폰을 더듬어 잡고 일어나면서 머리가 멍했다. 트래픽은 한산한 시간대인데 왜?

처음엔 단순한 락 경합인 줄 알았다. pg_stat_activity 봤는데 long-running 쿼리도 없고, pg_locks도 깨끗했다. 근데 디스크 IOPS는 평소 대비 4배. 뭔가 백그라운드에서 디스크를 갈아먹고 있는 게 분명한데 보이질 않았다. 멘탈이 살짝 나갔다.

pg_stat_io를 켰다

작년에 PG16으로 올리면서 pg_stat_io 뷰를 알게 됐었는데, 평상시엔 잘 안 보던 거였다. 이번 같은 상황에서 진가를 발휘하는 뷰다. context 컬럼에 bulkread, bulkwrite, vacuum, normal 같은 값이 들어가서, I/O가 어떤 종류의 작업에서 나오는지 바로 보인다.

SELECT backend_type, context, object,
       reads, writes, extends,
       hits, evictions
FROM pg_stat_io
WHERE reads > 0 OR writes > 0
ORDER BY reads + writes DESC;

결과 보자마자 답이 나왔다. autovacuum worker 백엔드 타입에 context = 'vacuum'인 행의 reads가 비정상적으로 컸다. 거기에 evictions 값도 어마어마했다. 즉, autovacuum이 큰 테이블을 훑으면서 셰어드 버퍼를 계속 밀어내고 있었고, 일반 쿼리는 캐시 미스 때문에 디스크로 다시 가야 했던 거다.

범인은 4억 row 짜리 audit 테이블

pg_stat_progress_vacuum으로 보니까 payment_audit 테이블에서 autovacuum이 돌고 있었다. 4억 row, 500GB. 트랜잭션 로그용으로 매일 수백만 row가 쌓이는 테이블이다. 근데 이상한 건, 이 테이블은 partition으로 쪼개놨는데 왜 통째로 vacuum이 도는지였다.

원인: 며칠 전 누가 ALTER TABLE payment_audit SET (autovacuum_vacuum_scale_factor = 0.01)을 적용했는데, 파티션 부모 테이블이 아니라 옛날 파티션(2024년 데이터) 하나에 적용한 걸 깜빡한 거였다. 그 파티션 하나가 dead tuple 임계치를 자주 넘기면서 매일 새벽마다 풀스캔을 돌고 있었다. 근데 평일 새벽엔 트래픽이 더 적어서 티가 안 났고, 이번 화요일은 마침 데이터 백필 잡이 같은 시간에 돌면서 폭발한 거다.

해결은 단순했다. 그 파티션의 옵션을 원복하고, 이미 물려 있던 vacuum 프로세스를 pg_cancel_backend()로 끊었다. 30초 후 IOPS가 정상으로 돌아왔다.

뒷이야기 — PG18로 더 편해진다

마침 회고하면서 사내 DB팀이 공유한 자료를 봤는데, 작년 9월에 풀린 PG18에서 pg_stat_io에 byte 단위 컬럼(read_bytes, write_bytes, extend_bytes)이 추가됐다고 한다. 이번 같은 케이스에서는 reads 카운트만으로도 잡혔지만, 8KB 블록 단위 카운트라서 큰 페이지 vs 작은 페이지 차이를 못 봤다. 바이트 단위면 "vacuum이 실제로 몇 GB를 읽었나"가 바로 나오니까 진짜 편해질 듯.

거기에 pg_stat_get_backend_io(pid) 함수도 새로 들어왔다. 특정 백엔드 한 놈만 콕 집어서 I/O 추적이 된다. 이번엔 autovacuum worker를 의심해서 운 좋게 잡았는데, 일반 백엔드 중 하나가 빌런이었으면 어떤 PID인지 좁히기 어려웠을 거다. 우리 팀에서는 이번 분기에 PG18로 올릴 계획이라 좀 더 풍성하게 디버깅할 수 있을 것 같다.

교훈

• 파티션 테이블에 옵션 걸 때는 부모/자식 어디에 거는지 무조건 확인. 이걸로 한 번 더 데일 것 같다.
• 디스크 I/O가 튀는데 쿼리에 안 보이면 pg_stat_io의 context 컬럼부터 본다. 그 한 줄로 vacuum/checkpoint/bulk read를 구분해주는 게 진짜 크다.
• evictions 값을 같이 보는 게 포인트. reads/writes만 보면 단순 I/O 부하로 끝나는데, evictions가 같이 크면 "shared buffer 압력"으로 다른 쿼리 레이턴시까지 깎아먹고 있다는 신호다.

다음에는 같은 새벽에 깨고 싶지 않다. 모니터링 대시보드에 pg_stat_io 기반 패널 하나 추가해뒀다. 다른 분들도 이런 거로 데인 적 있으면 어떻게 잡았는지 댓글로 알려주세요.