지표, 로그, 추적 정리: 관측성의 세 가지 신호와 trace_id로 잇기

관측성 정리에서 미리 정하지 않은 질문에 답하려면 원시 이벤트를 남겨야 한다고 했는데요. 그러면 다음 질문이 따라옵니다. 어떤 형태로 남길까? 앞 글에서 던진 자가 진단 세 질문을 다시 꺼내 보면 답이 셋으로 갈립니다. “지금 오류율이 얼마인가”는 숫자 하나로 답하고, “그 사용자의 요청에 무슨 일이 있었나”는 사건 기록으로 답하고, “요청이 어느 서비스에서 시간을 썼나”는 요청의 여정으로 답해야 하거든요.

이 세 형태가 지표(metric), 로그(log), 추적(trace)입니다. 2017년쯤부터 “관측성의 세 기둥”이라는 말로 불렸는데, 한 달 전인 2019년 5월에 OpenTracing과 OpenCensus라는 두 프로젝트가 합쳐져 OpenTelemetry가 출범하면서 셋을 신호(signal)라고 부르기 시작했어요. 이 글에서는 세 신호가 각각 어떤 질문에 맞고 무엇이 비싼지, 그리고 셋을 어떻게 이어서 장애를 좁혀 가는지를 정리해 보겠습니다.

지표: 지금 얼마나

지표는 시간에 따라 변하는 숫자입니다. 초당 요청 수, 오류율, p99 응답 시간, 큐 길이처럼 일정 간격으로 잰 값을 시계열(time series)로 쌓아 둡니다. 이 시리즈의 알림 규칙과 에러 예산이 전부 지표 위에서 돌아갔죠.

지표의 강점은 싸다는 겁니다. 요청이 1초에 만 건 들어와도 “초당 요청 수”는 숫자 하나예요. 이미 집계된 값이라 저장도 싸고 조회도 빠르고 몇 년 치를 보관해도 부담이 없습니다. 그래서 알림과 대시보드는 지표로 만듭니다. 1분마다 조건을 평가하는 알림 규칙이 원시 이벤트를 매번 뒤진다면 감당이 안 되니까요.

약점은 같은 이유에서 나옵니다. 집계하는 순간 개별 요청은 사라져요. “오류율 5%“는 알 수 있지만 그 5%가 누구였는지는 지표에 없습니다. 앞 글에서 다룬 카디널리티 문제가 여기서 생기는데, 사용자별로 시계열을 만들면 지표의 싼 값이 사라지거든요. 지표는 “지금 얼마나”에 답하는 신호이고, “누가, 왜”는 다른 신호의 몫입니다.

로그: 그때 무슨 일이

로그는 일어난 일의 기록입니다. 오래전부터 있었죠. 처음엔 사람이 읽을 문장이었고 지금은 기계가 읽을 구조로 바뀌고 있어요. “결제 실패: 사용자 18273, 카드 거절”이라는 문장 대신 앞 글에서 본 것처럼 필드가 나뉜 JSON 한 줄로 남기는 겁니다. 이걸 구조화된 로그(structured log)라고 부르고, 관측성이 요구하는 원시 이벤트가 바로 이 형태입니다.

로그의 강점은 높은 카디널리티를 그대로 담는다는 점입니다. user_id와 request_id부터 카드 거절 사유까지 전부 한 줄에 들어가요. 그래서 “그 사용자의 요청에 무슨 일이 있었나”에 답할 수 있는 신호는 로그뿐입니다. 언어마다 표준 도구가 있어서 파이썬의 logging 모듈이나 NestJS의 Logger처럼 이미 쓰고 있는 것에 필드만 붙이면 시작할 수 있고요.

약점은 양입니다. 요청마다 한 줄씩 남기면 초당 만 건이 초당 만 줄이 되고 저장과 검색 비용이 지표와는 자릿수가 다르게 커집니다. 그래서 무엇을 남기고 무엇을 버릴지, 얼마나 오래 보관할지가 로그 설계의 실제 문제가 됩니다. 또 하나, 로그는 서비스 안에서 일어난 일만 압니다. 결제 서비스 로그는 결제 서비스가 한 일을 적을 뿐 그 요청이 인증 서비스에서 얼마나 기다렸는지는 모릅니다. 서비스 경계를 넘는 순간 로그는 끊겨요.

