처리율 저하가 스톨은 아니다

13개 대상에 순차로 복구 작업을 돌리고 있었다. 마지막 대상에서 처리율이 급락했다.

Open Table of contents

증상 — 처리율이 급락했다

건수를 비교하니 차이가 컸다.

앞선 대상들   30분당 수천 건
이 대상       30분당 465건

30분당 465건 이라는 숫자가 스톨로 보여서 recovery 프로세스를 죽이려 했다.

kill 하기 전에 확인부터 하기로 했다. 먼저 프로세스가 살아 있는지 봤다.

pgrep -f 'recovery.*<대상>'
# 있음

pgrep -f 에 잡히니 죽은 것은 아니었다.

그런데 떠 있다는 것이 일하고 있다는 뜻은 아니다. 응답을 기다리며 멈춰 있어도 pgrep 에는 그대로 보이므로 생존 여부만으로는 갈리지 않았다.

로그 파일의 갱신 시각을 봤다.

stat -f '%m' recovery.log

recovery.log 의 mtime 이 2초 전이라 계속 쓰고 있다는 뜻이었다.

지금 무엇을 하고 있는지도 봤다.

tail -20 recovery.log

tail 에 특정 식별자의 본문 치환과 작업 삽입이 찍히고 있었다.

잠시 뒤에 다시 tail 하니 그 식별자가 다른 값으로 바뀌어 있었다. 갱신 시각과 처리 중 식별자 둘이 함께 살아 있으면 그 작업은 돌고 있는 것이다.

왜 느린지는 대상별 옵션 설정에 있었다.

다른 대상들  →  존재 확인만 (가벼움)
이 대상      →  파싱 → 백필 → 치환 갱신 → 작업 삽입

이 대상만 추가 옵션이 켜져 있어 상품당 네 단계를 한다.

파싱 과 백필 까지 붙어 단가가 크니 같은 시간에 처리되는 건수가 적다. 느려진 것이 아니라 이 대상의 정상 처리율이 원래 그것이었다.

내가 스톨의 근거로 삼은 신호가 무엇이었는지 정리했다.

[내가 본 신호]  처리 건수 증가폭
[실제 의미]     상품당 작업량이 크면 낮아진다

처리 건수 증가폭 이 스톨을 뜻하지 않고 옵션이 다르면 정상 처리율 자체가 다르다.

죽이고 재시작했으면 이렇게 됐을 것이다.

진행 중이던 작업 중단
    ↓
재시작
    ↓
같은 속도로 다시 감  (원래 그 속도니까)
    ↓
또 느리다고 판단
    ↓
반복

원래 그 속도이므로 재시작해도 같은 판단이 반복된다.

거기에 중단 지점의 부분 처리가 남는다. 판별에 몇 초면 되는데 그것을 안 하고 죽이면 진행분을 날리고 같은 자리로 돌아온다.

대상별 완주 시간 추정도 함께 고쳤다.

가벼운 옵션  →  상품당 x초
무거운 옵션  →  상품당 y초  (x 의 몇 배)

같은 건수여도 가벼운 옵션 과 무거운 옵션 에 따라 걸리는 시간이 다르다.

전체를 하나의 속도로 추정하면 같은 오해가 매번 반복된다. 단가를 알아야 총량이 나오고 느려 보인다는 인상이 조급함이 만든 신호인지도 그때 갈린다.