OTel Collector tail sampling에서 OOM으로 세 번 죽은 이야기

지난주에 OpenTelemetry Collector가 새벽에 세 번이나 OOM으로 재시작됐다. 알림이 잔뜩 쌓여있었고, 아침에 슬랙 열자마자 "이거 뭐야" 소리가 절로 나왔다. 원인은 결국 tail sampling processor였는데, 문제를 잡기까지 꽤 돌아왔다. 기록 삼아 남긴다.

처음엔 그냥 트래픽 스파이크인 줄 알았다

우리 팀은 최근에 head sampling에서 tail sampling으로 옮겼다. 이유는 명확했다. 에러 트레이스나 P99 넘어가는 느린 트레이스는 무조건 살려두고 싶은데, head sampling으로는 그게 불가능하니까. 트레이스 전체가 다 모여야 판단할 수 있는 정책들, 예를 들어 "이 트레이스에 5xx가 하나라도 있으면 keep" 같은 것들 말이다.

옮긴 지 2주 정도는 조용했다. 그러다 어느 날 새벽 3시 20분쯤 슬랙에 알림이 떴다.

[FIRING] OtelCollectorPodRestart
  pod: otel-collector-gateway-2
  reason: OOMKilled

첫 번째 반응은 "새벽 트래픽이 왜?" 였다. 우리 서비스는 국내향이라 새벽엔 QPS가 낮은데, 이상하게도 그때만 죽었다. 일단 memory limit을 4Gi에서 8Gi로 올려두고 잠들었다. 이게 첫 번째 실수였다.

두 번째 밤: 8Gi도 터졌다

다음 날 새벽 4시, 같은 알림. 이번엔 8Gi도 다 먹고 죽었다. 이쯤 되니까 트래픽 스파이크가 아니라는 걸 인정해야 했다. Prometheus에서 컬렉터 메모리 그래프를 다시 봤는데, 특징이 있었다.

• 낮 동안엔 완만하게 우상향
• 자정 넘어가면서 기울기가 급격히 올라감
• 결국 새벽 3~4시에 limit 도달

한마디로 뭔가가 계속 쌓이고, 배출이 안 되고 있었다. 처음엔 exporter 쪽 백프레셔를 의심했다. Tempo로 보내는데 Tempo가 밀리면서 큐가 쌓이는 건가? Tempo 대시보드를 열어봤다. 정상. 심지어 새벽엔 더 여유로웠다.

진짜 범인은 tail_sampling의 decision_wait였다

새벽 컬렉터의 debug 엔드포인트를 켜고 zpages를 봤다. /debug/tracez에 스팬들이 남아있는데, 이상하게 오래된 것들이 많았다. 30초, 1분, 심지어 5분짜리도 있었다.

그러다 zpages의 pipeline 그래프를 보고 감이 왔다. tail sampling processor의 pending trace 수가 계속 우상향 중이었다.

우리 설정을 다시 봤다.

processors:
  tail_sampling:
    decision_wait: 60s
    num_traces: 200000
    expected_new_traces_per_sec: 5000
    policies:
      - name: errors
        type: status_code
        status_code:
          status_codes: [ERROR]
      - name: slow
        type: latency
        latency:
          threshold_ms: 500
      - name: probabilistic-baseline
        type: probabilistic
        probabilistic:
          sampling_percentage: 5

decision_wait: 60s. 즉, 트레이스 하나가 도착하면 60초 동안 관련 스팬을 다 모을 때까지 메모리에 잡아둔다. 여기까지는 알고 있었다. 근데 우리 시스템에 특정 배치 잡이 하나 있는데, 이게 트레이스 하나가 실제로 완결되기까지 3~4분씩 걸린다. 사실 이건 트레이스라기보다 워크플로우에 가까운 물건이었다.

