OpenTelemetry 추적 정리: 스팬을 어느 단위로 나눌까

OpenTelemetry 정리에서 계측 코드가 API에만 의존하면 백엔드를 갈아 끼울 수 있다는 이야기를 했는데요. 그때 만든 스팬은 greet 하나뿐이었습니다. 이름을 붙이고 끝낸 게 전부였죠.

실제로는 여기서부터가 어렵습니다. 요청 하나를 처리하는 동안 스팬을 하나만 만들면 “이 요청이 200밀리초 걸렸다”까지만 알 수 있고, 반대로 함수마다 만들면 화면이 스팬으로 뒤덮여 오히려 안 보이거든요. 😅 이 글에서는 스팬에 무엇을 담는지, 어느 단위로 나누는 게 쓸모 있는지, 그리고 만든 추적을 Jaeger에서 어떻게 확인하는지를 정리해 보겠습니다.

스팬은 시간 구간에 붙인 이름표

추적(trace)은 요청 하나가 시스템을 지나간 전체 기록이고, 스팬(span)은 그 안의 한 구간입니다. 구간이라는 말이 핵심이에요. 스팬에는 시작 시각과 끝 시각이 있고, 그 사이에 무슨 일이 있었는지를 설명하는 정보가 붙습니다.

붙일 수 있는 정보는 세 종류입니다. 우선 속성(attribute)은 구간 전체에 해당하는 키와 값이에요. 어떤 SQL을 실행했는지, 주문 번호가 몇 번인지 같은 것이죠. 다음으로 이벤트(event)는 구간 안의 특정 순간에 일어난 일입니다. 속성과 달리 시각이 함께 기록돼서 “3밀리초 지점에서 캐시가 빗나갔다” 같은 걸 남길 수 있어요. 마지막으로 상태(status)는 이 구간이 성공했는지 실패했는지를 나타냅니다.

스팬끼리는 부모 자식으로도 엮입니다. 요청을 받은 구간이 부모가 되고, 그 안에서 데이터베이스를 조회한 구간이 자식이 되는 식이죠. 이 관계가 쌓이면 추적은 트리가 되고, 각 스팬의 시작 시각과 길이를 가로축에 놓으면 우리가 아는 폭포 그래프가 됩니다.

스팬 두 개로 시작하기

Bun으로 주문 조회 API를 만들어 보겠습니다. 앞 글에서 쓴 instrument.ts는 그대로 두고 서버 코드만 새로 씁니다.

orders.ts
import "./instrument";
import { SpanStatusCode, trace } from "@opentelemetry/api";

const tracer = trace.getTracer("orders");

async function findOrder(id: string) {
  return tracer.startActiveSpan("db.query", async (span) => {
    span.setAttribute("db.system", "postgresql");
    span.setAttribute("db.statement", "SELECT * FROM orders WHERE id = $1");
    await Bun.sleep(12); // 조회에 걸리는 시간을 흉내 냅니다
    span.end();
    return id === "404" ? null : { id, total: 32000 };
  });
}

Bun.serve({
  port: 3000,
  async fetch(request) {
    const id = new URL(request.url).pathname.split("/").at(-1) ?? "";
    return tracer.startActiveSpan("GET /orders/:id", async (span) => {
      span.setAttribute("http.request.method", "GET");
      span.setAttribute("order.id", id);
      const order = await findOrder(id);
      if (!order) {
        span.addEvent("order.not_found", { "order.id": id });
        span.setStatus({ code: SpanStatusCode.ERROR, message: "주문을 찾지 못함" });
        span.end();
        return new Response("Not Found", { status: 404 });
      }
      span.end();
      return Response.json(order);
    });
  },
});

눈여겨볼 곳은 findOrder 안에서 부모를 지정하지 않았다는 점입니다. 그런데도 db.query는 바깥 스팬의 자식이 돼요.

bun run orders.ts
curl http://localhost:3000/orders/42

콘솔에 찍힌 두 스팬에서 관계가 드러납니다. 자식이 먼저 끝나므로 먼저 출력됩니다.

