트레이스

트레이스는 요청 하나가 시스템을 지나간 길을 처음부터 끝까지 이어 붙여 남깁니다. 요청이 여러 서비스를 거치면 어디서 시간이 걸렸는지가 서비스마다 흩어집니다. 트레이스는 그 조각을 한 줄기로 묶어 보여 줍니다. 프로그램이 예외를 던질 때 찍히는 스택 트레이스와는 다른 것입니다.

상세

택배 송장 조회를 떠올려 봅시다. 송장 번호 하나로 조회하면 물건이 어느 터미널에 언제 들어가 언제 나왔는지가 한 화면에 이어집니다.

트레이스는 요청 하나가 시스템을 지나며 거친 작업들을 한데 묶어 남긴 기록입니다. 작업마다 누가 자기를 불렀는지도 함께 적어 둡니다.

바깥에서 들어온 HTTP(HyperText Transfer Protocol) 요청 하나가 있다고 합시다. 그 요청을 받은 서버가 다른 서버를 부릅니다. 그 서버가 다시 데이터베이스에 SQL(Structured Query Language) 쿼리를 보냅니다. 이 세 작업이 한 트레이스에 담깁니다.

트레이스를 이루는 작업 하나하나를 스팬이라고 부릅니다. 스팬은 작업 하나의 이름과 시작 시각, 끝 시각을 적은 기록입니다. 서버 사이의 호출 하나에 대개 스팬 하나가 생깁니다.

스팬을 잇는 세 번호

흩어진 스팬을 한 트레이스로 잇는 것은 번호 셋입니다. 이 번호를 흔히 ID(Identifier, 식별자)라고 부릅니다.

부모 ID 가 없는 스팬이 루트 스팬입니다. 요청이 시스템에 처음 들어온 지점의 작업입니다. 대개 요청 처리 전체의 처음과 끝을 나타냅니다.

스팬이 이루는 나무

루트 스팬을 뺀 스팬은 모두 부모를 하나씩 가리킵니다. 그래서 스팬들은 루트에서 뻗어 나가는 나무 꼴이 됩니다. 호출이 한 단계 더 깊어질 때마다 나무도 한 층 깊어집니다.

아래는 스팬 여섯 개가 한 트레이스를 이룬 모양입니다. A 가 루트 스팬입니다. B 와 C 는 A 가 부른 작업입니다. D 는 B 가, E 와 F 는 C 가 부른 작업입니다.

flowchart TD
    A["스팬 A · 루트 스팬"] --> B["스팬 B"]
    A --> C["스팬 C"]
    B --> D["스팬 D"]
    C --> E["스팬 E"]
    C --> F["스팬 F"]

같은 나무를 시간 축 위에 펼쳐 보기도 합니다. 스팬마다 시작에서 끝까지가 막대 하나가 됩니다. 그러면 어느 작업이 어느 작업과 겹쳐 돌았는지, 어디서 시간이 갔는지가 드러납니다.

서비스 경계를 넘는 번호

나무가 서비스 경계를 넘어 이어지려면 번호가 요청과 함께 건너가야 합니다. 서비스 A 가 서비스 B 를 부를 때 트레이스 ID 와 자기 스팬 ID 를 요청에 실어 보냅니다. 서비스 B 는 같은 트레이스 ID 로 새 스팬을 엽니다. 넘어온 스팬 ID 는 새 스팬의 부모 ID 로 적습니다. 이렇게 번호를 넘기는 일을 컨텍스트 전파라고 부릅니다.

sequenceDiagram
    participant A as 서비스 A
    participant B as 서비스 B
    Note over A: 스팬을 연다
    A->>B: 요청 + 트레이스 ID + A 의 스팬 ID
    Note over B: 같은 트레이스 ID 로 새 스팬을 연다<br/>부모 ID 는 A 의 스팬 ID 다
    B-->>A: 응답

배경

구글의 웹 검색에서는 2010년 무렵 앞단 서비스가 검색어 한 건을 수백 대의 쿼리 서버로 나눠 보낼 수 있었습니다. 서버마다 색인을 한 조각씩 맡아 찾아봅니다. 같은 검색어가 광고, 맞춤법 검사, 이미지·뉴스 검색 같은 하위 시스템으로도 갈 수 있습니다. 결과 페이지 하나를 만드는 데 기계 수천 대와 서비스 여럿이 필요할 수 있습니다.

검색하는 사람은 지연에 민감합니다. 지연은 하위 시스템 어디서든 성능이 떨어지면 생길 수 있습니다. 전체 지연만 보는 엔지니어는 문제가 있다는 것까지는 알 수 있습니다. 어느 서비스 탓인지는 짐작하지 못할 수 있습니다.