문제는 이런 "긴 꼬리"를 가진 트레이스가 새벽에 몰려서 도는 크론 잡에서 대량으로 발생한다는 거였다. Decision wait가 지나기 전에 새 스팬이 계속 들어오면서 트레이스가 "재활성화"되는 케이스도 있었고, 그러면서 num_traces limit인 20만 개에 도달, 그때부터 오래된 트레이스가 스팬을 잃은 채 강제로 밀려나면서 이상한 상태가 됐다. 이 시점에 실제 사용 메모리는 이미 configured num_traces가 감당할 수 있는 수준을 훨씬 넘어가고 있었다.

근본적으로 잘못 접근한 부분

솔직히 이건 설정만 조금 만지면 되는 문제가 아니었다. 우리는 tail_sampling을 한 대의 게이트웨이 컬렉터에 통짜로 쓰고 있었는데, 이게 잘못이었다.

tail sampling processor의 전제 조건 중 하나가 "같은 trace_id의 모든 스팬은 같은 collector 인스턴스로 도착해야 한다"이다. 우리는 어차피 게이트웨이가 한 대라 신경 안 썼는데, 이제와서 보면 스케일 아웃할 수 없는 구조를 만들어둔 셈이다. 앞단에 load balancing exporter를 두고 tail sampler를 여러 인스턴스로 분산하는 게 정석이다.

또 하나. memory_limiter processor를 파이프라인 맨 앞에 안 두고 있었다. 아래처럼 tail_sampling 다음에 있었다.

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [tail_sampling, memory_limiter, batch]
      exporters: [otlphttp]

memory_limiter는 파이프라인의 맨 앞에 둬야 뒤에 있는 무거운 processor로 데이터가 흘러들어가는 걸 미리 막을 수 있다. 우리는 이미 tail_sampling에 다 물린 뒤에 memory_limiter가 튀어봤자 이미 늦었다.

임시 조치와 장기 계획

일단 이번 주 급한 대로 세 가지를 했다.

첫째, decision_wait를 60초에서 15초로 줄였다. 대신 우리 배치 잡용 트레이스는 애초에 sampling에서 제외했다. always_sample 정책을 attribute 기반으로 붙여서, batch.job=true 인 트레이스는 뒤도 안 보고 keep. 결과적으로 tail sampler가 붙잡고 있어야 할 이유 자체가 사라졌다.

policies:
  - name: batch-jobs-always
    type: string_attribute
    string_attribute:
      key: batch.job
      values: ["true"]

둘째, memory_limiter를 파이프라인 앞으로 옮겼다. 이건 진작 했어야 했다.

셋째, num_traces를 20만에서 5만으로 낮췄다. 큰 값이 안전할 것 같아서 크게 잡았던 건데, 사실 num_traces가 크면 클수록 메모리도 그만큼 커진다. 우리의 실제 초당 새 트레이스 수를 다시 계산해보니 2천 정도. decision_wait 15초면 3만 트레이스면 충분했다. 여유 두고 5만.

이 세 가지만으로 새벽 3~4시 스파이크가 사라졌다. Peak 메모리도 8Gi에서 3Gi 아래로 떨어졌다.

장기적으로는 load balancing exporter를 앞단에 두고 tail sampler를 3대 이상으로 분산하려고 한다. 요건 다음 스프린트 작업으로 잡아뒀다. 최근에 OTel 커뮤니티에서도 이 패턴을 표준으로 밀고 있고, 관련 블로그 글도 2월에 몇 개 올라왔더라.

남은 의문

한 가지 아직도 좀 걸리는 게 있는데, decision_wait가 짧아지면 늦게 도착하는 스팬은 그냥 놓치는 거다. 우리 시스템의 span propagation latency P99가 얼마인지 정확히 모른 채로 15초로 잘랐는데, 이게 진짜 충분한지는 좀 더 지켜봐야 한다. 만약 늦게 도착하는 스팬이 통계적으로 유의미하게 있다면, 그 트레이스는 반쪽짜리로 저장되는 셈이니까.

혹시 이런 케이스를 어떻게 관측하는지 아시는 분 있으면 알려주세요. 지금은 임시로 late-arriving span 카운터를 커스텀 processor로 붙일까 고민 중이다.