autovacuum이 돌고 있는 줄 알았다

autovacuum이 돌고 있는 줄 알았다

지난주에 PostgreSQL 디스크가 갑자기 부풀어오르는 사건이 있었다. 정확히는 이미 며칠 전부터 부풀고 있었는데, 우리가 늦게 알아챈 거다.

처음에는 단순히 "데이터가 많아져서 그렇겠지" 생각했다. 그런데 dead tuple 비율을 찍어보니 40%를 넘기고 있었다. 어떤 테이블은 60%. 라이브 row보다 죽은 row가 더 많은 상태였다. autovacuum 로그를 뒤져보니 마지막 vacuum이 4일 전에 멈춰 있었다. 그리고 그 사이에 누가 무엇을 했는지 추적이 시작됐다.

pg_stat_activity가 말해준 것

pg_stat_activity 뷰를 열어보니 한 세션이 4일째 살아 있었다. state는 idle in transaction. xact_start는 월요일 새벽. 우리가 발견한 건 금요일 오후.

SELECT pid, usename, application_name, state,
       xact_start, query_start,
       now() - xact_start AS xact_age,
       backend_xmin
FROM pg_stat_activity
WHERE state IS NOT NULL
ORDER BY xact_start NULLS LAST;

문제의 세션은 BI 도구에서 떠 있던 connection이었다. 누군가 분석 쿼리를 돌리다가 트랜잭션을 닫지 않고 그대로 자리를 비웠다. application은 살아 있었고, connection pool은 그 세션을 keep-alive로 유지 중이었다. autocommit이 꺼진 채로.

backend_xmin 값이 오래 박혀 있으면 MVCC 입장에서 그 트랜잭션이 볼 수도 있는 row를 함부로 정리할 수 없다. autovacuum은 매 분마다 호출되고 있었지만, 작업 가능한 dead tuple이 없다고 판단해서 cleanup 없이 돌아갔다. 로그에는 "removed 0 row versions" 같은 줄만 잔뜩.

이걸 처음 봤을 때 솔직히 멘탈이 살짝 나갔다. 그동안 autovacuum 튜닝을 한답시고 autovacuum_vacuum_scale_factor를 0.05까지 내려놨는데, 그게 무슨 소용이었나 싶었다. 더 자주 도는 게 문제가 아니라 돌아도 일을 못 하고 있던 거다.

그래서 어떻게 풀었나

선택지는 두 가지였다.

하나는 그 세션을 그냥 pg_terminate_backend로 끊는 것. 빠르고 확실하다. 다만 그 BI 사용자가 어떤 작업 중이었는지 모르니, 일단 슬랙으로 한 번 묻고 답이 없으면 끊기로 했다. 30분 기다리다가 그냥 끊었다.

SELECT pg_terminate_backend(pid)
FROM pg_stat_activity
WHERE pid = 23847;

세션을 끊자마자 다음 autovacuum 사이클에서 dead tuple이 잡히기 시작했다. 큰 테이블은 vacuum이 한 사이클에 끝나지 않아 두세 번 나눠 돌았고, 한 시간쯤 지나니 n_dead_tup 수치가 평소 수준으로 내려왔다. 디스크 사용량은 바로 줄지 않는다 (PostgreSQL은 파일 끝부분이 비었을 때만 OS에 돌려준다). 우리는 운영 시간 외에 VACUUM FULL을 돌릴지 pg_repack을 쓸지 따로 결정했다.

결국 pg_repack을 택했다. lock 없이 돌아가니까. 평일 새벽 시간에 큰 테이블 두 개만 골라서 돌렸고, 디스크가 200GB 정도 회수됐다.

모니터링이 왜 못 잡았나

사실 이 사건의 진짜 교훈은 여기에 있다. 우리 모니터링은 디스크 사용량 임계치(85%)에 알람이 걸려 있었다. 사고가 터지기 직전까지 78%였고, 그날 오후에 81%, 다음 날 87%에서 알람이 울렸다. 그제서야 우리가 들여다본 거다.

근데 dead tuple 비율, 가장 오래된 트랜잭션의 age, backend_xmin 같은 지표는 보지 않고 있었다. Grafana에 PG exporter를 붙여놓긴 했는데, replication lag와 connection 수만 보고 있었다. 이번 사건 이후로 다음 패널과 알람을 추가했다:

• max(now() - xact_start) — 가장 오래된 트랜잭션 나이. 30분 넘으면 warning, 1시간 넘으면 critical.
• idle in transaction 상태인 세션 개수.
• 테이블별 n_dead_tup / (n_live_tup + n_dead_tup) 비율. 30% 넘는 테이블이 하나라도 있으면 알람.
• 최근 autovacuum이 어떤 결과를 냈는지 (pg_stat_user_tables의 last_autovacuum과 autovacuum_count).

알람 임계치를 정할 때 좀 고민했다. 분석팀이 무거운 쿼리를 한 시간씩 돌리는 경우가 있어서, 너무 짧게 잡으면 거짓 알람이 쏟아진다. 일단 1시간으로 잡고 한 달 보면서 조정하기로 했다.

추가로, idle_in_transaction_session_timeout을 글로벌로 10분 걸어버렸다. 이게 정답인지는 아직 모르겠다. BI 도구처럼 트랜잭션이 길게 유지되는 워크로드에는 부작용이 있을 수 있어서, 일단 분석용 readonly 인스턴스에는 적용하지 않았다. 메인 OLTP에만 걸어뒀다.

-- postgresql.conf
idle_in_transaction_session_timeout = '10min'

남은 의문

여전히 풀리지 않은 부분이 있다. BI 도구의 connection pool이 왜 그 세션을 4일 동안 유지했는지는 그쪽 팀이 조사 중이다. 풀의 idle timeout은 30분으로 설정돼 있다고 들었는데, 트랜잭션이 열려 있으면 풀이 회수를 미루는 건지, 아니면 사용자가 의도적으로 살려둘 건지 아직 명확하지 않다.

또 하나는 pg_stat_activity의 backend_xmin 값을 알람의 직접 지표로 삼는 게 맞는지. xmin과 xact_start는 미묘하게 다르게 움직이는 경우가 있다 (subtransaction 등). 더 정확한 지표를 찾고 있는데, 아직 결론은 못 냈다.

혹시 비슷한 사건 겪어본 분 있으면 어떻게 풀었는지 댓글로 좀 알려주세요.