2000년대 후반의 진단 도구는 대개 네트워크 계층 하나나 애플리케이션 하나만 보도록 만들어졌습니다. 같은 요청에 속한 작업을 여러 프로그램과 기계에 걸쳐 함께 볼 수단이 필요했습니다. 작업마다 같은 요청의 번호와 부른 쪽의 번호를 붙여 두면 흩어진 기록에서 요청 하나의 모양을 다시 세울 수 있습니다. 그렇게 다시 세운 기록을 트레이스라고 부릅니다.

예시

트레이스를 실물로 보는 두 모습입니다. 하나는 서비스 사이를 오가는 헤더 한 줄입니다. 다른 하나는 저장된 스팬 기록입니다.

W3C Trace Context 의 traceparent 헤더

W3C(World Wide Web Consortium)의 Trace Context 는 서비스끼리 번호를 넘기는 HTTP 헤더의 모양을 정한 표준입니다. 번호를 싣는 헤더가 traceparent 입니다. 아래는 그 표준에 실린 예시 값입니다.

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01

값은 줄표로 나뉜 네 토막입니다.

trace-id 가 상세에서 본 트레이스 ID 입니다. 받는 쪽은 이 값을 바꾸지 않고 자기 스팬에 씁니다. parent-id 는 부르는 쪽 스팬의 스팬 ID 입니다. 받는 쪽은 이 값을 자기 스팬의 부모 ID 로 적습니다.

트레이스는 대개 요청 가운데 일부만 골라 남깁니다. 이것을 샘플링이라고 부릅니다. 골라 남긴 요청은 표본이라고 합니다. 마지막 토막이 이 결정을 다음 서비스로 실어 나릅니다. 부르는 쪽이 표본으로 남기지 않은 요청이면 같은 헤더의 끝이 00 이 됩니다.

OpenTelemetry 의 스팬 기록

OpenTelemetry 는 트레이스와 메트릭, 로그를 함께 다루는 프로젝트입니다. 아래는 스팬 세 개가 한 트레이스를 이룬 기록 가운데 루트 스팬 hello 입니다. JSON(JavaScript Object Notation)으로 적었습니다. 특정 전송 형식을 따른 것은 아닙니다.

{
  "name": "hello",
  "context": {
    "trace_id": "5b8aa5a2d2c872e8321cf37308d69df2",
    "span_id": "051581bf3cb55c13"
  },
  "parent_id": null,
  "start_time": "2022-04-29T18:52:58.114201Z",
  "end_time": "2022-04-29T18:52:58.114687Z",
  "attributes": {
    "http.route": "some_route1"
  },
  "events": [
    {
      "name": "Guten Tag!",
      "timestamp": "2022-04-29T18:52:58.114561Z",
      "attributes": {
        "event_attributes": 1
      }
    }
  ]
}

trace_id · span_id · parent_id 가 상세의 트레이스 ID · 스팬 ID · 부모 ID 입니다. parent_id 가 null 이라 이 스팬이 루트 스팬입니다. 루트 스팬은 이 트레이스 전체의 처음과 끝을 나타냅니다. 시작이 18:52:58.114201, 끝이 18:52:58.114687 이니 전체에 486마이크로초가 걸렸습니다.

attributes 는 스팬에 붙인 키와 값의 쌍입니다. 이것을 스팬의 속성이라고 부릅니다. 이 스팬에는 http.route 가 some_route1 이라는 속성이 붙었습니다.

events 는 스팬에 시각과 함께 적어 둔 일의 목록입니다. 이것을 스팬 이벤트라고 부릅니다. 이 스팬에는 Guten Tag! 라는 이벤트 하나가 시각과 함께 적혔습니다.

세 스팬의 번호만 뽑으면 이렇습니다.

세 벌 모두 trace_id 가 5b8aa5a2d2c872e8321cf37308d69df2 로 같습니다. 그래서 한 트레이스입니다. 두 스팬의 parent_id 는 hello 의 span_id 와 같습니다. 둘 다 hello 의 자식입니다. 둘은 서로 형제입니다.

스팬 하나만 떼어 보면 구조화된 로그 한 줄과 닮았습니다. 구조화된 로그는 필드 이름과 값으로 적은 로그입니다. 다른 점은 번호입니다. 서로 다른 프로세스와 서비스, 데이터센터에서 나온 기록도 이 번호로 이어져 요청 하나의 처음부터 끝까지를 보여 줍니다.

다른 구현도 뼈대는 같습니다. 트레이스를 모아 보여 주는 도구인 Zipkin 은 같은 세 번호를 다른 이름으로 적습니다.