추적: 요청이 어디서 시간을 썼나

추적은 요청 하나의 여정을 기록합니다. 사용자가 결제 버튼을 누른 순간부터 응답이 돌아갈 때까지 요청이 거쳐 간 서비스와 각 서비스에서 보낸 시간을 트리로 남겨요. 트리의 마디 하나를 스팬(span)이라고 부릅니다. 스팬은 이름과 시작 시각, 걸린 시간, 부모 스팬을 갖고 같은 요청에 속한 스팬은 전부 같은 trace_id를 공유합니다.

flowchart TB
    accTitle: 결제 요청 하나의 추적
    accDescr: 결제 요청 전체가 842ms 걸렸고, 그 아래로 인증 120ms, 재고 확인 95ms, 결제 승인 600ms 스팬이 있다. 결제 승인 스팬 아래에는 카드사 API 호출 580ms 스팬이 있어서, 전체 시간의 대부분이 외부 카드사 호출에서 소비됐음을 보여 준다.

    root["POST /checkout<br/>842ms"]
    root --> auth["인증 확인<br/>120ms"]
    root --> stock["재고 확인<br/>95ms"]
    root --> pay["결제 승인<br/>600ms"]
    pay --> bank["카드사 API 호출<br/>580ms"]

이 그림 하나가 “왜 느린가”에 답합니다. 842ms 중 580ms가 카드사 API 호출이니 우리 코드를 아무리 최적화해도 소용없고 카드사 쪽 지연이거나 타임아웃 설정 문제라는 걸 바로 알 수 있죠. 로그로는 이 답을 얻기 어렵습니다. 서비스 네 개의 로그를 시각으로 맞춰 이어 붙여야 하는데 시계가 조금씩 어긋나고 요청 수가 많으면 어느 줄이 같은 요청인지 알 수 없거든요. 추적은 그 이어 붙이기를 trace_id와 부모 스팬 관계로 미리 해 둔 것입니다.

분산 추적(distributed tracing)이라는 이름으로 불리는 이 기법은 Google이 2010년에 Dapper 논문으로 공개했고 Zipkin과 Jaeger 같은 오픈소스 구현이 뒤따랐습니다. 구현마다 계측 방식이 달라서 한 번 계측하면 도구를 못 바꾸는 문제가 있었는데 그걸 풀려던 OpenTracing과 OpenCensus가 합쳐진 게 OpenTelemetry예요.

약점은 역시 양입니다. 요청마다 스팬을 여러 개 남기니 로그보다도 많아질 수 있어요. 그래서 대개 샘플링(sampling)을 합니다. 요청의 1%만 추적하거나, 느리거나 실패한 요청만 남기는 식이죠. 샘플링을 하면 “그 사용자의 그 요청”이 추적에 없을 수 있다는 점은 감수해야 합니다.

세 신호를 잇는 것: trace_id

세 신호를 따로 두면 각자 답하는 질문이 다를 뿐 서로 연결되지 않습니다. 지표에서 오류율이 튄 걸 봤는데 어느 추적을 봐야 하는지 모르고, 추적에서 느린 스팬을 찾았는데 그 스팬 안에서 무슨 일이 있었는지는 로그를 뒤져야 하죠. 그 연결을 상관관계(correlation)라고 부르고 열쇠는 trace_id입니다.

방법은 단순합니다. 로그 한 줄을 남길 때 지금 처리 중인 요청의 trace_id를 같이 적는 거예요. 앞 글의 이벤트에 필드 두 개가 더 붙는 셈입니다.

{
  "timestamp": "2019-06-01T03:14:07Z",
  "service": "payment",
  "level": "error",
  "message": "card declined",
  "user_id": "u_18273",
  "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736",
  "span_id": "00f067aa0ba902b7"
}

그러면 추적에서 느린 스팬을 골라 그 trace_id로 로그를 검색하면 그 요청의 로그만 나옵니다. 반대로 로그에서 이상한 줄을 발견하면 trace_id로 그 요청의 전체 여정을 열어 볼 수 있고요. span_id까지 있으면 그 로그가 여정의 어느 마디에서 나왔는지도 바로 알 수 있습니다.

