order-cancel 토픽의 취소 처리가 멈춰서 로그를 뒤지니 관련 예외는 하루 넘게 전부터 있었다. 그런데 그 하루 동안은 처리가 정상이었다. 그때는 괜찮았고 지금은 멈춘 이유를 설명해야 했다. 지표는 records-consumed-rate 와 commit-rate 로 봤다.
Table of contents
Open Table of contents
조치 — 두 지표의 분리 측정
예외 발생 시각만 보면 전날 오전이고 처리가 멈춘 시각은 다음 날 오후다. 이 둘을 하나로 보면 설명이 안 되므로 두 지표를 시간대별로 나눠 쟀다. poll() 로 메시지를 꺼낸 횟수와 commitSync() 까지 끝낸 횟수다.
전날 오전부터 다음 날 오후 초입까지는 가져간 것이 시간당 수십 건이었고 처리도 그만큼 끝났다. 예외가 나긴 했지만 산발적이었고 나머지는 정상으로 흘렀다. 그 뒤부터 숫자가 뒤집혀서 가져간 것이 시간당 수백 건으로 뛰는 동안 커밋은 0이 됐다.
원인 — 재시도 루프로 넘어간 지점
예외 발생률이 시간당 수십 건에서 수백 건으로 뛴 시점이 있었고 수십 밀리초 간격의 연속 발생이었다. 그때부터 같은 offset 의 메시지가 계속 다시 꺼내지고 있었다. 처리에 실패하니 오프셋을 커밋하지 못하고 커밋하지 못하니 다음 poll() 이 또 같은 것을 꺼낸다. Kafka 공식 문서의 설계 항목대로 컨슈머의 위치는 파티션마다 정수 하나인 다음 읽을 오프셋이고 파티션 안은 전순서라, 그 하나가 안 넘어가면 뒤는 전부 기다린다.
그 메시지 하나가 파티션 전체를 막았고 뒤에 있던 정상 메시지는 순서상 그 뒤라 차례가 오지 않았다. 막힌 메시지를 처리하는 데는 두 가지 방법이 있었는데 그 메시지를 건너뛰고 오프셋을 손으로 올리는 것과 실패한 메시지를 별도 토픽 order-cancel-dlq 로 보내고 커밋하는 것이다. 뒤쪽을 골랐다. 이유는 건너뛴 메시지는 어디에도 남지 않아서다. 대신 실패 토픽을 소비하는 경로를 하나 더 만드는 것을 감수했다. 근거는 건너뛴 오프셋이 로그에만 남고 로그는 아무도 다시 읽지 않는다는 점이다. 예외가 있는 것과 진행이 막히는 것은 다르다. 산발적일 때는 실패한 건만 빠지고 나머지가 흐르지만 특정 밀도를 넘으면 실패한 건이 뒤를 막는다. 그 전환점이 실제 정지 시각이다.
판단 기준 — 전환점을 찾는 방법
ERROR 로그의 첫 시각과 consumer lag 이 오르기 시작한 시각이 다를 수 있다고 먼저 가정하는 것이 이 조사의 출발점이었다. 같다고 보면 왜 전날부터 안 멈췄는지에서 막히고 다르다고 보면 언제 전환됐는지를 찾게 된다.
전환을 찾으려면 두 지표를 함께 봐야 한다. 예외 건수만 보면 전날 오전이 나오고 consumer lag 만 보면 다음 날 오후가 나오는데, 둘을 겹쳐 놓으면 두 곡선이 갈라지는 지점이 드러난다. 한 지표만으로는 어느 시각을 골라도 절반만 설명된다.
같은 구조의 다른 사례
배포 후 오류가 났을 때도 같은 모양이었다. /image/resize 의 처리 시간이 늘어난 것은 배포 시점부터인데 504 시간 초과가 난 것은 며칠 뒤 요청이 몰린 특정 시간대였다.
처리 시간 증가만으로는 한계치에 안 닿고 php-fpm 의 동시 처리 수가 늘어야 대기가 쌓여 닿는다. 원인은 배포 시점에 들어왔고 발현은 부하가 겹친 시점이다. 이 구조에서 배포를 되돌리면 증상은 멎지만 부하가 더 커지면 되돌린 상태에서도 같은 일이 난다.
원인과 발현의 간격
간격이 더 긴 경우도 봤다. 이미지 실체를 지연 삭제 큐 media-purge 에 넣고 media 참조 행은 즉시 지웠는데 외부 마켓은 옛 참조를 그대로 들고 있었다. 아직 S3 의 실체가 살아 있어서 화면은 정상이다.
지연 삭제 큐가 그것을 소비하는 순간 전부 깨진다. 지금 정상인 것은 문제가 없어서가 아니라 아직 그 시점이 오지 않았기 때문이다. 원인과 발현의 간격이 며칠에서 몇 주이므로 발현했을 때 그 시점에서만 원인을 찾으면 아무것도 안 나온다.
정리
- 오류 발생 시각과 처리 정지 시각은 다를 수 있다
- 먼저 다르다고 가정해야 전환점을 찾게 된다
- 산발적 실패는 그 건만 빠지고 밀도를 넘으면 뒤를 막는다
poll()수와 커밋 수를 함께 재야 갈라지는 지점이 보인다- 오프셋을 커밋하지 못하는 실패는 같은 것을 무한 반복한다
- 원인이 들어온 시점과 발현 시점의 간격이 며칠일 수 있다
- 지금 정상인 것이 문제가 없다는 뜻은 아니다