점심 피크 타임 지연을 잠재운 Go 포스트모템

요약

주문 접수 요청은 매장 측 접수 시스템에 확인 호출을 보낸 뒤 응답을 돌려줍니다. 이 호출을 처리하는 내부 워커 풀에는 상한이 없었고, 큐가 길어질 때마다 워커를 늘리는 자동 조정이 붙어 있었습니다. 매장 시스템은 동시에 25건 남짓만 안정적으로 처리하는 구간이 있었는데, 우리는 그 앞에 최대 64개의 워커를 밀어 넣고 있었습니다.

그 결과 매장 시스템의 응답이 조금 느려지면 우리 쪽 동시 요청이 늘고, 동시 요청이 늘면 매장 시스템이 더 느려지는 되먹임이 생겼습니다. 여기에 외부 호출에 타임아웃이 없었기 때문에, 이미 사용자가 떠난 요청도 고루틴을 계속 붙잡고 있었습니다.

영향

영향은 하루 한 구간에 몰렸습니다. 평일 12시 05분부터 12시 40분 사이, 주문 접수 API의 p95 지연이 평시 90ms에서 1.1초까지 올라갔습니다. 오류율은 거의 오르지 않았습니다. 요청은 결국 성공했고, 다만 늦었습니다. 이것이 이 문제를 오래 방치하게 만든 이유이기도 합니다. 대시보드에서 오류율만 보고 있으면 아무 일도 일어나지 않은 것처럼 보입니다.

사용자 쪽에서는 주문 버튼을 두 번 누르는 비율이 피크 구간에 눈에 띄게 올라갔고, 중복 접수 문의가 같은 시간대에 몰렸습니다. 즉 지연은 지연으로만 끝나지 않고 중복 요청이라는 부하를 한 번 더 만들어 냈습니다.

타임라인

계측

가장 도움이 된 계측은 화려한 것이 아니었습니다. 하나의 요청이 소비한 시간을 큐에서 기다린 시간과 실제로 일한 시간으로 나눠 기록한 것뿐입니다. 이 두 값을 분리하기 전까지 우리는 “느리다”는 말밖에 할 수 없었습니다.

구간                        p50        p95        피크 밖 p95
------------------------  ---------  ---------  -----------
워커 큐 대기                  30ms     1,010ms         14ms
매장 시스템 확인 호출 왕복      52ms        61ms         49ms
내부 주문 DB 조회/기록          4ms         6ms          5ms
직렬화 및 응답                 2ms         2ms          2ms
------------------------  ---------  ---------  -----------
합계                         88ms     1,079ms         70ms

같은 시각 관측값
  동시 실행 워커 수            64 (상한 없음, 자동 증가)
  매장 시스템 동시 처리 한계    약 25건 이상부터 왕복 시간 상승
  진행 중 고루틴 수            38,412

표의 마지막 줄이 사실상 사건의 전부입니다. 실제로 일하는 시간은 피크 안팎이 거의 같았습니다. 61ms와 49ms의 차이는 있지만 1초를 만들 크기가 아닙니다. 늘어난 1,010ms는 전부 순서를 기다린 시간이었습니다. 대기 시간이 서비스 시간의 열여섯 배가 되는 상황은 처리가 느려서가 아니라 너무 많은 요청을 동시에 밀어 넣어서 생깁니다.

기각한 가설

이 절을 남기는 이유는, 우리가 실제로 쓴 시간의 절반이 여기에 들어갔기 때문입니다.

가설 1: GC 정지 때문이다. 정오에 요청이 몰리면 할당이 늘고, 힙이 커지면 정지 시간이 길어져 꼬리 지연을 만든다는 그림이었습니다. Go 서비스에서 꼬리 지연이 튈 때 가장 먼저 나오는 이야기이기도 합니다. 우리는 피크 시간대에 런타임 추적을 켜고 프로파일을 함께 받았습니다.

