OpenTelemetry + Grafana Tempo でマイクロサービスのトレーシングを見てみた

developmentopentelemetrygrafanatracing

はじめに

エラーが発生したとき、どのサービスが原因かを特定するためにログを1つひとつ追うのが地味につらい。しかもサービスをまたいだ処理のどこで遅延しているのかがまったく見えない。

このようなところに対するアプローチであるトレーシングに元々興味があり、実際に可視化して見ました。

今回は OpenTelemetry（OTel） と Grafana Tempo を使った分散トレーシングを導入してみました。

分散トレーシングとは

マイクロサービスでは、1つのリクエストが複数のサービスをまたいで処理されます。

ユーザー → A → B → C
                └→ D

このとき「どのサービスが何ミリ秒かかったか」「どの順序で呼ばれたか」を1本の線として追えるのが分散トレーシングです。

トレースとスパンという単位で管理されます。

  • トレース: リクエスト1つの全体の旅路
  • スパン: 1区間の処理単位（サービスの受信→応答など）

サービス間では traceparent という HTTP ヘッダーでコンテキストを引き継ぎます。上流サービスがこのヘッダーを付けて下流を呼ぶことで、「このスパンは誰の子か」という親子関係が記録され、全体のツリー構造が組み立てられます。

今回の構成

[Go サービス（OTel SDK）]
        ↓ OTLP/HTTP (4318)
[OpenTelemetry Collector]
        ↓ OTLP/gRPC (4317)
[Grafana Tempo]
        ↑ HTTP クエリ (3200)
[Grafana]

Go サービスは OTel SDK でトレースを生成し、OTel Collector に投げます。Collector がバッファリングして Tempo に転送し、Grafana から可視化する流れです。

なぜ Collector を挟むのか

アプリから Tempo に直接送ることもできますが、Collector を挟むことでいくつかメリットがあります。

  • バッチ処理でまとめて転送できるため、Tempo への接続数が減る
  • アプリ側のコードを変えずにバックエンドを差し替えられる
  • メモリ上限の設定など、アプリ側では面倒な制御を Collector に任せられる

Go サービスへの計装

OTel の Go SDK を使った計装のコアは、TracerProvider の初期化と HTTP ハンドラへのラップです。

TracerProvider の初期化

func initTracing(serviceName string) func() {
    if tracingDisabled() {
        return func() {}
    }

    ctx := context.Background()
    exporter, err := otlptracehttp.New(ctx)
    if err != nil {
        log.Printf("OpenTelemetry tracing disabled: %v", err)
        return func() {}
    }

    res, _ := resource.Merge(resource.Default(), resource.NewWithAttributes(
        "",
        attribute.String("service.name", getEnv("OTEL_SERVICE_NAME", serviceName)),
    ))

    provider := sdktrace.NewTracerProvider(
        sdktrace.WithResource(res),
        sdktrace.WithSampler(traceSampler()),
        sdktrace.WithBatcher(exporter),
    )
    otel.SetTracerProvider(provider)
    otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(
        propagation.TraceContext{},
        propagation.Baggage{},
    ))

    return func() {
        ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
        defer cancel()
        provider.Shutdown(ctx)
    }
}

otlptracehttp.New(ctx) は環境変数 OTEL_EXPORTER_OTLP_ENDPOINT を自動で読むので、エンドポイントをコードに書く必要はありません。tracingDisabled() でエンドポイントが未設定のときはスキップするようにしておくと、ローカル開発でも余計なエラーが出ません。

main.go への組み込みは2行

func main() {
    defer initTracing("your-service")()

    // ...

    log.Fatal(http.ListenAndServe(":"+port, tracedHTTPHandler("your-service", mux)))
}

tracedHTTPHandler は otelhttp.NewHandler のラッパーで、受信リクエストのサーバースパンを自動生成します。アウトバウンドの HTTP クライアントも otelhttp.NewTransport でラップしており、サービス間の traceparent 伝播が自動で行われます。

細かな工夫

スパン名の正規化

何も考えずに記録すると GET /tasks/1, GET /tasks/2, GET /tasks/99 のようにスパン名が際限なく増えます。Grafana のドロップダウンが使い物にならなくなるので、パスの数値部分を :id に正規化します。

func normalizedPath(path string) string {
    parts := strings.Split(strings.Trim(path, "/"), "/")
    for i, part := range parts {
        if _, err := strconv.ParseUint(part, 10, 64); err == nil {
            parts[i] = ":id"
        }
    }
    return "/" + strings.Join(parts, "/")
}

