지갑 노드의 재스캔을 블록 구간 열셋으로 나눠 순차로 돌리고 있었다. 마지막 구간에서 처리율이 급락했다.
Table of contents
Open Table of contents
증상 — 처리율이 급락했다
블록 수를 비교하니 차이가 컸다.
앞선 구간들 30분당 수천 블록
이 구간 30분당 수백 블록30분당 수백 블록 이라는 숫자가 스톨로 보여서 bitcoind 를 죽이려 했다.
kill 하기 전에 확인부터 하기로 했다. 먼저 프로세스가 살아 있는지 봤다.
pgrep -f 'bitcoind.*-datadir=/data/btc'
# 있음pgrep -f 에 잡히니 죽은 것은 아니었다.
그런데 떠 있다는 것이 일하고 있다는 뜻은 아니다. 디스크 응답을 기다리며 멈춰 있어도 pgrep 에는 그대로 보이므로 생존 여부만으로는 갈리지 않았다.
판단 기준 — 갱신 시각과 처리 중 블록 높이
생존 말고 진행을 보는 데는 두 가지 방법이 있었는데, 로그 파일의 갱신 시각과 처리 중 블록 높이다. 먼저 갱신 시각을 봤다.
stat -c '%Y' /data/btc/debug.logdebug.log 의 mtime 이 몇 초 전이라 계속 쓰고 있다는 뜻이었다.
지금 무엇을 하고 있는지도 봤다.
tail -20 /data/btc/debug.logtail 에 Still rescanning. At block 54xxxx. Progress=0.9x 가 찍히고 있었다. Bitcoin Core 0.17 지갑 코드는 이 줄을 60초마다 남기고, 0.17.0 릴리스 노트에는 rescanblockchain 의 진행률 보고를 고친 항목도 실려 있다.
잠시 뒤에 다시 tail 하니 그 블록 높이가 더 큰 값으로 바뀌어 있었다. 갱신 시각과 처리 중 블록 높이 둘이 함께 살아 있으면 그 작업은 돌고 있는 것이다.
원인 — 블록이 만든 단가 차이
왜 느린지는 구간별 블록의 성격에 있었다.
앞선 구간들 → 블록당 트랜잭션 몇 개에서 몇백 개
이 구간 → 블록당 트랜잭션 수천 개 (최근 1년)재스캔은 블록의 모든 트랜잭션을 지갑 키와 대조하므로 블록당 비용이 트랜잭션 수에 비례한다.
Progress 값이 블록 수가 아니라 트랜잭션 양을 기준으로 오르는 것도 그래서다. 느려진 것이 아니라 이 구간의 정상 처리율이 원래 그것이었다.
주의 — 성급한 종료의 비용
내가 스톨의 근거로 삼은 신호가 무엇이었는지 정리했다.
[내가 본 신호] 블록 높이 증가폭
[실제 의미] 블록당 트랜잭션이 많으면 낮아진다블록 높이 증가폭 이 스톨을 뜻하지 않고 구간이 다르면 정상 처리율 자체가 다르다.
죽이고 재시작했으면 이렇게 됐을 것이다.
재스캔 중단 (Rescan interrupted by shutdown request)
↓
재시작 → 그 구간을 처음부터 다시
↓
같은 속도로 다시 감 (원래 그 속도니까)
↓
또 느리다고 판단
↓
반복원래 그 속도이므로 재시작해도 같은 판단이 반복된다.
거기에 중단된 구간의 진행분이 날아간다. 판별에 몇 초면 되는데 그것을 안 하고 죽이면 진행분을 날리고 같은 자리로 돌아온다. 확인 없이 죽이는 것 대신 tail 두 번을 골랐다. 이유는 두 번의 블록 높이 차이가 곧 판정이라서다.
재발 방지 — 구간별 단가로 추정
구간별 완주 시간 추정도 함께 고쳤다.
초기 구간 → 블록당 x초
최근 구간 → 블록당 y초 (x 의 몇십 배)같은 블록 수여도 초기 구간 과 최근 구간 에 따라 걸리는 시간이 다르다.
전체를 하나의 속도로 추정하면 같은 오해가 매번 반복된다. 단가를 알아야 총량이 나오고 느려 보인다는 인상이 조급함이 만든 신호인지도 그때 갈린다.
정리
- 처리율 저하가 스톨을 뜻하지 않는다
- 구간이 다르면 정상 처리율 자체가 다르다
- 스톨 판별은 로그 갱신 시각과 처리 중 블록 높이로 한다
- 프로세스 생존만으로는 부족하고 멈춰 있을 수 있다
- 성급한 종료와 재시작이 진행 중인 것을 날린다
- 재시작해도 원래 그 속도라 같은 판단이 반복된다
- 중단된 구간의 진행분이 날아간다
- 완주 시간 추정에 구간별 단가를 전제로 잡는다
- 느려 보인다는 것은 조급함이 만드는 신호다