한도에 걸린 줄 알았는데, 백오프 대기를 줄이니 429 가 231회에서 0회가 됐습니다

사내 문서 지식그래프 검색 도구의 문서 엔진에 과거 문서를 백필(지난 데이터를 한꺼번에 채워 넣는 작업)하고 있었습니다. 한 회차가 몇 시간씩 걸렸습니다. 이런 작업은 느린 만큼 비용과 일정이 그대로 늘어납니다.

그런데 파이프라인이 어디서 시간을 쓰는지는 로그로 알 수 없었습니다. 로그에는 '변환·파싱 중'이라는 한 덩어리만 남아 있었습니다. 눈에 띄는 신호는 둘이었습니다. 임베딩(문장을 벡터로 바꾸는 작업) 호출에서 429(요청 한도 초과 응답)가 잔뜩 기록됐고, 국산 문서 형식 변환이 오래 걸렸습니다.

두 신호 모두 처음 짐작과 달랐습니다. 상대가 막은 것도, 코드가 느린 것도 아니었습니다. 두 번 다 우리가 필요 이상으로 기다리고 있었습니다.

429 가 231회, 더 쉬자는 생각이 먼저 들었습니다

한 회차에 429 가 231회 났습니다. 색인 작업은 429 를 받을 때마다 백오프(실패한 뒤 재시도까지 기다리는 시간을 단계적으로 늘리는 방식)에 따라 쉬었습니다. 대기 시간은 15초, 30초, 45초, 60초, 90초, 120초 순서였습니다.

이런 로그를 보면 한도에 걸렸다고 읽기 쉽습니다. 그러면 대기를 더 늘리거나 호출 방식을 바꾸는 쪽으로 생각이 갑니다. 429 앞에서 더 저렴한 모델이 답이 아니었던 기록은 따로 정리해 두었습니다.

이번에는 대기 시간을 늘리기 전에 한 가지를 먼저 확인했습니다. 색인이 쉬고 있는 바로 그 시각에, 옆 프로세스에서 같은 배치를 12번 연속으로 보내 봤습니다. 12번 모두 통과했고 건당 0.5초가 걸렸습니다.

상대가 막고 있다면 같은 시각에 보낸 요청도 429 를 받아야 합니다. 12번이 전부 통과했으니 남는 설명은 하나였습니다. 상대는 받아 줄 수 있었고, 우리가 그보다 오래 쉬고 있었습니다.

표의 위 두 줄은 똑같습니다. 로그만 읽어서는 두 경우를 구분할 수 없고, 마지막 줄에서만 차이가 드러납니다. 건당 0.5초로 12번이면 호출 시간은 6초 남짓입니다.

마지막 120초만 남기고 앞쪽 대기를 줄였습니다

대기 시간 목록을 아래처럼 바꿨습니다. 첫 대기는 15초에서 2초로 낮췄고, 마지막 120초는 그대로 뒀습니다.

변경 전: [15, 30, 45, 60, 90, 120]  (초)
변경 후: [ 2,  5, 12, 30, 60, 120]  (초)

앞쪽과 뒤쪽은 하는 일이 다릅니다. 앞쪽 단계는 일시적인 429 에 얼마나 빨리 다시 시도할지를 정합니다. 뒤쪽 단계는 진짜 한도에 걸렸을 때 상대와 우리 시스템을 보호합니다.

둘을 하나의 기다림으로 묶어 늘리면 일시적인 429 한 번에 몇 분씩 잃습니다. 앞쪽을 줄이면 그 시간을 되찾으면서 마지막 단계의 보호는 유지됩니다.

바꾼 뒤 429 는 231회에서 0회가 됐습니다. 색인이 15~120초씩 멈춰 있던 구간도 사라졌습니다. 재시도와 대기가 작업 시간을 얼마나 쓰는지는 생성 모델의 자동 재시도를 다룰 때도 본 적이 있습니다.

이 결론에는 조건이 있습니다. 임베딩 제공자의 요금 등급 확인은 그때 아직 답을 기다리는 중이었습니다. 한도를 확인해서 내린 결론이 아니라, 지금 문제의 원인이 한도가 아니라는 것을 실측으로 보인 것입니다.

진짜 한도에 걸린 계정에서 첫 대기를 2초로 줄이면 상황이 더 나빠집니다. 이 값은 쉬는 시각에도 통과한다는 것을 확인한 뒤의 조정이고, 일반 권장값이 아닙니다

옆에서 보내는 요청도 한도를 씁니다. 십수 번 정도에서 멈추고, 과금되는 호출이면 그 비용도 계산에 넣습니다

67.8초 중 95%는 변환이 아니라 락 대기였습니다