결과
{
  ...
  traceId: "c25a76c3f9712c05d3fb4684dadac2ee",
  parentSpanContext: {
    traceId: "c25a76c3f9712c05d3fb4684dadac2ee",
    spanId: "c25fbb5f3428071a",
    ...
  },
  name: "db.query",
  id: "47b57141e23bbbf8",
  duration: 15234.625,
  attributes: {
    "db.system": "postgresql",
    "db.statement": "SELECT * FROM orders WHERE id = $1",
  },
  ...
}
{
  ...
  traceId: "c25a76c3f9712c05d3fb4684dadac2ee",
  parentSpanContext: undefined,
  name: "GET /orders/:id",
  id: "c25fbb5f3428071a",
  duration: 19175.292,
  attributes: {
    "http.request.method": "GET",
    "order.id": "42",
  },
  ...
}

두 스팬의 traceId가 같고, 자식의 parentSpanContext.spanId가 부모의 id와 일치합니다. 부모는 parentSpanContext가 비어 있으니 추적의 뿌리고요. 이 세 값이 트리를 만드는 전부입니다.

flowchart TB
    accTitle: traceId와 spanId로 스팬이 트리를 이루는 방식
    accDescr: 두 스팬이 같은 traceId를 공유한다. 부모 스팬은 parentSpanContext가 비어 있어 추적의 뿌리가 되고, 자식 스팬은 parentSpanContext의 spanId로 부모의 id를 가리킨다.

    subgraph trace ["같은 traceId: c25a76c3…"]
        direction TB
        parent["GET /orders/:id<br/>id: c25fbb5f…<br/>부모 없음 (뿌리)"]
        child["db.query<br/>id: 47b57141…<br/>부모: c25fbb5f…"]
        parent --> child
    end

    style trace fill:none,stroke:#888,stroke-width:1px

부모를 알려준 적이 없는데

findOrder는 매개변수로 부모 스팬을 받지 않았습니다. 그런데도 관계가 잡힌 건 startActiveSpan이 스팬을 만들면서 그 스팬을 현재 컨텍스트(context)에 올려놓기 때문이에요. 콜백 안에서 새로 만드는 스팬은 그 컨텍스트를 보고 자기 부모를 정합니다. 콜백이 끝나면 컨텍스트는 원래대로 돌아가고요.

그래서 스팬을 만드는 함수끼리 아무것도 주고받지 않아도 트리가 완성됩니다. 부모를 인자로 넘기며 함수 서명을 오염시키지 않아도 되는 거죠.

컨텍스트를 올리지 않고 스팬만 만들고 싶다면 startSpan을 씁니다. 다만 이 경우 그 스팬 안에서 만든 스팬은 부모를 못 찾으니, 추적을 끊고 싶은 게 아니라면 startActiveSpan이 기본입니다.

주의할 점이 하나 있어요. 컨텍스트는 콜백이 살아 있는 동안만 유지되므로, 콜백 밖으로 나간 뒤에 만든 스팬은 부모를 잃습니다. 비동기 작업을 await 없이 던져 놓고 콜백을 끝내 버리면 그 안의 스팬이 뿌리로 떨어져 추적이 둘로 쪼개져요.

실패를 남기는 자리

주문을 못 찾았을 때 두 가지를 기록했습니다. 사건 자체는 이벤트로, 이 구간의 결과는 상태로 남겼죠. 404 요청의 부모 스팬은 이렇게 나옵니다.

결과
{
  ...
  name: "GET /orders/:id",
  attributes: {
    "http.request.method": "GET",
    "order.id": "404",
  },
  status: {
    code: 2,
    message: "주문을 찾지 못함",
  },
  events: [
    {
      name: "order.not_found",
      attributes: {
        "order.id": "404",
      },
      time: [ 1790541100, 277287917 ],
      droppedAttributesCount: 0,
    }
  ],
  ...
}

code: 2가 오류입니다. 0은 아직 정하지 않았다는 뜻이고 1이 명시적인 성공인데, 성공을 굳이 적을 일은 드물어서 대부분 0이나 2만 보게 돼요. 이벤트에는 time이 따로 붙어 있어서 구간 안의 어느 시점이었는지 알 수 있습니다.

예외를 잡았다면 recordException으로 스택 트레이스까지 이벤트로 남길 수 있습니다. 다만 예외를 기록해도 상태는 자동으로 바뀌지 않으니 setStatus를 함께 불러 줘야 합니다.

한 가지 조심할 건 오류 상태를 어디에 찍느냐입니다. 자식 스팬이 실패했다고 부모가 자동으로 실패가 되지는 않아요. 재시도해서 결국 성공했다면 부모는 정상이어야 맞고, 그대로 실패로 끝났다면 부모에도 상태를 찍어 줘야 폭포에서 빨갛게 보입니다.

Jaeger로 보기