Zipkin 으로 적은 트레이스 한 벌에서 앞의 두 스팬을 뽑으면 이렇습니다. 두 스팬의 traceId 는 5982fe77008310cc80f1da5e10147517 로 같습니다.

get-traces 의 parentId 가 get 의 id 와 같습니다. 이것으로 get-traces 가 get 의 자식이라는 것을 압니다.

경계

스택 트레이스도 이 문서가 말하는 트레이스일까요? 아닙니다.

스택 트레이스는 프로그램 하나의 호출 스택을 찍은 것입니다. 어느 함수가 어느 함수를 불러 지금 지점까지 왔는지를 한 시점에서 적습니다. 아래는 자바 프로그램이 예외를 던졌을 때의 스택 트레이스입니다.

Exception in thread "main" java.lang.RuntimeException: Test exception
 at com.example.GenerateTrace.methodB(GenerateTrace.java:13)
 at com.example.GenerateTrace.methodA(GenerateTrace.java:9)
 at com.example.GenerateTrace.main(GenerateTrace.java:5)

main 이 methodA 를 불렀습니다. methodA 가 다시 methodB 를 불렀습니다. 호출 순서 말고도 예외 이름과 메시지, 파일 이름과 줄 번호가 담겨 있습니다. 그러나 언제 시작해 얼마나 걸렸는지는 없습니다.

트레이스는 다릅니다. 시작 시각과 끝 시각을 가진 작업들을 요청 하나 단위로 이은 기록입니다. 요청을 받는 애플리케이션이 한 덩어리로 배포되는 모놀리스여도 트레이스를 남깁니다. 요청이 서비스 여럿을 거치면 트레이스도 여러 프로세스와 기계에 걸칩니다.

스택 트레이스는 트레이스 안에 들어갈 수 있습니다. 스팬에서 예외가 나면 그 예외를 스팬 이벤트로 적을 수 있습니다. 그 이벤트의 exception.stacktrace 속성이 위와 같은 스택 트레이스를 문자열 하나로 담습니다. 스택 트레이스는 트레이스 안에 든 값 하나입니다. 트레이스 자신은 아닙니다.

flowchart TD
    subgraph T["트레이스"]
        subgraph S["스팬 하나"]
            subgraph E["스팬 이벤트 · 이름 exception"]
                V["속성 exception.stacktrace<br/>스택 트레이스 문자열 하나"]
            end
        end
    end

OpenTelemetry 에서는 예외를 어디에 남길지가 옮겨 가는 중입니다. 같은 속성을 로그로 남기는 방식이 안정판입니다. 스팬 이벤트로 남기는 방식은 폐기 예정 상태입니다. 예외를 스팬 이벤트로 남기던 기존 코드는 따로 설정하지 않으면 계속 그렇게 남깁니다. 어느 쪽이든 스택 트레이스는 기록 하나에 붙는 문자열 값입니다.

대가

트레이스를 남기기로 하면 세 가지를 치릅니다. 요청마다 붙는 일, 쌓이는 저장량, 그리고 한 구간만 빠져도 끊기는 기록입니다.

요청마다 붙는 계측 비용

트레이스를 남기려면 코드가 스팬을 열고 닫아야 합니다. 이렇게 기록을 내보내도록 코드를 심는 일을 계측이라고 부릅니다. 트레이스를 만들고 모으는 일은 계측한 시스템의 성능을 깎습니다.

구글의 트레이싱 시스템인 Dapper 에서는 비용의 큰 몫이 두 가지였습니다. 스팬을 만들고 없애는 일, 그리고 스팬을 로컬 디스크에 적어 두었다가 모아 가게 하는 일입니다. 처리량이 높은 애플리케이션에서는 이 디스크 쓰기가 성능에 느껴질 만큼 영향을 줄 수 있었습니다. 모든 요청을 남길 때 특히 그랬습니다.

구글이 실제 서비스에서 잰 결과로는 처리량에 대한 영향은 크지 않았습니다. 그래도 지연이 눈에 띄게 늘지 않게 하려면 샘플링이 필요했습니다.

저장량과 샘플링

남긴 트레이스는 저장하고 분석할 자원도 따로 듭니다. 구글의 프로덕션 클러스터는 표본만 남기고도 하루에 1테라바이트가 넘는 트레이스 데이터를 만들었습니다. 사용자들은 그 데이터가 적어도 두 주는 남아 있기를 바랐습니다. 데이터를 촘촘히 남길수록 저장소의 기계와 디스크 값이 붙습니다.

이 때문에 요청 가운데 일부만 표본으로 남깁니다. 표본 비율을 어디에 두느냐에 따라 나빠지는 것이 갈립니다.