$ GODEBUG=gctrace=1 ./order-api
gc 411 @1802.339s 1%: 0.071+2.9+0.048 ms clock, 0.57+0.28/2.1/0.0+0.38 ms cpu, 39->42->21 MB, 43 MB goal, 8 P
gc 412 @1806.115s 1%: 0.066+3.3+0.051 ms clock, 0.53+0.19/2.6/0.0+0.41 ms cpu, 41->44->22 MB, 44 MB goal, 8 P
gc 413 @1809.884s 1%: 0.083+3.1+0.044 ms clock, 0.66+0.31/2.4/0.0+0.35 ms cpu, 42->45->22 MB, 45 MB goal, 8 P

  30초 동안 STW 정지 합계 : 약 1.4ms
  GC가 쓴 CPU 비율        : 1%
  힙 크기                 : 45MB 부근에서 안정

$ curl -s localhost:6060/debug/pprof/goroutine?debug=1 | head -6
goroutine profile: total 38412
27904 @ 0x43e0c5 0x44f2b8 0x7a1d31 0x7a2044 0x46d2a1
#	internal/poll.runtime_pollWait+0x85
#	orderapi/store.(*Client).Confirm+0x1c1   store_client.go:88
 9803 @ 0x43e0c5 0x44f2b8 0x6d1a77 0x46d2a1
#	orderapi/worker.(*Pool).acquire+0x77     pool.go:52

이 출력으로 가설 1은 끝났습니다. 30초 동안 전체 정지 시간이 1.4ms 남짓인데 p95는 1초를 넘고 있었습니다. 크기 자체가 세 자릿수 차이라 더 볼 것이 없었습니다. 힙도 45MB 근처에서 평평했습니다.

대신 같은 출력의 아랫부분이 다음 단서를 줬습니다. 고루틴이 3만 8천 개 있었고 그중 2만 8천 개가 매장 시스템 응답을 기다리는 지점에, 9천 8백 개가 워커 자리를 얻으려고 대기하는 지점에 멈춰 있었습니다. 초당 요청 수를 생각하면 나올 수 없는 숫자였습니다. 이미 사용자가 포기한 요청들이 그대로 살아 있다는 뜻이었습니다.

가설 2: DB 커넥션 풀이 고갈됐다. 두 번째로 유력했던 설명입니다. 대기 시간이 늘었으니 어딘가에서 자원을 못 얻고 있는 것은 맞았습니다. 다만 위치가 틀렸습니다. 커넥션 풀 지표에서 대기 이벤트는 피크 구간에도 0에 가까웠고, 내부 DB 조회 구간의 p95는 6ms로 평시와 같았습니다. 풀이 마르면 그 값이 먼저 움직입니다. 움직이지 않았으므로 기각했습니다.

두 가설이 지워지고 나서야 남은 설명은 하나였습니다. 우리는 매장 시스템이 감당할 수 있는 것보다 많은 요청을 동시에 보내고 있었고, 그 대기열을 무제한으로 자라게 두고 있었습니다. 그리고 워커를 늘리는 자동 조정은 이 상황에서 소화기가 아니라 연료였습니다. 큐가 길어지면 워커를 늘리고, 워커가 늘면 매장 시스템이 더 느려지고, 느려지면 큐가 더 길어졌습니다.

조치

고친 것은 두 가지입니다. 첫째, 동시 실행 수를 CPU 코어 수나 큐 길이가 아니라 다운스트림이 감당하는 용량에 맞춰 고정했습니다. 25건 부근에서 왕복 시간이 오르기 시작했으므로 여유를 두고 24로 정했습니다. 둘째, 외부 호출 전체에 마감 시각을 부여해서 사용자가 기다리지 않는 작업이 자원을 붙잡지 못하게 했습니다. 이 마감은 큐에서 기다리는 시간까지 포함합니다. 자리를 얻는 데 이미 800ms를 썼다면 호출을 시작할 이유가 없기 때문입니다.

// 다운스트림이 안정적으로 처리하는 동시 요청 수를 그대로 상한으로 둡니다.
// 이 값은 CPU 코어 수와 무관합니다.
const storeConcurrency = 24

// 외부 호출은 큐 대기까지 포함해 이 시간 안에 끝나야 합니다.
const storeBudget = 800 * time.Millisecond

type Client struct {
	sem      chan struct{}
	http     *http.Client
	endpoint string
}

func NewClient(h *http.Client, endpoint string) *Client {
	return &Client{
		sem:      make(chan struct{}, storeConcurrency),
		http:     h,
		endpoint: endpoint,
	}
}

