요청 밖으로 뺀 무거운 계산

주문을 넣을 때 삼 초가 걸렸다. 그중 대부분이 주문 자체가 아닌 것이었다.

Table of contents

증상 — 주문 한 건에 삼 초

어디에서 시간을 쓰는지부터 갈라야 해서 주문 등록 안의 호출마다 구간을 찍었다.

주문 저장          120ms
재고 차감           80ms
추천 지수 갱신     1,840ms   ←
알림 발송           520ms
통계 반영           410ms
적립금 계산         180ms

추천 지수 갱신이 1.8초였다. 그 상품과 비슷한 상품을 그 자리에서 다시 계산하고 있었다.

주문을 INSERT 하는 것 자체는 120밀리초였고 재고를 줄이는 UPDATE 도 그와 비슷했다. 삼 초 중에서 주문이 성립하는 데 쓰인 시간은 오분의 일이 되지 않았다.

나머지는 주문과 관련은 있지만 주문이 성립하는 조건은 아닌 것들이었다. 그것들이 같은 요청 안에 줄줄이 붙어 있어서 사용자가 그 시간을 전부 기다리고 있었다.

판단 기준 — 실패하면 취소해야 하는가

무엇을 빼도 되는지 정할 기준이 필요했는데 처음에는 중요도로 나누려다 막혔다.

알림이 중요한지 통계가 중요한지를 두고 이야기가 좁혀지지 않았다. 중요도는 사람마다 다르게 읽히는 말이어서 같은 표를 보고도 결론이 갈렸다.

기준을 바꿔서 이것이 실패하면 주문을 취소해야 하는지를 물었다. 이 질문에는 답이 한쪽으로만 나왔고 더 이야기할 것이 없었다.

그 기준으로 여섯 가지를 두 무더기로 갈랐다.

지금 해야 하는 것
  주문 저장       주문이 안 되면 의미가 없다
  재고 차감       재고가 없으면 주문을 받으면 안 된다
  적립금 계산     화면에 바로 보여야 한다

나중에 해도 되는 것
  추천 지수       몇 분 늦어도 된다
  알림            몇 초 늦어도 된다
  통계            시간 단위로 집계한다

추천 지수 갱신이 실패해도 주문은 유효하다. 적립금은 화면에 바로 보여야 해서 안에 남겼다.

조치 — 나중에 할 것을 큐로 뺐다

트랜잭션 안에서는 지금 해야 하는 것만 하고 나머지는 queue 로 넘겼다.

$db->transaction(function () use ($order, &$events) {
    $this->orders->save($order);
    $this->stock->deduct($order);
    $this->point->calculate($order);
    $events[] = new OrderPlaced($order->no);
});

foreach ($events as $e) { $this->queue->push($e); }

save 와 deduct 와 calculate 만 트랜잭션 안에 두고 OrderPlaced 는 밖에서 밀어 넣는다.

빠져나간 것들은 워커가 queue 에서 꺼내 순서대로 처리한다. 사용자가 보는 화면은 주문 번호가 나온 시점에 끝나고 나머지는 뒤에서 이어진다.

줄어든 시간이 계산에서 사라진 것은 아니다. 같은 1.8초를 여전히 쓰지만 그것을 기다리는 쪽이 사용자에서 워커로 옮겨 간 것이다.

응답 시간은 이렇게 바뀌었다.

3,150ms → 380ms

380밀리초 중 남은 것은 인증과 조회에 쓰는 시간이라 더 줄일 여지가 많지 않았다.

커밋 전에 넣으면 워커가 못 찾는다

queue 에 넣는 줄을 트랜잭션 안에 두면 안 됐다.

// 이렇게 하면 안 된다
$db->transaction(function () use ($order) {
    $this->orders->save($order);
    $this->queue->push(new OrderPlaced($order->no));   // 아직 커밋 전이다
});

워커가 빨리 꺼내면 아직 커밋되지 않은 주문을 조회해서 없다고 나온다.

