떠 있는데 이상하다 — 무엇을 먼저 보는가

한 줄 요약

장애 대응에서 비싼 것은 고치는 일이 아니라 어디가 원인인지 가려내는 일이다. 데이터베이스는 대개 죽지 않는다. 떠 있는 채로 이상해지고, 그때 증상이 보이는 자리와 원인이 있는 자리는 거의 언제나 다르다.

왜 이게 필요했나

주문 API 두 개가 응답을 안 한다. 오류도 아니고 타임아웃도 아니고, 그냥 안 돌아온다.

먼저 하는 일은 정해져 있다. 느린 쿼리를 본다. 그런데 목록이 비어 있다. CPU 도 한가하고, 디스크도 놀고 있고, 커넥션 수도 평소와 같다. 지표가 전부 초록불이다. 여기서 "DB 는 멀쩡한데?" 라고 결론 내리고 애플리케이션 쪽을 뒤지기 시작하면 그날 하루가 날아간다.

지표가 초록불인 데는 이유가 있다. 아무도 일을 하고 있지 않기 때문이다. 다들 기다리고 있다. 기다리는 세션은 CPU 를 쓰지 않고, 디스크도 건드리지 않고, 느린 쿼리 목록에도 오르지 않는다. 그리고 그들을 붙잡고 있는 세션은 쿼리를 돌리고 있지조차 않다.

어떻게 동작하나

pg_stat_activity 한 뷰에 필요한 것이 거의 다 있다. 읽는 순서가 있다.

| 컬럼 | 무엇을 말해 주나 |
| --- | --- |
| state | active 는 지금 쿼리를 돌리는 중, idle 은 트랜잭션 밖에서 노는 중, idle in transaction 은 트랜잭션을 열어 놓고 노는 중 |
| wait_event_type · wait_event | 무엇을 기다리는가. Lock 이면 잠금 대기, Client · ClientRead 면 클라이언트가 다음 명령을 안 보내는 것 |
| xact_start | 트랜잭션이 시작된 시각. 이게 오래됐다는 사실 하나가 대부분의 사고를 설명한다 |
| pg_blocking_pids(pid) | 이 세션을 막고 있는 pid 목록 |

state 의 셋째 값이 핵심이다. idle in transaction 과 ClientRead 가 같이 있으면, 그 세션은 일을 시켜 놓고 사라진 클라이언트를 기다리고 있다는 뜻이다. 서버 입장에서는 아무 잘못이 없고, 그래서 어떤 경고도 울리지 않는다.

사슬을 한 단계만 따라가면 피해자가 나온다

이 코스의 실습 환경에서 그대로 찍은 화면이다.

 pid  | application_name |        state        | wait_event_type |  wait_event   | blocked_by------+------------------+---------------------+-----------------+---------------+-----------  784 | nightly-batch    | idle in transaction | Client          | ClientRead    | {}  796 | api-cart         | active              | Lock            | transactionid | {784}  795 | api-order        | active              | Lock            | tuple         | {796}

api-order 가 막혀 있다. 누가 막았느냐고 물으면 답은 796 이다. 그런데 796 도 막혀 있다. 796 을 끊어 봐야 795 는 곧바로 다음 차례를 기다릴 뿐이고, 진짜 원인인 784 는 그대로 남는다.

그래서 물어야 할 것은 "누가 나를 막았나" 가 아니라 "막힌 사람이 아무도 없는 지점이 어디인가" 이다.

select distinct b as root_pid  from pg_stat_activity a, unnest(pg_blocking_pids(a.pid)) b where cardinality(pg_blocking_pids(b)) = 0;

남을 막고 있으면서 자기는 아무에게도 막혀 있지 않은 pid — 그게 사슬의 끝이다. 위 화면에서는 784 하나가 나온다.

wait_event 도 그냥 지나치면 안 된다. transactionid 는 "앞 트랜잭션이 끝나기를 기다린다" 이고, tuple 은 "같은 행을 노리는 대기 줄에서 내 앞사람을 기다린다" 이다. 두 값이 섞여 있으면 대기 줄이 이미 두 겹이라는 뜻이다.

커넥션은 어디로 사라지나

기다리는 세션은 커넥션을 하나씩 물고 있다. 이게 이 고장이 번지는 방식이다.

lock_timeout 의 기본값은 0, 즉 무제한이다. 한도를 걸면 이렇게 끝난다.

ERROR:  55P03: canceling statement due to lock timeout

1초 뒤 오류로 돌아오고 커넥션은 즉시 풀에 반납된다. 한도가 없으면 그 커넥션은 영원히 묶이고, 같은 행에 요청이 몰릴수록 묶인 커넥션이 늘어난다. 풀이 바닥나는 순간부터는 그 행과 아무 상관 없는 요청까지 커넥션을 못 받아 실패한다.

증상이 "DB 가 느리다" 가 아니라 "서버가 응답을 안 한다" 로 나타나는 이유가 이것이고, 그래서 이 사고는 데이터베이스가 아니라 애플리케이션 문제로 오진되기 쉽다.

max_connections 를 올리는 것은 첫 수가 아니다. 커넥션이 모자란 게 아니라 반납이 안 되고 있는 것이라, 한도를 올리면 묶이는 커넥션의 상한만 올라간다. 백엔드 하나마다 프로세스가 하나씩 뜨므로 메모리와 컨텍스트 스위치 비용은 정직하게 늘어난다. 먼저 할 일은 왜 반납이 안 되는지를 찾는 것이다.

현장에서 만나는 모습

첫째, 감시 지표에 '가장 오래된 트랜잭션의 나이' 를 넣는다. 느린 쿼리만 보는 감시는 idle in transaction 을 영원히 못 잡는다. 쿼리를 돌리고 있지 않으니 잡힐 자리가 없다. 한 줄이면 된다.

select max(now() - xact_start) as oldest  from pg_stat_activity where state <> 'idle';

이 값 하나가 이 코스에서 다루는 사고의 절반을 미리 알려 준다.

둘째, 한도는 코드가 아니라 커넥션에 건다. 쿼리마다 set lock_timeout 을 넣는 방식은 언젠가 빠뜨린다. 풀이 커넥션을 빌려줄 때 세션 기본값으로 걸어 두면 빠뜨릴 자리가 없어진다. lock_timeout 은 '기다리는' 한도, idle_in_transaction_session_timeout 은 '트랜잭션을 열어 놓고 노는' 한도라 서로 다른 사고를 막는다. 실습 환경에서 뒤엣것을 3초로 걸어 두고 확인해 보니, 놀고 있던 세션이 그대로 끊겨 사라졌다.

셋째, 마이그레이션에는 반드시 lock_timeout 을 건다. alter table 은 ACCESS EXCLUSIVE 를 요구한다. 같은 환경에서 그 잠금을 잡아 두고 select count(*) 를 해 봤더니 읽기까지 그대로 막혔다.

ERROR:  canceling statement due to lock timeoutLINE 1: select count(*) from products

앞에 긴 쿼리 하나만 있으면 마이그레이션이 대기열에 들어가고, 그 뒤에 오는 모든 쿼리가 마이그레이션 뒤에 줄을 선다. 읽기까지 포함해서다. 한도를 걸어 두면 배포가 실패할 뿐이지만, 걸지 않으면 서비스가 멈춘다. 실패하는 배포가 멈추는 서비스보다 싸다.

다음 퀴즈에서 확인할 것

사슬의 끝을 찾는 기준, idle in transaction 이 감시에 안 잡히는 이유, 그리고 max_connections 를 올리는 것이 왜 첫 수가 아닌지를 확인한다.