같은 코드인데 오후가 되면 여덟 배 느려진다
봇은 판단에 쓸 분 단위 시세를 자체 캐시에 쌓아둔다. 갱신 루프가 종목을 차례로 돌며 최신 분봉을 받아 채운다. 캐시를 항상 최신으로 유지하는 것이 이 루프의 유일한 목적이다.
한 바퀴 도는 데 걸린 시간을 하루치로 재봤다.
| 시각 | 한 바퀴 |
|---|---|
| 09:01 | 33.4초 |
| 14:30 | 364.2초 |
코드는 그대로다. 종목 수도 그대로다. 그런데 오후에는 한 바퀴가 여섯 분을 넘었다.
원인은 응답이 시간에 비례해 커진다는 것이었다
시세 API가 분봉을 주는 방식이 이렇다. 요청할 때마다 당일 누적 분봉을 전부 돌려준다. 마지막 한 개만 달라고 할 수 없다.
장 시작 직후에는 봉이 몇 개뿐이니 응답이 가볍다. 오후가 되면 같은 요청에 수백 개가 따라온다. 요청 횟수는 같은데 한 번의 요청이 처리해야 할 양이 장 시간에 비례해 자란다.
루프는 잘못한 게 없다. 루프가 부르는 API의 성격이 그랬고, 나는 그 성격을 한 바퀴 비용으로 환산해본 적이 없었다.
진짜 피해는 루프 바깥에 났다
여기까지는 성능 문제다. 한 바퀴가 여섯 분이면 느린 것뿐이라고 생각하기 쉽다.
그런데 이 캐시에는 읽는 쪽이 있다. 캐시를 읽어 종목을 줄 세우고 볼 만한 것을 고르는 표다. 한 바퀴가 여섯 분이면, 그 표가 읽는 값은 최대 여섯 분 전 시세다.
표에서 신선하다고 볼 수 있는 종목이 어떻게 줄었는지 따라가 봤다. 장 초반에는 대부분이 신선했다. 정오를 지나며 열 종목 남짓으로 줄었고, 오후 늦게는 한 종목이었다. 나머지는 전부 낡은 값으로 줄을 서고 있었다.
최신으로 유지하려고 만든 루프가, 느려지면서 캐시를 낡게 만들고 있었다.
8분 지연이 순위를 뒤집었다
낡은 값이 얼마나 문제인지 한 종목으로 확인했다. 같은 종목의 같은 지표를 8분 낡은 값으로 재는 것과 최신 값으로 재는 것을 비교했다.
백분위가 2.2에서 59.6으로 움직였다. 전체에서 거의 바닥에 있던 종목이 한가운데로 올라온 것이다. 8분이면 분봉 여덟 개다.
순위를 매기는 표에서 이 정도 이동은 선택과 탈락을 가른다. 표는 틀린 값을 쓴 것이 아니라 한때 맞았던 값을 쓰고 있었고, 그것이 더 까다롭다. 값 자체는 어디까지나 실제로 있었던 시세라서 검산으로 걸러지지 않는다.
가장 나빴던 것은 이게 안 보였다는 점이다
표에는 종목마다 캐시에 쌓인 봉 개수를 적는 열이 있었다. 신선도를 감시하려고 만들어둔 열이다.
그 열이 무력했다. 전 종목이 같이 밀리면 숫자가 나란해서 정상처럼 보인다.
이 열은 원래 "다른 종목보다 이 종목만 덜 채워졌다"를 잡으라고 만든 것이었다. 즉 종목 간 상대 지연을 본다. 그런데 루프가 전체적으로 느려지는 상황에서는 모든 종목이 똑같이 밀리므로 편차가 생기지 않는다. 열은 가지런한 숫자를 보여주고, 가지런한 숫자는 문제없어 보인다.
💡 전부가 같이 틀리면 편차가 0이 되고, 편차를 보는 감시는 그 순간 아무것도 감시하지 않는다. 상대값으로 만든 지표는 전체가 한 방향으로 움직이는 고장을 원리상 못 잡는다.
남은 것
응답 크기가 시간에 비례하는 API는 루프 비용도 시간에 비례한다. 설계할 때는 한 번 호출해보고 걸린 시간으로 예산을 잡게 되는데, 그 한 번이 대개 장 시작 직후다. 가장 가벼운 순간의 값으로 하루치를 계획한 셈이었다. 이런 API는 가장 무거운 시점으로 예산을 잡아야 한다.
느려진 루프는 성능 문제로 끝나지 않는다. 캐시를 채우는 루프가 느려지면 그것은 읽는 쪽에서 데이터 품질 문제로 나타난다. 그리고 읽는 쪽은 자기가 낡은 값을 보고 있다는 사실을 알 방법이 없다. 느려진 쪽과 손해 보는 쪽이 다르면 원인 추적이 한 단계 멀어진다.
신선도는 절대 시각으로 잰다. 개수나 상대 비교가 아니라 "이 값이 몇 분 전 것인가"를 값마다 붙여두고, 그 나이가 임계를 넘으면 쓰지 않거나 경고한다. 남들보다 얼마나 뒤졌는지가 아니라 지금으로부터 얼마나 뒤졌는지를 물어야 한다.
감시 지표를 만들 때 "전부가 같이 고장 나면 이 지표가 어떻게 보이는가"를 한 번 물어본다. 이 질문에 "정상으로 보인다"가 답이면 그 지표는 가장 중요한 고장을 못 잡는다.