재현이 잘 안 되는 종류였다. 워커가 한가할 때만 push 와 COMMIT 사이를 파고들어서 오히려 부하가 낮은 새벽에 더 자주 났다.

커밋 뒤에 넣으면 그 사이에 프로세스가 죽었을 때 queue 에 안 들어간다. 그 경우를 다루려고 표를 하나 뒀다.

$db->transaction(function () use ($order) {
    $this->orders->save($order);
    $this->outbox->insert('OrderPlaced', $order->no);   // 같은 트랜잭션
});

outbox 에 남긴 줄과 주문이 같이 커밋되고 별도 배치가 그 표를 읽어 queue 로 옮긴다.

주문이 저장됐는데 outbox 만 비어 있는 상태는 생기지 않는다. 둘이 같은 트랜잭션이라 함께 남거나 함께 사라진다.

배치가 한 번 실패해도 표가 남아 있으니 다음 회차가 같은 줄을 다시 집어 간다. queue 로 옮긴 뒤에 표시를 지우는 순서를 지켜야 그 성질이 유지된다.

주의 — 워커가 못 따라가는 경우

밖으로 빼면 큐가 밀릴 수 있어서 대기 수를 계속 남겼다.

14:00  대기 12
15:00  대기 840
16:00  대기 3,200

늘고 있으면 워커가 부족한 것이고 이 표는 주문이 몰린 날의 기록이다.

얼마나 늦어지는지도 함께 쟀다.

$delay = time() - $event->createdAt;
Metrics::observe('queue.delay', $delay);

createdAt 과 지금의 차를 queue.delay 로 남기고 임계를 넘으면 알린다.

추천 지수가 십 분 늦는 것은 문제가 아니지만 두 시간 늦으면 문제였다. 늦어도 되는 일에도 얼마나 늦어도 되는지가 따로 있었다.

대기 수만 보면 워커가 쉬는 시간에는 줄어든 것처럼 보인다. 처리된 것과 밀린 것을 같은 수로 세기 때문에 queue.delay 를 함께 봐야 지금 상태가 갈렸다.

대응 — 조용히 실패하는 것을 모았다

요청 안에 있을 때는 실패하면 화면에 나왔는데 밖으로 빼니 아무 데도 안 나온다.

try {
    $handler->handle($event);
    $this->queue->ack($event);
} catch (Throwable $e) {
    $event->attempts++;
    if ($event->attempts >= 5) {
        $this->deadLetter->push($event, $e->getMessage());
        log_error("5회 실패로 보류: {$event->type} {$event->refNo}");
    } else {
        $this->queue->retryAfter($event, 60 * $event->attempts);
    }
}

다섯 번까지는 retryAfter 로 간격을 늘려 가며 다시 넣고 그 뒤에는 deadLetter 로 보낸다.

모아 둔 것을 매일 아침에 확인하는 일을 누가 하는지도 같이 정했다. 쌓이는 자리만 만들고 보는 사람이 없으면 전과 다를 것이 없다.

화면에서 무엇이 달라지는지는 기획 쪽에 하나씩 물었다. 추천이 몇 분 뒤에 갱신되는 것은 괜찮다고 했고 결제 완료 알림은 바로 가야 한다고 해서 그것만 요청 안에 남겼다.

정리

• 요청 안에서 무엇에 시간을 쓰는지 구간별로 나눈다
• 중요도로 나누면 사람마다 다르게 읽힌다
• 실패하면 주문을 취소해야 하는가로 지금 할 것과 나중에 할 것을 가른다
• queue 에 넣는 줄을 트랜잭션 안에 두면 아직 커밋 전이다
• 커밋 뒤에 넣으면 그 사이에 죽는 경우가 있다
• 같은 트랜잭션에 outbox 를 남기고 배치가 옮긴다
• 밖으로 빼면 밀릴 수 있으므로 대기 수와 queue.delay 를 남긴다
• 조용히 실패하게 되므로 deadLetter 를 모으고 보는 사람을 정한다
• 전부 빼지 않고 하나씩 물어서 화면 변화를 확인한다