콘솔 출력은 값을 확인하기엔 좋지만 트리를 보기엔 불편합니다. 추적을 화면으로 보려면 받아 줄 백엔드가 필요한데, Jaeger가 OTLP를 그대로 받으니 컨테이너 하나면 됩니다. Docker로 띄워 보겠습니다.

docker run -d --name jaeger \
  -p 16686:16686 -p 4318:4318 \
  jaegertracing/all-in-one:1.62.0

4318이 OTLP HTTP를 받는 포트고 16686이 웹 화면입니다. 이제 익스포터(exporter)를 콘솔에서 OTLP로 바꿉니다. 스팬을 하나씩 바로 보내는 대신 모아서 보내도록 BatchSpanProcessor도 함께 씁니다.

instrument.ts
import { BatchSpanProcessor, NodeTracerProvider } from "@opentelemetry/sdk-trace-node";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
import { resourceFromAttributes } from "@opentelemetry/resources";
import { ATTR_SERVICE_NAME } from "@opentelemetry/semantic-conventions";

const provider = new NodeTracerProvider({
  resource: resourceFromAttributes({ [ATTR_SERVICE_NAME]: "orders" }),
  spanProcessors: [new BatchSpanProcessor(new OTLPTraceExporter())],
});

provider.register();

보낼 주소는 코드가 아니라 환경 변수로 넘깁니다.

OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4318 bun run orders.ts
curl http://localhost:3000/orders/42

http://localhost:16686을 열어 서비스로 orders를 고르면 추적이 보입니다.

Jaeger 추적 화면에서 GET /orders/:id 스팬 아래에 db.query 스팬이 중첩된 폭포 그래프

GET /orders/:id 아래에 db.query가 들여쓰기돼 있고, 두 막대의 길이가 거의 같습니다. 13밀리초 중 대부분이 데이터베이스에서 쓰였다는 뜻이죠. 스팬을 두 개로 나눈 덕에 알 수 있는 사실입니다. 하나만 만들었다면 “13밀리초 걸렸다”에서 멈췄을 거예요.

그래서 어느 단위로 나눌까

기준은 하나입니다. 느려졌을 때 범인을 좁혀 주는 경계에만 스팬을 두는 거예요.

경계 밖으로 나가는 호출이 대표적입니다. 데이터베이스 질의, 외부 API 호출, 캐시 조회, 메시지 발행처럼 내 프로세스 밖에서 시간이 흐르는 지점이죠. 여기가 느려지는 원인의 대부분이고, 코드를 읽어서는 알 수 없는 시간이라 기록할 가치가 큽니다.

반대로 순수 계산 함수는 스팬을 두지 않습니다. 정렬이나 포매팅 같은 건 느려져도 스팬으로 알아내기보다 프로파일러로 잡는 게 맞고, 스팬을 만드는 비용 자체가 그 함수의 실행 시간보다 클 수도 있어요.

애매하면 이렇게 생각해 보면 됩니다. 이 스팬이 느리다고 나왔을 때 무엇을 하겠는가? 답이 떠오르지 않으면 그 스팬은 없어도 됩니다. db.query가 느리면 인덱스를 보겠지만, formatCurrency가 느리다고 나오면 할 일이 없죠.

스팬 이름도 같은 원칙을 따릅니다. GET /orders/:id처럼 경로 패턴을 쓰고 GET /orders/42처럼 실제 값을 넣지 않아요. 값을 이름에 넣으면 주문 번호마다 다른 이름이 생겨서 “이 엔드포인트의 p99”를 구할 수 없게 됩니다. 구체적인 값은 이름이 아니라 속성에 넣습니다. order.id를 속성으로 둔 것도 그래서고요.

마치며

스팬은 시간 구간에 이름을 붙이고 속성과 이벤트와 상태를 얹은 것이고, startActiveSpan이 컨텍스트로 부모를 이어 주기 때문에 함수끼리 무엇을 주고받지 않아도 트리가 만들어집니다. 나누는 기준은 “느렸을 때 뭘 할 수 있는가”이고, 경계를 넘는 호출이 거의 항상 정답이에요.

그런데 지금까지의 트리는 프로세스 하나 안에서만 이어집니다. 주문 서비스가 결제 서비스를 HTTP로 부르면 저쪽에서는 새 추적이 시작되죠. 다음 글에서는 이 경계를 넘어 추적을 이어 붙이는 방법을 다루겠습니다.

스팬에 담을 수 있는 정보의 전체 목록은 OpenTelemetry 공식 문서의 Traces에 정리돼 있습니다.