func (c *Client) Confirm(ctx context.Context, o Order) (Ack, error) {
	ctx, cancel := context.WithTimeout(ctx, storeBudget)
	defer cancel()

	// 자리를 얻는 것 자체가 마감 대상입니다.
	// 예전 코드는 여기서 무한정 기다렸고, 그래서 고루틴이 쌓였습니다.
	select {
	case c.sem <- struct{}{}:
		defer func() { <-c.sem }()
	case <-ctx.Done():
		queueWaitTimeouts.Inc()
		return Ack{}, fmt.Errorf("매장 확인: 큐 대기 마감 초과: %w", ctx.Err())
	}

	req, err := http.NewRequestWithContext(ctx, http.MethodPost, c.endpoint, o.Body())
	if err != nil {
		return Ack{}, fmt.Errorf("매장 확인: 요청 생성: %w", err)
	}

	res, err := c.http.Do(req)
	if err != nil {
		return Ack{}, fmt.Errorf("매장 확인: 호출 실패: %w", err)
	}
	defer res.Body.Close()

	return decodeAck(res.Body)
}

// 소비자 쪽은 읽기 전용 채널만 받도록 좁혀 두었습니다.
func drain(ctx context.Context, in <-chan Order, c *Client) {
	for {
		select {
		case o, ok := <-in:
			if !ok {
				return
			}
			if _, err := c.Confirm(ctx, o); err != nil {
				log.Printf("접수 확인 실패 order=%s: %v", o.ID, err)
			}
		case <-ctx.Done():
			return
		}
	}
}

바꾼 코드가 하는 일은 단순합니다. 동시에 24건만 나가고, 그 이상은 기다리되 마감 안에서만 기다립니다. 마감을 넘기면 요청은 실패로 빨리 돌아옵니다. 지표상으로는 오류율이 조금 올라갔지만, 사용자가 1.1초를 기다린 끝에 성공하는 것보다 200ms 만에 재시도 안내를 받는 쪽이 나은 경험이었습니다. 이 판단은 팀이 합의해서 문서에 적어 둔 부분입니다. 동시성과 채널 방향을 다루는 기본기는 Go 고루틴 가이드에, 이런 지연 분해를 프로파일로 확인하는 방법은 Go 성능 가이드에 따로 정리해 두었습니다.

재발 방지

같은 모양의 사고가 다른 경로에서 또 일어나지 않도록 규칙 몇 가지를 코드와 리뷰 항목으로 남겼습니다.

• 외부 시스템을 호출하는 모든 경로는 동시 실행 상한을 상수로 선언한다. 상한 값의 근거는 다운스트림 측정치이며, 코드 주석에 그 근거를 함께 적는다.
• 모든 외부 호출은 마감 시각을 갖는다. 큐에서 자리를 기다리는 시간도 그 마감에 포함한다.
• 큐 길이를 보고 워커 수를 자동으로 늘리는 조정은 쓰지 않는다. 다운스트림이 병목일 때 이 조정은 부하를 키우는 방향으로만 작동한다.
• 지연 지표는 큐 대기 시간과 서비스 시간을 분리해서 기록한다. 합계만 보면 “느리다”까지밖에 말할 수 없다.
• 고루틴 수를 상시 지표로 둔다. 초당 요청 수 대비 설명되지 않는 고루틴 수는 사라지지 않는 작업이 있다는 신호다.
• 배포 검증에는 오류율과 함께 p95를 본다. 이번 사고는 오류율만 보면 존재하지 않는 사고였다.

정리하면 이번에 배운 것은 Go에 대한 이야기가 아니라 대기열에 대한 이야기입니다. 처리 용량이 정해진 대상 앞에서 동시 요청을 늘리면 처리량은 늘지 않고 대기 시간만 늘어납니다. 우리가 늘릴 수 있었던 것은 워커 수뿐이었고, 정작 늘려야 했던 것은 매장 시스템의 처리 용량이었습니다. 그것을 늘릴 수 없다면 남은 선택지는 우리 쪽에서 들여보내는 양을 정하는 것뿐입니다.

“동시성은 처리 능력이 아닙니다. 얼마나 많이 동시에 기다릴 수 있는지를 정할 뿐입니다. 무엇을 기다리는지 모르는 상태에서 그 숫자를 올리면, 우리는 문제를 더 빠르게 만들고 있는 셈입니다.”