これで GET /tasks/:id としてまとまり、一覧で探しやすくなります。

ヘルスチェックはフィルタを適応

/health や /metrics へのポーリングをそのまま記録するとトレースがノイズだらけになります。

func traceRequestFilter(r *http.Request) bool {
    return r.URL.Path != "/health" && r.URL.Path != "/metrics"
}

サンプリングの設定

環境変数でサンプリング戦略を切り替えられるようにしました。

func traceSampler() sdktrace.Sampler {
    ratio := 1.0
    if raw := os.Getenv("OTEL_TRACES_SAMPLER_ARG"); raw != "" {
        if parsed, err := strconv.ParseFloat(raw, 64); err == nil {
            ratio = parsed
        }
    }

    switch strings.ToLower(os.Getenv("OTEL_TRACES_SAMPLER")) {
    case "always_off":
        return sdktrace.NeverSample()
    case "traceidratio":
        return sdktrace.TraceIDRatioBased(ratio)
    default:
        return sdktrace.ParentBased(sdktrace.TraceIDRatioBased(ratio))
    }
}

parentbased_traceidratio（デフォルト）は「上流がサンプリングしたリクエストだけ記録する」という挙動になります。上流・下流でサンプリング判断が一致するので、マイクロサービスとの相性が良いです。

OTel Collector の設定

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318

processors:
  memory_limiter:
    check_interval: 1s
    limit_mib: 128
  batch:
    timeout: 5s
    send_batch_size: 1024

exporters:
  otlp/tempo:
    endpoint: tempo.<namespace>.svc.cluster.local:4317
    tls:
      insecure: true

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [memory_limiter, batch]
      exporters: [otlp/tempo]

batch プロセッサが5秒または1024件単位でまとめて Tempo に転送します。memory_limiter はメモリ使用量が上限に近づいたときにデータを落として OOM を防ぎます。

Tempo の設定

distributor:
  receivers:
    otlp:
      protocols:
        grpc:
          endpoint: 0.0.0.0:4317

ingester:
  trace_idle_period: 10s
  max_block_duration: 5m

compactor:
  compaction:
    block_retention: 24h

storage:
  trace:
    backend: local
    wal:
      path: /var/tempo/wal
    local:
      path: /var/tempo/blocks

学習環境なのでストレージはローカルにしていますが、本番では backend: gcs や backend: s3 を指定します。block_retention: 24h でデータの保持期間を24時間に設定。

Grafana のデータソースは ConfigMap のラベル（grafana_datasource: "1"）を使って sidecar に自動登録させています。

Grafana で実際に見えたもの

リクエストの呼び出しツリー

導入後に Grafana の Explore から Tempo データソースでトレースを開くと、こんな形で見えます。

Tempo Trace

「このリクエスト、こんなにサービスをまたいでたのか」という発見がありました。ログをひとつひとつ追っていたときには見えていなかった全体像が、一画面で把握できます。

どこで時間がかかっているか

全体で 1.59s かかっていたリクエストを見たとき、ウォーターフォール図から「task-orchestrator-service の呼び出し待ちが 300ms 以上占めている」とすぐわかりました。ログだけだとこの把握は難しいなと感じました。

サービスマップ

サービス間の依存グラフが自動で生成されます。構成図を手で書かなくても「このサービスは何に依存しているか」が見えます。

導入してわかったこと

ログとトレースは役割が違う

トレースで「どのサービスのどのスパンで落ちたか」を特定して、そのサービスのログを深掘りする、という流れが自然にできます。トレースは「どこか」を特定するのが得意で、ログは「なぜか」を読み解くのが得意。両方あって初めて完結します。

計装コストは思ったより低かった

otelhttp を使えば HTTP の送受信は自動でスパンが作られます。サービスごとに書くのは初期化の2行とフィルタ・正規化の設定程度で、既存の実装にほぼ手を入れる必要がありませんでした。

まとめ

OTel + Tempo を入れてみて、マイクロサービスの「見えなかった部分」がかなり見えるようになりました。ログだけの状態とは、障害対応のしやすさが体感でわかるくらい変わります。

次は Loki のログと Tempo のトレース ID をリンクさせて、ログ → トレース、トレース → ログを行き来できるようにしてみたいです。