This work is licensed under CC BY 4.0CCBY

개발자를 위한 뉴스레터

달레가 정리한 AI 개발 트렌드와 직접 만든 콘텐츠를 전해드립니다.

관련 포스트

OpenTelemetry 정리: 계측 코드를 벤더에서 떼어 내기

추적(trace)을 처음 붙일 때 Jaeger를 골랐다고 해 볼게요. Jaeger가 주는 라이브러리를 받아 서비스 곳곳에 스팬을 만드는 코드를 심었고, 잘 돌아갑니다. 그런데 반년 뒤 팀이 다른 백엔드로 옮기기로 합니다. 무엇을 다시 해야 할까요? 심어 둔 계측 코드 전부입니다. 😅 몇 년 전까지는 이게 기본값이었습니다. 관측 도구를 고르는 일이 곧 그 도구를 코드에 새겨 넣는 일이었고, 한번 새기면 되돌리기 어려웠죠. 지금은 다릅니다. 계측 코드는 그대로 두고 환경 변수 하나만 바꾸면 텔레메트리(telemetry)가 다른 곳으로

OpenTelemetry 컨텍스트 전파 정리: traceparent 헤더로 추적 잇기

OpenTelemetry 추적 정리에서 만든 트리는 깔끔했지만 한계가 있었습니다. 프로세스 하나 안에서만 이어진다는 것이요. 주문 서비스가 결제 서비스를 HTTP로 부르면 어떻게 될까요? 결제 서비스 입장에서는 그냥 요청 하나가 들어온 겁니다. 자기가 누구의 자식인지 알 도리가 없으니 새 추적을 시작하죠. 결과적으로 사용자 눈에는 한 번의 주문인데 추적은 두 개로 쪼개집니다. 😅 서비스가 늘어날수록 이 조각은 많아지고, 정작 알고 싶은 "이 주문 요청이 어디서 시간을 썼나"는 답할 수 없게 돼요. 이 글에서는 경계를 넘어 추적을

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

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

OpenTelemetry 시맨틱 컨벤션 정리: 속성 이름을 정해 두는 이유

지금까지 이 시리즈에서 속성 이름을 꽤 여러 개 지었습니다. order.id, db.system, http.request.method 같은 것들이요. 별생각 없이 지은 이름도 있고 어디서 본 듯한 이름도 있었죠. 그런데 이름은 정말 아무래도 괜찮을까요? 🤔 스팬 하나만 놓고 보면 그렇습니다. http.method라고 적든 request_method라고 적든 내가 읽으면 되니까요. 문제는 그 스팬이 나 혼자 만든 게 아닐 때 시작됩니다. 이름이 갈리면 잃는 것 상황을 그려 보겠습니다. 주문 서비스는 직접 계측해서 http.metho

OpenTelemetry 로그 정리: 로그 브리지로 추적과 잇기

남은 신호는 로그 하나입니다. 그런데 지표 정리까지 왔다면 좀 이상하게 느껴질 거예요. 로그는 이미 다들 쓰고 있잖아요. 😅 파이썬이면 logging, Node라면 Pino나 Winston을 붙여 두고 잘 돌아가는데 여기에 또 새로운 걸 얹어야 하나 싶죠. OpenTelemetry도 같은 생각을 했습니다. 그래서 로그만 다른 길을 갔어요. 이 글에서는 그 선택이 무엇이었는지, 그리고 기존 로그를 추적과 이어 붙이는 방법을 다루겠습니다. 로그만 접근이 달랐던 이유 추적과 지표는 OpenTelemetry가 새로 표준을 만들었습니다.

OpenTelemetry 지표 정리: 계측기 고르기부터 Prometheus까지

수집기 정리까지 오면서 흘려보낸 건 추적뿐이었습니다. 추적은 요청 하나를 아주 자세히 보여 주지만 "지난 한 시간 동안 오류율이 몇 퍼센트였나"에는 답하지 못해요. 요청 하나하나를 다 뒤져 세야 하니까요. 지표, 로그, 추적 정리에서 정리했듯 그건 지표(metric)의 몫입니다. 이 글에서는 지표를 만드는 계측기(instrument) 종류를 고르는 법, 속성을 붙일 때 조심할 것, 그리고 Prometheus까지 연결하는 과정을 다루겠습니다. 계측기는 네 가지 지표를 만들려면 먼저 미터(meter)를 얻고 거기서 계측기를 만듭니다.