취소 처리가 멈춰서 로그를 뒤지니 관련 예외는 29시간 전부터 있었다. 그런데 그 29시간 동안은 처리가 정상이었다. 그때는 괜찮았고 지금은 멈춘 이유를 설명해야 했다.
Table of contents
Open Table of contents
두 지표의 분리 측정
예외 발생 시각만 보면 전날 오전 9시이고 처리가 멈춘 시각은 다음 날 오후 2시다. 이 둘을 하나로 보면 설명이 안 되므로 두 지표를 시간대별로 나눠 쟀다. 큐에서 메시지를 꺼낸 횟수와 실제로 처리를 끝낸 횟수다.
전날 오전부터 다음 날 오후 1시 반까지는 가져간 것이 시간당 64건에서 68건 사이였고 처리도 그만큼 끝났다. 예외가 나긴 했지만 산발적이었고 나머지는 정상으로 흘렀다. 오후 2시부터 숫자가 뒤집혀서 가져간 것이 시간당 478건과 768건으로 뛰는 동안 처리 완료는 0이 됐다.
재시도 루프로 넘어간 지점
예외 발생률이 시간당 30건에서 720건으로 뛴 시점이 있었고 34밀리초 간격의 연속 발생이었다. 그때부터 같은 메시지가 계속 다시 꺼내지고 있었다. 처리에 실패하니 진행 위치를 확정하지 못하고 확정하지 못하니 다음번에 또 같은 것을 꺼낸다.
그 메시지 하나가 파티션 전체를 막았고 뒤에 있던 정상 메시지는 순서상 그 뒤라 차례가 오지 않았다. 예외가 있는 것과 진행이 막히는 것은 다르다. 산발적일 때는 실패한 건만 빠지고 나머지가 흐르지만 특정 밀도를 넘으면 실패한 건이 뒤를 막는다. 그 전환점이 실제 정지 시각이다.
전환점을 찾는 방법
원인 시각과 장애 시각이 다를 수 있다고 먼저 가정하는 것이 이 조사의 출발점이었다. 같다고 보면 왜 전날부터 안 멈췄는지에서 막히고 다르다고 보면 언제 전환됐는지를 찾게 된다.
전환을 찾으려면 두 지표를 함께 봐야 한다. 예외 건수만 보면 전날 오전이 나오고 처리 완료만 보면 다음 날 오후가 나오는데, 둘을 겹쳐 놓으면 두 곡선이 갈라지는 지점이 드러난다. 한 지표만으로는 어느 시각을 골라도 절반만 설명된다.
같은 구조의 다른 사례
배포 후 오류가 났을 때도 같은 모양이었다. 이미지 처리 시간이 늘어난 것은 배포 시점부터인데 시간 초과가 난 것은 며칠 뒤 요청이 몰린 특정 시간대였다.
처리 시간 증가만으로는 한계치에 안 닿고 동시 처리 수가 늘어야 대기가 쌓여 닿는다. 원인은 배포 시점에 들어왔고 발현은 부하가 겹친 시점이다. 이 구조에서 배포를 되돌리면 증상은 멎지만 부하가 더 커지면 되돌린 상태에서도 같은 일이 난다.
원인과 발현의 간격
간격이 더 긴 경우도 봤다. 이미지 실체를 지연 삭제 큐에 넣고 참조 행은 즉시 지웠는데 외부 마켓은 옛 참조를 그대로 들고 있었다. 아직 실체가 살아 있어서 화면은 정상이다.
지연 삭제 큐가 그것을 소비하는 순간 전부 깨진다. 지금 정상인 것은 문제가 없어서가 아니라 아직 그 시점이 오지 않았기 때문이다. 원인과 발현의 간격이 며칠에서 몇 주이므로 발현했을 때 그 시점에서만 원인을 찾으면 아무것도 안 나온다.
정리
- 오류 발생 시각과 처리 정지 시각은 다를 수 있다
- 먼저 다르다고 가정해야 전환점을 찾게 된다
- 산발적 실패는 그 건만 빠지고 밀도를 넘으면 뒤를 막는다
- 가져간 수와 완료한 수를 함께 재야 갈라지는 지점이 보인다
- 진행 위치를 확정하지 못하는 실패는 같은 것을 무한 반복한다
- 원인이 들어온 시점과 발현 시점의 간격이 며칠일 수 있다
- 지금 정상인 것이 문제가 없다는 뜻은 아니다