두 번째 신호인 국산 문서 형식 변환도 같은 방식으로 확인했습니다. 로그에는 67.8초가 걸렸다고 나왔습니다. 같은 문서를 단독으로 실행하면 3~4초였습니다. 67.8초의 95%쯤이 락 대기였습니다.

변환 코드가 느린 것이 아니라 앞선 변환이 끝나기를 기다리는 시간이었습니다. 프로파일러를 붙이기 전에 같은 입력을 혼자 실행해 본 것만으로 대부분이 설명됐습니다. 로그 시간과 단독 실행 시간의 차이가 곧 경합의 크기입니다.

동시 변환을 막아 둔 데에는 근거가 있었습니다. 변환기에 고유 프로필을 주면 필요한 확장이 따라오지 않는다는 예전 관찰이었습니다. 다시 살펴보니 이 근거는 조건부였습니다. 기본 프로필을 통째로 복제하면 확장도 런타임 설정도 함께 따라왔습니다.

확장을 공유 위치에 설치하는 안도 시도했지만 두 번 막혔습니다. 한 번은 권한 거부였습니다. 다른 한 번은 패키지를 업그레이드할 때 확장이 사라지는 문제였습니다.

프로필 복제로 동시 변환을 허용하자 변환 시간은 실제로 3초대로 줄었습니다. 프로필을 만들지 못하면 한 번에 하나씩 처리하는 방식으로 전환되게 해서 실패로 번지지 않게 했습니다.

다만 3초대는 그 회차의 값입니다. 락을 풀면 병목은 다음 단계로 옮겨갑니다. 동시성을 더 올리면 임베딩과 디스크가 다음 병목이 됩니다. 프로필 복제도 도구의 설정이 프로필 디렉토리 안에 있을 때만 성립합니다. 시스템 전역 설정을 읽는 도구라면 복제해도 따라오지 않습니다.

'변환·파싱 중'을 다섯 단계로 나눴습니다

두 원인을 확인하는 동안 로그는 도움이 되지 않았습니다. '변환·파싱 중'으로 묶여 있으면 어디서 시간을 쓰는지를 로그에 물어볼 수 없습니다. 로그를 나누는 단위가 곧 물어볼 수 있는 질문의 단위입니다. 그래서 한 덩어리를 다섯 단계로 나눴습니다.

변환 대기

변환

파싱

청킹

임베딩

단계 이름은 요청 문맥 변수(contextvar, 함수 인자로 넘기지 않아도 같은 요청 안에서 공유되는 값)로 전달했습니다. 덕분에 변환 함수를 호출하는 4곳은 수정하지 않았습니다. 1초 미만은 기록하지 않습니다.

이제 '변환 대기가 길다'와 '변환이 느리다'를 구분해서 말할 수 있습니다. 대신 1초 미만을 버리므로 짧은 단계가 많으면 합이 전체 시간과 맞지 않습니다. '어디가 느린가'에는 답하지만 '총합이 왜 이런가'에는 답하지 못합니다.

같은 관찰을 엿새 전에 이미 했습니다

정리하다 보니 놓친 것이 하나 있었습니다. 429 가 나는 시각에 옆 요청은 통과한다는 관찰을 엿새 전에 이미 했습니다. 그때 본 곳은 질문을 처리하는 경로였습니다. 그 배움을 색인 경로에는 옮기지 않았습니다.

그래서 같은 원인을 두 번 찾았고 엿새를 더 썼습니다. 이번에 추가한 절차는 하나입니다. 고칠 때 같은 코드가 또 어디 있는지 한 번 세어 봅니다.

느리다는 보고를 받으면 먼저 보는 것

두 번의 측정을 점검 항목으로 옮기면 아래와 같습니다.

로그의 단계 구분이 어디서 시간을 쓰는지에 답할 수 있는지 봅니다

429 가 많으면 쉬는 시각에 옆에서 같은 요청을 십수 번 보내 봅니다. 통과하면 백오프의 앞쪽 대기부터 줄입니다

로그 시간과 단독 실행 시간을 비교합니다. 차이가 크면 코드보다 경합을 먼저 봅니다

'A 라서 동시에 실행하지 못한다'는 제약이 있으면 A 가 아직 사실인지, 조건을 없앨 수 있는지 다시 확인합니다

한 곳을 고치면 같은 코드가 있는 다른 경로를 셉니다

이번 측정에는 한계도 있습니다. 회차 중간에 설정을 두 번 바꿔서 전체 속도가 얼마나 빨라졌는지는 깨끗하게 측정되지 않았습니다. 확인된 값은 429 가 231회에서 0회로, 변환이 67.8초에서 3초대로 줄었다는 두 가지입니다.

로그는 429 의 횟수를 보여 주지만, 그 429 가 정말 한도 때문인지는 말해 주지 않습니다. 이번에 그 답을 준 것은 쉬고 있는 그 시각에 옆에서 보낸 요청 12번이었습니다.