구글은 처음에 모든 프로세스에 같은 비율을 썼습니다. 남길 수 있는 트레이스 1024개 가운데 평균 하나를 남겼습니다. 처리량이 높은 서비스에서는 관심 있는 일 대부분이 이 비율로도 잡힐 만큼 자주 나타날 가능성이 컸습니다.

구글의 경험으로는 그런 서비스에서 주목할 만한 실행 패턴이 한 번 나타나면 수천 번 나타납니다. 0.01% 까지 낮춘 표본으로도 중요한 분석 대부분이 막히지 않는다고 봤습니다.

트래픽이 적은 서비스는 사정이 반대입니다. 초당 요청이 수만 건이 아니라 수십 건쯤이라면 요청마다 다 남길 여유가 있습니다. 2010년 무렵 구글은 고정 비율 대신 단위 시간당 남길 트레이스 수를 정하는 적응형 샘플링을 배포하고 있었습니다. 트래픽이 적으면 비율이 저절로 오릅니다. 많으면 내려갑니다.

기록 여부를 어디서 정하느냐에 따라 트레이스가 깨질 수 있습니다. 서비스마다 따로, 또는 무작위로 기록 여부를 정하면 한 요청의 스팬 가운데 일부만 남습니다. 트레이스마다 데이터가 조각나는 것입니다. 구글은 기록을 모으는 단계에서 표본을 한 번 더 고를 때 트레이스 ID 를 기준으로 삼았습니다. 스팬 하나하나가 아니라 트레이스 하나를 전부 남기거나 전부 버린 것입니다. 예시 절의 trace-flags 토막이 기록 결정을 다음 서비스로 넘기는 것도 조각나지 않게 하려는 것입니다.

언제 고르느냐에도 대가가 따릅니다.

번호가 끊기는 구간

트레이스는 번호가 넘어가야 이어집니다. 시스템의 작은 부분만 계측에서 빠져도 트레이스의 쓸모가 크게 떨어질 수 있습니다. 구글에서는 계측되지 않은 통신 라이브러리를 쓰는 극소수 프로그램이 Dapper 트레이스에 안 잡혔습니다. 날것의 TCP(Transmission Control Protocol) 소켓이나 SOAP(Simple Object Access Protocol) 호출로 주고받는 프로그램이 그런 예였습니다.

표준을 벗어난 제어 흐름을 쓰는 코드에서는 Dapper 가 흐름을 못 따라갈 수 있었습니다. 관계없는 일을 인과로 잘못 이을 수도 있었습니다. Dapper 는 이럴 때 개발자가 번호를 손으로 넘길 수 있게 하는 라이브러리를 우회책으로 두었습니다.

이 비용을 치르고 얻는 것은 요청 하나가 거친 길을 한 줄기로 보는 능력입니다. 이 능력이 필요해지는 때는 요청이 여러 프로그램과 기계를 거쳐 어느 서비스 탓인지 짐작하기 어려울 때입니다. 계측에서 빠진 구간이 많은 시스템에서는 비용을 치르고도 기록이 자꾸 끊깁니다.

관련 항목

트레이스를 이루는 구성 요소

스팬 · 루트 스팬 · 트레이스 ID · 스팬 ID · 스팬 컨텍스트 · 스팬 속성 · 스팬 이벤트 · 스팬 링크

트레이스와 함께 쓰이는 텔레메트리 신호

로그 · 메트릭 · 프로파일 · 텔레메트리 · 이벤트 · 구조화 로그

트레이스를 이어 붙이는 전파 수단

컨텍스트 전파 · Trace Context · traceparent · tracestate · 배기지 · B3 전파 · W3C

트레이스를 만들고 모으는 도구와 표준

OpenTelemetry · Jaeger · Zipkin · OpenTracing · OpenCensus · Dapper · X-Trace · OTLP · 관측성 백엔드

트레이스를 남기고 줄이는 처리 단계

계측 · 자동 계측 · 샘플링 · 헤드 샘플링 · 테일 샘플링 · 적응형 샘플링 · 익스포터 · 수집기

트레이스가 속하는 상위 분류

관측성 · 분산 트레이싱 · 모니터링 · APM

트레이스로 찾는 문제

지연 · 병목 · 연쇄 장애 · 타임아웃 · N+1 문제

트레이스를 가리키는 다른 이름과 헷갈리는 이웃

분산 추적 · 스택 트레이스 · 호출 스택 · strace · ftrace · 실행 추적 · 감사 로그

트레이스가 거치는 시스템 구조

마이크로서비스 · 분산 시스템 · API 게이트웨이 · 메시지 큐 · 서비스 메시 · RPC