장애 대응이 이렇게 흘러갑니다. 지표 알림이 울려서 오류율이 튄 시간대를 알아내고, 그 시간대의 실패한 추적을 열어 어느 스팬에서 실패했는지 보고, 그 스팬의 trace_id로 로그를 찾아 실패 사유를 읽습니다. 넓은 데서 좁은 데로, 싼 신호에서 비싼 신호로 내려가는 순서예요. 앞 글의 자가 진단 세 질문이 여기서 각각 답을 얻습니다. 배포 없이 새 질문에 답하는 건 구조화된 로그, 요청을 서비스 경계 너머로 따라가는 건 추적, 사용자 한 명의 경험을 재구성하는 건 trace_id로 이은 로그와 추적입니다.

기둥이 아니라 해상도

“세 기둥”이라는 비유는 셋이 독립된 축처럼 들리게 하는데, 실제로는 같은 사건을 다른 해상도로 본 것에 가깝습니다. 요청 하나가 들어오면 그 요청은 스팬이 되고, 스팬 안의 사건은 로그가 되고, 스팬 수천 개를 세면 지표가 됩니다. 지표는 로그를 집계한 것이고 추적은 로그에 구조를 준 것이라고 봐도 크게 틀리지 않아요.

그래서 셋 중 무엇을 고를지가 아니라 어느 해상도에서 볼지를 정하는 문제가 됩니다. 알림은 낮은 해상도(지표)로 걸고, 조사는 높은 해상도(로그, 추적)로 내려가는 거죠. 셋 다 필요하되 역할이 다릅니다.

어디서부터 시작할까

셋을 한꺼번에 갖추려고 하면 시작을 못 합니다. 순서를 정하면 이렇습니다.

구조화된 로그에 request_id를 붙이는 것부터 시작하는 게 가장 싸요. 이미 로그는 남기고 있을 테니 형식을 JSON으로 바꾸고 요청마다 식별자 하나를 만들어 모든 줄에 붙이면 됩니다. 이것만으로 “그 사용자의 요청에 무슨 일이 있었나”에 답할 수 있게 되고 나중에 추적을 붙일 때 그 식별자가 trace_id 자리를 그대로 이어받습니다.

그다음이 지표입니다. 알림과 SLO를 걸려면 지표가 있어야 하는데, 요청 수와 오류 수와 응답 시간 세 가지만 있어도 앞선 글의 내용을 전부 적용할 수 있어요. 추적은 마지막입니다. 서비스가 서너 개를 넘어가서 “어느 서비스가 느린가”를 로그로 답하기 어려워지는 시점에 붙이면 되고 그 전까지는 로그의 request_id로 충분한 경우가 많습니다.

같은 말, 다른 이름

이 층의 용어는 도구마다 갈립니다. 추적의 마디를 Zipkin, Jaeger, OpenTracing은 스팬이라고 부르지만 AWS X-Ray는 세그먼트(segment)라고 불러요. 지표에 붙는 키-값 쌍은 Prometheus에서 레이블(label), 다른 도구에서는 태그(tag)나 디멘션(dimension)입니다. OpenTelemetry는 스팬에 붙는 키-값 쌍을 속성(attribute)이라고 정했고요. 이름은 달라도 “숫자 시계열”, “사건 기록”, “요청의 여정”이라는 세 형태와 그 위의 키-값 쌍이라는 구조는 같습니다.

마치며

지표는 싸고 집계된 숫자라 “지금 얼마나”에 답하고, 로그는 높은 카디널리티를 담은 사건 기록이라 “그때 무슨 일이”에 답하고, 추적은 요청의 여정이라 “어디서 시간을 썼나”에 답합니다. 셋은 독립된 기둥이 아니라 같은 사건의 다른 해상도이고 trace_id로 이어 두면 지표에서 추적으로, 추적에서 로그로 내려가며 장애를 좁힐 수 있습니다.

여기까지 여섯 편에서 알림, 온콜, SLO, 에러 예산, 관측성, 세 신호를 다뤘습니다. 세 신호를 계측하고 내보내는 방식을 하나로 맞추려는 게 막 출범한 OpenTelemetry인데, 이 이야기는 다음 시리즈에서 이어 가겠습니다.

세 신호의 정의는 OpenTelemetry 공식 문서의 Observability Primer를 참고하세요.